logging: impl custom log options per route

Author: artur-barsegyan

CHANGELOG.md

@@ -4,6 +4,9 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
+## [Unreleased]
+- Added options `log_requests` and `log_errors` to `route()` method for customizing request log output and error log output respectively. 
+
 ## [1.0.3] - 2018-06-29
 ### Added
 - Fixed eof detection

README.md

@@ -89,9 +89,9 @@ To stop the server, use `httpd:stop()`.
 httpd = require('http.server').new(host, port[, { options } ])
 ```
 
-`host` and `port` must contain: 
+`host` and `port` must contain:
 * For tcp socket: the host and port to bind to.
-* For unix socket: `unix/` and path to socket (for example `/tmp/http-server.sock`) to bind to. 
+* For unix socket: `unix/` and path to socket (for example `/tmp/http-server.sock`) to bind to.
 
 `options` may contain:
 
@@ -110,8 +110,12 @@ httpd = require('http.server').new(host, port[, { options } ])
   type `text/html`, `text/plain` and `application/json`.
 * `display_errors` - return application errors and backtraces to the client
   (like PHP).
-* `log_errors` - log application errors using `log.error()`.
-* `log_requests` - log incoming requests.
+* `log_requests` - log incoming requests. This parameter can receive:
+    - function value, supporting C-style formatting: log_requests(fmt, ...), where fmt is a format string and ... is Lua Varargs, holding arguments to be replaced in fmt.
+    - boolean value, where `true` choose default `log.info` and `false` disable request logs at all.
+
+  By default uses `log.info` function for requests logging.
+* `log_errors` - same as the `log_requests` option but is used for error messages logging. By default uses `log.error()` function.
 
 ## Using routes
 
@@ -158,6 +162,8 @@ The first argument for `route()` is a Lua table with one or more keys:
 * `path` - route path, as described earlier.
 * `name` - route name.
 * `method` - method on the route like `POST`, `GET`, `PUT`, `DELETE`
+* `log_requests` - option that overrides the server parameter of the same name but only for current route.
+* `log_errors` - option that overrides the server parameter of the same name but only for current route.
 
 The second argument is the route handler to be used to produce
 a response to the request.

http/server.lua

@@ -589,6 +589,50 @@ response_mt = {
     }
 }
 
+local function is_function(obj)
+    return type(obj) == 'function'
+end
+
+local function get_request_logger(server_opts, route_opts)
+    if route_opts and route_opts.endpoint.log_requests ~= nil then
+        if is_function(route_opts.endpoint.log_requests) then
+            return route_opts.endpoint.log_requests
+        elseif route_opts.endpoint.log_requests == false then
+            return log.debug
+        end
+    end
+
+    if server_opts.log_requests then
+        if is_function(server_opts.log_requests) then
+            return server_opts.log_requests
+        end
+
+        return log.info
+    end
+
+    return log.debug
+end
+
+local function get_error_logger(server_opts, route_opts)
+    if route_opts and route_opts.endpoint.log_errors ~= nil then
+        if is_function(route_opts.endpoint.log_errors) then
+            return route_opts.endpoint.log_errors
+        elseif route_opts.endpoint.log_errors == false then
+            return log.debug
+        end
+    end
+
+    if server_opts.log_errors then
+        if is_function(server_opts.log_errors) then
+            return server_opts.log_errors
+        end
+
+        return log.error
+    end
+
+    return log.debug
+end
+
 local function handler(self, request)
     if self.hooks.before_dispatch ~= nil then
         self.hooks.before_dispatch(self, request)
@@ -601,7 +645,6 @@ local function handler(self, request)
         format = pformat
     end
 
-
     local r = self:match(request.method, request.path)
     if r == nil then
         return static_file(self, request, format)
@@ -685,9 +728,10 @@ local function process_client(self, s, peer)
             s:write('HTTP/1.0 100 Continue\r\n\r\n')
         end
 
-        local logreq = self.options.log_requests and log.info or log.debug
+        local route = self:match(p.method, p.path)
+        local logreq = get_request_logger(self.options, route)
         logreq("%s %s%s", p.method, p.path,
-            p.query ~= "" and "?"..p.query or "")
+               p.query ~= "" and "?"..p.query or "")
 
         local res, reason = pcall(self.options.handler, self, p)
         p:read() -- skip remaining bytes of request body
@@ -697,9 +741,9 @@ local function process_client(self, s, peer)
             status = 500
             hdrs = {}
             local trace = debug.traceback()
-            local logerror = self.options.log_errors and log.error or log.debug
+            local logerror = get_error_logger(self.options, route)
             logerror('unhandled error: %s\n%s\nrequest:\n%s',
-                tostring(reason), trace, tostring(p))
+                     tostring(reason), trace, tostring(p))
             if self.options.display_errors then
             body =
                   "Unhandled error: " .. tostring(reason) .. "\n"
@@ -1099,6 +1143,18 @@ local function add_route(self, opts, sub)
     opts.sub = sub
     opts.url_for = url_for_route
 
+    if opts.log_requests ~= nil then
+        if type(opts.log_requests) ~= 'function' and type(opts.log_requests) ~= 'boolean' then
+            error("'log_requests' option should be a function or a boolean")
+        end
+    end
+
+    if opts.log_errors ~= nil then
+        if type(opts.log_errors) ~= 'function' and type(opts.log_errors) ~= 'boolean' then
+            error("'log_errors' option should be a function or a boolean")
+        end
+    end
+
     if opts.name ~= nil then
         if opts.name == 'current' then
             error("Route can not have name 'current'")

test.sh

@@ -10,7 +10,8 @@ local yaml = require 'yaml'
 local urilib = require('uri')
 
 local test = tap.test("http")
-test:plan(7)
+test:plan(8)
+
 test:test("split_uri", function(test)
     test:plan(65)
     local function check(uri, rhs)
@@ -388,4 +389,136 @@ test:test("server requests", function(test)
     httpd:stop()
 end)
 
+local log_queue = {}
+
+local custom_logger = {
+    debug = function() end,
+    verbose = function(...)
+        table.insert(log_queue, { log_lvl = 'verbose', })
+    end,
+    info = function(...)
+        table.insert(log_queue, { log_lvl = 'info', msg = string.format(...)})
+    end,
+    warn = function(...)
+        table.insert(log_queue, { log_lvl = 'warn', msg = string.format(...)})
+    end,
+    error = function(...)
+        table.insert(log_queue, { log_lvl = 'error', msg = string.format(...)})
+    end
+}
+
+local function find_msg_in_log_queue(msg, strict)
+    for _, log in ipairs(log_queue) do
+        if not strict then
+            if log.msg:match(msg) then
+                return log
+            end
+        else
+            if log.msg == msg then
+                return log
+            end
+        end
+    end
+end
+
+local function clear_log_queue()
+    log_queue = {}
+end
+
+test:test("Custom log functions for route", function(test)
+    test:plan(5)
+
+    test:test("Setting log option for server instance", function(test)
+        test:plan(2)
+
+        local httpd = http_server.new("127.0.0.1", 12345, { log_requests = custom_logger.info, log_errors = custom_logger.error })
+        httpd:route({ path='/' }, function(_) end)
+        httpd:route({ path='/error' }, function(_) error('Some error...') end)
+        httpd:start()
+
+        http_client.get("127.0.0.1:12345")
+        test:is_deeply(find_msg_in_log_queue("GET /"), { log_lvl = 'info', msg = 'GET /' }, "Route should logging requests in custom logger if it's presents")
+        clear_log_queue()
+
+        http_client.get("127.0.0.1:12345/error")
+        test:ok(find_msg_in_log_queue("Some error...", false), "Route should logging error in custom logger if it's presents")
+        clear_log_queue()
+
+        httpd:stop()
+    end)
+
+    test:test("Setting log options for route", function(test)
+        test:plan(8)
+        local httpd = http_server.new("127.0.0.1", 12345, { log_requests = true, log_errors = false })
+        local dummy_logger = function() end
+
+        local ok, err = pcall(httpd.route, httpd, { path = '/', log_requests = 3 })
+        test:is(ok, false, "Route logger can't be a log_level digit")
+        test:like(err, "'log_requests' option should be a function", "route() should return error message in case of incorrect logger option")
+
+        ok, err = pcall(httpd.route, httpd, { path = '/', log_requests = { info = dummy_logger } })
+        test:is(ok, false, "Route logger can't be a table")
+        test:like(err, "'log_requests' option should be a function", "route() should return error message in case of incorrect logger option")
+
+        local ok, err = pcall(httpd.route, httpd, { path = '/', log_errors = 3 })
+        test:is(ok, false, "Route error logger can't be a log_level digit")
+        test:like(err, "'log_errors' option should be a function", "route() should return error message in case of incorrect logger option")
+
+        ok, err = pcall(httpd.route, httpd, { path = '/', log_errors = { error = dummy_logger } })
+        test:is(ok, false, "Route error logger can't be a table")
+        test:like(err, "'log_errors' option should be a function", "route() should return error message in case of incorrect log_errors option")
+    end)
+
+    test:test("Log output with custom loggers on route", function(test)
+        test:plan(3)
+        local httpd = http_server.new("127.0.0.1", 12345, { log_requests = true, log_errors = true })
+        httpd:start()
+
+        httpd:route({ path = '/', log_requests = custom_logger.info, log_errors = custom_logger.error }, function(_) end)
+        http_client.get("127.0.0.1:12345")
+        test:is_deeply(find_msg_in_log_queue("GET /"), { log_lvl = 'info', msg = 'GET /' }, "Route should logging requests in custom logger if it's presents")
+        clear_log_queue()
+
+        httpd.routes = {}
+        httpd:route({ path = '/', log_requests = custom_logger.info, log_errors = custom_logger.error }, function(_)
+            error("User business logic exception...")
+        end)
+        http_client.get("127.0.0.1:12345")
+        test:is_deeply(find_msg_in_log_queue("GET /"), { log_lvl = 'info', msg = 'GET /' }, "Route should logging request and error in case of route exception")
+        test:ok(find_msg_in_log_queue("User business logic exception...", false),
+                "Route should logging error custom logger if it's presents in case of route exception")
+        clear_log_queue()
+
+        httpd:stop()
+    end)
+
+    test:test("Log route requests with turned off 'log_requests' option", function(test)
+        test:plan(1)
+        local httpd = http_server.new("127.0.0.1", 12345, { log_requests = false })
+        httpd:start()
+
+        httpd:route({ path = '/', log_requests = custom_logger.info }, function(_) end)
+        http_client.get("127.0.0.1:12345")
+        test:is_deeply(find_msg_in_log_queue("GET /"), { log_lvl = 'info', msg = 'GET /' }, "Route can override logging requests if the http server have turned off 'log_requests' option")
+        clear_log_queue()
+
+        httpd:stop()
+    end)
+
+    test:test("Log route requests with turned off 'log_errors' option", function(test)
+        test:plan(1)
+        local httpd = http_server.new("127.0.0.1", 12345, { log_errors = false })
+        httpd:start()
+
+        httpd:route({ path = '/', log_errors = custom_logger.error }, function(_)
+            error("User business logic exception...")
+        end)
+        http_client.get("127.0.0.1:12345")
+        test:ok(find_msg_in_log_queue("User business logic exception...", false), "Route can override logging requests if the http server have turned off 'log_errors' option")
+        clear_log_queue()
+
+        httpd:stop()
+    end)
+end)
+
 os.exit(test:check() == true and 0 or 1)