From d985997f1c57babdfbe6d63396e677d339ecd1eb Mon Sep 17 00:00:00 2001 From: Oleg Chaplashkin Date: Mon, 25 Dec 2023 19:56:01 +0400 Subject: [PATCH] Add more logs Everything is logged via new `luatest.log` module. Important and most popular modules improved by additional logs about internal states or logic. This should help in investigating problems. Closes #325 --- CHANGELOG.md | 1 + luatest/assertions.lua | 6 ++++++ luatest/helpers.lua | 5 ++--- luatest/hooks.lua | 5 +++++ luatest/process.lua | 4 ++-- luatest/replica_proxy.lua | 2 +- luatest/replica_set.lua | 8 +++++--- luatest/runner.lua | 7 +++++-- luatest/server.lua | 20 ++++++++++++++------ 9 files changed, 41 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3f9c1406..ae076e2b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Add memory leak detection during server process execution (gh-349). - Improve `luatest.log` function if a `nil` value is passed (gh-360). - Added `assert_error_covers`. +- Add more logs (gh-326). ## 1.0.1 diff --git a/luatest/assertions.lua b/luatest/assertions.lua index 9ee17910..edf768c9 100644 --- a/luatest/assertions.lua +++ b/luatest/assertions.lua @@ -8,6 +8,7 @@ local math = require('math') local comparator = require('luatest.comparator') local mismatch_formatter = require('luatest.mismatch_formatter') local pp = require('luatest.pp') +local log = require('luatest.log') local utils = require('luatest.utils') local prettystr = pp.tostring @@ -177,6 +178,7 @@ end -- @string[opt] message -- @bool[opt] deep_analysis print diff. function M.assert_equals(actual, expected, message, deep_analysis) + log.info('Assert %s equals to %s', actual, expected) if not comparator.equals(actual, expected) then failure(M.private.error_msg_equality(actual, expected, deep_analysis), message, 2) end @@ -283,6 +285,7 @@ end -- @param expected -- @string[opt] message function M.assert_not_equals(actual, expected, message) + log.info('Assert %s not equals to %s', actual, expected) if comparator.equals(actual, expected) then fail_fmt(2, message, 'Actual and expected values are equal: %s', prettystr(actual)) end @@ -384,6 +387,8 @@ M.private.str_match = str_match -- @bool[opt] is_pattern -- @string[opt] message function M.assert_str_contains(value, expected, is_pattern, message) + log.info('Assert string %s contains %s', value, expected) + M.assert_type(value, 'string', nil, 2) M.assert_type(expected, 'string', nil, 2) @@ -526,6 +531,7 @@ end -- @param ... arguments for function function M.assert_error_msg_contains(expected_partial, fn, ...) local no_error, error_msg = pcall(fn, ...) + log.info('Assert error message %s contains %s', error_msg, expected_partial) if no_error then local failure_message = string.format( 'Function successfully returned: %s\nExpected error containing: %s', diff --git a/luatest/helpers.lua b/luatest/helpers.lua index ea9bfc03..88b8a194 100644 --- a/luatest/helpers.lua +++ b/luatest/helpers.lua @@ -4,7 +4,7 @@ local clock = require('clock') local fiber = require('fiber') -local log = require('log') +local log = require('luatest.log') local helpers = {} @@ -69,8 +69,7 @@ function helpers.retrying(config, fn, ...) if (clock.time() - started_at) > timeout then return fn(...) end - log.debug('Retrying in ' .. delay .. ' sec. due to error:') - log.debug(result) + log.verbose('Retrying in %d sec due to error: %s', delay, result) fiber.sleep(delay) end end diff --git a/luatest/hooks.lua b/luatest/hooks.lua index 9e28a455..d10688e8 100644 --- a/luatest/hooks.lua +++ b/luatest/hooks.lua @@ -1,3 +1,4 @@ +local log = require('luatest.log') local utils = require('luatest.utils') local comparator = require('luatest.comparator') @@ -129,6 +130,7 @@ local function run_group_hooks(runner, group, hooks_type) end local function run_test_hooks(self, test, hooks_type, legacy_name) + log.verbose('Run hook %s', hooks_type) local group = test.group local hook -- Support for group.setup/teardown methods (legacy API) @@ -143,6 +145,7 @@ local function run_test_hooks(self, test, hooks_type, legacy_name) end local function run_named_test_hooks(self, test, hooks_type) + log.verbose('Run hook %s', hooks_type) local group = test.group local hook = group['run_' .. hooks_type] if hook then @@ -172,7 +175,9 @@ function export.patch_runner(Runner) run_named_test_hooks(self, test, 'before_test') if test:is('success') then + log.info('Start test %s', test.name) super(self, test, ...) + log.info('End test %s', test.name) end run_named_test_hooks(self, test, 'after_test') diff --git a/luatest/process.lua b/luatest/process.lua index 9d447b32..bb546188 100644 --- a/luatest/process.lua +++ b/luatest/process.lua @@ -3,8 +3,8 @@ local errno = require('errno') local fun = require('fun') local ffi = require('ffi') local fio = require('fio') -local log = require('log') +local log = require('luatest.log') local Class = require('luatest.class') local OutputBeautifier = require('luatest.output_beautifier') @@ -77,7 +77,7 @@ function Process.mt:initialize() self._pid_ull = ffi.cast('void*', 0ULL + self.pid) ffi.gc(self._pid_ull, function(x) local pid = tonumber(ffi.cast(ffi.typeof(0ULL), x)) - log.debug("Killing GC'ed process " .. pid) + log.debug("Killing GC'ed process %d", pid) Process.kill_pid(pid, nil, {quiet = true}) end) end diff --git a/luatest/replica_proxy.lua b/luatest/replica_proxy.lua index 4d19c21d..9ca22503 100644 --- a/luatest/replica_proxy.lua +++ b/luatest/replica_proxy.lua @@ -5,10 +5,10 @@ local checks = require('checks') local fiber = require('fiber') local fio = require('fio') -local log = require('log') local socket = require('socket') local uri = require('uri') +local log = require('luatest.log') local utils = require('luatest.utils') local Connection = require('luatest.replica_conn') diff --git a/luatest/replica_set.lua b/luatest/replica_set.lua index 555bc462..f5e19a5b 100644 --- a/luatest/replica_set.lua +++ b/luatest/replica_set.lua @@ -4,10 +4,10 @@ local checks = require('checks') local fio = require('fio') -local log = require('log') local helpers = require('luatest.helpers') local Server = require('luatest.server') +local log = require('luatest.log') local utils = require('luatest.utils') local ReplicaSet = {} @@ -72,6 +72,7 @@ function ReplicaSet:initialize() else self.servers = {} end + log.info('Replica set %s initialized', self.id) end --- Build a server object for the replica set. @@ -147,8 +148,7 @@ function ReplicaSet:delete_server(alias) if server_index then table.remove(self.servers, server_index) else - log.warn(('Server with alias "%s" does not exist in replica set') - :format(alias)) + log.warn('Server %s does not exist in replica set %s', alias, self.id) end end @@ -174,6 +174,7 @@ function ReplicaSet:start(opts) server:wait_until_ready() end end + log.info('All servers started in replica set %s', self.id) end --- Stop all servers in the replica set. @@ -235,6 +236,7 @@ function ReplicaSet:wait_for_fullmesh(opts) end end end, self) + log.info('Full mesh is ready in replica set %s', self.id) end return ReplicaSet diff --git a/luatest/runner.lua b/luatest/runner.lua index ce8baf69..75caa783 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -4,13 +4,13 @@ local clock = require('clock') local fio = require('fio') -local log = require('log') local assertions = require('luatest.assertions') local capturing = require('luatest.capturing') local Class = require('luatest.class') local GenericOutput = require('luatest.output.generic') local hooks = require('luatest.hooks') +local log = require('luatest.log') local loader = require('luatest.loader') local pp = require('luatest.pp') local Server = require('luatest.server') @@ -96,7 +96,7 @@ function Runner.run(args, options) -- Initialize logging for luatest runner. -- The log format will be as follows: -- YYYY-MM-DD HH:MM:SS.ZZZ [ID] main/.../luatest I> ... - log.cfg{ + require('log').cfg{ log = log_cfg, level = options.log_level or 5, } @@ -337,11 +337,13 @@ function Runner.mt:bootstrap() load_tests(path) end self.groups = self.luatest.groups + log.verbose('Bootstrap finished: %d test(s), %d group(s)', #self.paths, #self.groups) end function Runner.mt:cleanup() if not self.no_clean then fio.rmtree(Server.vardir) + log.verbose('Directory %s removed via cleanup procedure', Server.vardir) end end @@ -505,6 +507,7 @@ function Runner.mt:run_tests(tests_list) end rawget(_G, 'current_test').value = test self:run_test(test) + log.verbose('Test %s marked as %s', test.name, test.status) if self.result.aborted then break end diff --git a/luatest/server.lua b/luatest/server.lua index 442ff155..5a31540b 100644 --- a/luatest/server.lua +++ b/luatest/server.lua @@ -10,7 +10,6 @@ local fio = require('fio') local fun = require('fun') local http_client = require('http.client') local json = require('json') -local log = require('log') local net_box = require('net.box') local tarantool = require('tarantool') local uri = require('uri') @@ -19,6 +18,7 @@ local _, luacov_runner = pcall(require, 'luacov.runner') -- luacov may not be in local assertions = require('luatest.assertions') local HTTPResponse = require('luatest.http_response') local Process = require('luatest.process') +local log = require('luatest.log') local utils = require('luatest.utils') local DEFAULT_VARDIR = '/tmp/t' @@ -117,6 +117,7 @@ function Server:new(object, extra) if not object.tests[t.name] then object.tests[t.name] = t t.servers[object.id] = object + log.verbose('Server %s used in %s test', object.alias, t.name) end end return v(...) @@ -324,7 +325,6 @@ function Server:start(opts) for _, v in ipairs(args) do table.insert(log_cmd, string.format('%q', v)) end - log.debug(table.concat(log_cmd, ' ')) self.process = Process:start(command, args, env, { chdir = self.chdir, @@ -344,7 +344,7 @@ function Server:start(opts) self:wait_until_ready() end - log.debug('Started server PID: ' .. self.process.pid) + log.info('Server %s (pid: %d) started', self.alias, self.process.pid) end --- Restart the server with the given parameters. @@ -378,7 +378,7 @@ function Server:restart(params, opts) }, {wait_until_ready = '?boolean'}) if not self.process then - log.warn("Process wasn't started") + log.warn('Cannot restart server %s since its process not started', self.alias) end self:stop() @@ -387,7 +387,7 @@ function Server:restart(params, opts) end self:start(opts) - log.debug('Restarted server PID: ' .. self.process.pid) + log.info('Server %s (pid: %d) restarted', self.alias, self.process.pid) end -- Save server artifacts by copying the working directory. @@ -396,6 +396,7 @@ end -- following string: `Failed to copy artifacts for server (alias: , workdir: )`. function Server:save_artifacts() if self.artifacts_saved then + log.verbose('Artifacts of server %s already saved to %s', self.alias, self.artifacts) return end local ok, err = fio.copytree(self.workdir, self.artifacts) @@ -404,12 +405,16 @@ function Server:save_artifacts() :format(self.alias, fio.basename(self.workdir)) log.error(('%s: %s'):format(self.artifacts, err)) end + log.verbose('Artifacts of server %s saved from %s to %s', + self.alias, self.workdir, self.artifacts) self.artifacts_saved = true end -- Wait until the given condition is `true` (anything except `false` and `nil`). -- Throws an error when the server process is terminated or timeout exceeds. local function wait_for_condition(cond_desc, server, func, ...) + log.verbose('Wait for %s condition for server %s (pid: %d) within %d sec', + cond_desc, server.alias, server.process.pid, WAIT_TIMEOUT) local deadline = clock.time() + WAIT_TIMEOUT while true do if not server.process:is_alive() then @@ -437,6 +442,7 @@ function Server:stop() self:coverage('shutdown') end self.net_box:close() + log.verbose('Connection to server %s (pid: %d) closed', self.alias, self.process.pid) self.net_box = nil end @@ -470,7 +476,7 @@ function Server:stop() ) ) end - log.debug('Killed server process PID ' .. self.process.pid) + log.info('Process of server %s (pid: %d) killed', self.alias, self.process.pid) self.process = nil end end @@ -774,6 +780,8 @@ function Server:grep_log(pattern, bytes_num, opts) return rawget(_G, 'box_cfg_log_file') or box.cfg.log end) local file = fio.open(filename, {'O_RDONLY', 'O_NONBLOCK'}) + log.verbose('Trying to grep %s in server\'s log file %s', pattern, filename) + local function fail(msg) local err = errno.strerror() if file ~= nil then