From 1d35478791e01de231060f78f092dde42ca73e06 Mon Sep 17 00:00:00 2001 From: Satbek Turganbayev Date: Thu, 30 Jan 2020 14:09:07 +0300 Subject: [PATCH] Return ability to use custom loggers and to set loggers for a specific route --- .travis.yml | 2 +- README.md | 11 +- http/router/init.lua | 13 ++ http/server/init.lua | 54 +++++- test/integration/logging_test.lua | 279 ++++++++++++++++++++++++++++++ 5 files changed, 354 insertions(+), 5 deletions(-) create mode 100644 test/integration/logging_test.lua diff --git a/.travis.yml b/.travis.yml index 47f0f87..23d0082 100644 --- a/.travis.yml +++ b/.travis.yml @@ -24,7 +24,7 @@ _test: &test - sudo apt-get install -y tarantool tarantool-dev - tarantoolctl rocks make - tarantoolctl rocks install luacheck 0.25.0 - - tarantoolctl rocks install luatest 0.4.0 + - tarantoolctl rocks install luatest 0.5.0 script: - .rocks/bin/luacheck . - .rocks/bin/luatest -v --shuffle all diff --git a/README.md b/README.md index 0e180f9..eb4c5b1 100644 --- a/README.md +++ b/README.md @@ -112,8 +112,13 @@ server = require('http.server').new(host, port[, { options } ]) needed). * `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. ## Creating a router @@ -163,6 +168,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. diff --git a/http/router/init.lua b/http/router/init.lua index e34ce81..497626c 100644 --- a/http/router/init.lua +++ b/http/router/init.lua @@ -260,6 +260,19 @@ local function add_route(self, opts, handler) else table.insert(self.routes, opts) end + + 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 + return self end diff --git a/http/server/init.lua b/http/server/init.lua index 768ebc6..1c15787 100644 --- a/http/server/init.lua +++ b/http/server/init.lua @@ -32,6 +32,54 @@ local function headers_ended(hdrs) or string.endswith(hdrs, "\r\n\r\n") end +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 + elseif route_opts.endpoint.log_requests == true then + return log.info + 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 + elseif route_opts.endpoint.log_errors == true then + return log.error + 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 + ---------- -- Server ---------- @@ -99,7 +147,9 @@ 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 matched_route = self.options.router:match(p.method, p.path) + + local logreq = get_request_logger(self.options, matched_route) logreq("%s %s%s", p.method, p.path, p.query ~= "" and "?"..p.query or "") @@ -117,7 +167,7 @@ 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, matched_route) -- TODO: copypaste logerror('unhandled error: %s\n%s\nrequest:\n%s', diff --git a/test/integration/logging_test.lua b/test/integration/logging_test.lua new file mode 100644 index 0000000..50095ad --- /dev/null +++ b/test/integration/logging_test.lua @@ -0,0 +1,279 @@ +local t = require('luatest') +local capture = require('luatest.capture'):new() +local json = require('json') +local http_server = require('http.server') +local http_router = require('http.router') +local http_client = require('http.client') +local g = t.group() + +local helper = require('test.helper') + +g.before_all(function() + g.default_log_level = box.cfg.log_level + box.cfg{ log_level = 7 } +end) + +g.after_all(function() + box.cfg{ log_level = g.default_log_level } +end) + +local log_queue = {} + +local custom_logger = { + debug = function() end, + info = function(...) + table.insert(log_queue, { log_lvl = 'info', 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) + for _, log in ipairs(log_queue) do + if log.msg:match(msg) then + return log + end + end +end + +local function clear_log_queue() + log_queue = {} +end + +g.before_each(function() + g.server = http_server.new(helper.base_host, helper.base_port) + g.router = http_router.new() + g.server:set_router(g.router) + g.server:start() +end) + +g.after_each(function() + clear_log_queue() + g.server:stop() +end) + +g.test_default_server_logger = function() + local test_cases = { + { + log_options = nil, + log_prefixes = { + log_requests = 'I>', + log_errors = 'E>' + } + }, + { + log_options = { + log_requests = true, + log_errors = true, + }, + log_prefixes = { + log_requests = 'I>', + log_errors = 'E>' + } + }, + { + log_options = { + log_requests = false, + log_errors = false, + }, + log_prefixes = { + log_requests = 'D>', + log_errors = 'D>' + } + } + } + + g.router:route({path = 'log', method = 'GET'}, function() error('test') end) + for _, test_case in pairs(test_cases) do + if test_case.log_options ~= nil then + g.server.options.log_requests = test_case.log_options.log_requests + g.server.options.log_errors = test_case.log_options.log_errors + end + + -- capture logs + capture:wrap(true, function() + http_client.get(helper.base_uri .. 'log') + end) + local logs = capture:flush().stderr + + t.assert_str_contains( + logs, test_case.log_prefixes.log_requests .. ' GET /log\n', false, json.encode(test_case) + ) + t.assert_str_contains( + logs, test_case.log_prefixes.log_errors .. ' unhandled error:(.-) test\n', + true, json.encode(test_case) + ) + end +end + +g.test_server_custom_logger_output = function() + g.server.options.log_requests = custom_logger.info + g.server.options.log_errors = custom_logger.error + g.router:route({ path='/' }, function() error('Some error...') end) + + http_client.get(helper.base_uri) + + t.assert_items_include( + log_queue, {{ log_lvl = 'info', msg = 'GET /' }}, + "Route should logging requests in custom logger if it's presents" + ) + + t.assert_is_not( + find_msg_in_log_queue("Some error..."), nil, + "Route should logging error in custom logger if it's presents" + ) +end + +g.test_route_log_options = function() + local dummy_logger = function() end + + local test_cases = { + { + args = { path = '/', log_requests = 3 }, + err = "'log_requests' option should be a function", + }, + { + args = { path = '/', log_requests = { info = dummy_logger } }, + err = "'log_requests' option should be a function or a boolean", + }, + { + args = { path = '/', log_errors = 3 }, + err = "'log_errors' option should be a function or a boolean" + }, + { + args = { path = '/', log_errors = { error = dummy_logger } }, + err = "'log_errors' option should be a function or a boolean" + } + } + + for _, test_case in pairs(test_cases) do + local ok, err = pcall(g.router.route, g.router, test_case.args) + t.assert_is(ok, false) + t.assert_str_contains( + err, + test_case.err + ) + end +end + +g.test_route_custom_logger_output = function() + local servers_options = { + { + log_requests = true, + log_errors = true + }, + { + log_requests = false, + log_errors = false + }, + } + g.router:route( + { path = '/', log_requests = custom_logger.info, log_errors = custom_logger.error }, + function() error("User business logic exception...") end + ) + + for _, opts in ipairs(servers_options) do + http_client.get(helper.base_uri) + g.server.options.log_requests = opts.log_requests + g.server.options.log_errors = opts.log_errors + t.assert_items_include(log_queue, {{ log_lvl = 'info', msg = 'GET /' }}, + "Route should logging requests in custom logger if it's presents" + ) + t.assert_is_not( + find_msg_in_log_queue("User business logic exception..."), nil, + "Route should logging error custom logger if it's presents in case of route exception" + ) + clear_log_queue() + end +end + +g.test_route_logger_override_default_logger = function() + local test_cases = { + { + servers_options = { + log_requests = true, + log_errors = true, + }, + route_options = { + log_requests = false, + log_errors = false, + }, + log_prefixes = { + log_requests = 'D>', + log_errors = 'D>' + } + }, + { + servers_options = { + log_requests = false, + log_errors = false, + }, + route_options = { + log_requests = true, + log_errors = true, + }, + log_prefixes = { + log_requests = 'I>', + log_errors = 'E>' + } + } + } + + for _, test_case in ipairs(test_cases) do + g.router.routes = {} + g.router:route( + { + path = '/', method = 'GET', + log_requests = test_case.route_options.log_requests, + log_errors = test_case.route_options.log_errors + }, function() error('test') end + ) + + g.server.options.log_requests = test_case.servers_options.log_requests + g.server.options.log_errors = test_case.servers_options.log_errors + + -- capture logs + capture:wrap(true, function() + http_client.get(helper.base_uri) + end) + local logs = capture:flush().stderr + + t.assert_str_contains(logs, test_case.log_prefixes.log_requests .. ' GET /\n', false, json.encode(test_case)) + t.assert_str_contains( + logs, test_case.log_prefixes.log_errors .. ' unhandled error:(.-) test\n', true, json.encode(test_case) + ) + end +end + +g.test_route_logger_override_custom_logger = function() + local server_logger = { + debug = function() end, + info = function(...) + table.insert(log_queue, { log_lvl = 'server-info', msg = string.format(...)}) + end, + error = function(...) + table.insert(log_queue, { log_lvl = 'server-error', msg = string.format(...)}) + end + } + g.server.options.log_requests = server_logger.info + g.server.options.log_errors = server_logger.error + + g.router:route( + { + path = '/', method = 'GET', + log_requests = custom_logger.info, + log_errors = custom_logger.error + }, function() error('test') end + ) + + http_client.get(helper.base_uri) + + t.assert_items_include(log_queue, {{ log_lvl = 'info', msg = 'GET /' }}, + "Route should logging requests in custom logger if it's presents" + ) + t.assert_is_not( + find_msg_in_log_queue("test"), nil, + "Route should logging error custom logger if it's presents in case of route exception" + ) +end