From e80cfe792b1b2a1a9ca58cfb055f83c34311a32a Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 11:09:12 +0300 Subject: [PATCH 1/6] Do not spam stdout on failure when unified logging is enabled Unified logging is a fetaure that enables writing logs emitted by all server instances instances and the luatest runner itself to a single file. It's implemented by duplicating logs to stdout (using the tee Linux command) and piping stdout to a log file in OutputBeautifier. The OutputBeautifier still writes the logs to stdout, even if unified logging is enabled. As a result, on any failure the runner spams stdout with captured logs of started server instances. There's no need for that because all logs can be read from the unified log file. It only clutters the output making it difficult to figure out what went wrong. So let's disable writing to stdout in OutputBeautifier if unified logging is enabled. No changelog because the feature was added by commit f8a1c10baa482 ("Add logging to unified file"), which hasn't been released yet. Closes #382 --- luatest/output_beautifier.lua | 15 ++++++--------- luatest/runner.lua | 2 +- 2 files changed, 7 insertions(+), 10 deletions(-) diff --git a/luatest/output_beautifier.lua b/luatest/output_beautifier.lua index b9cf587..5d98cc0 100644 --- a/luatest/output_beautifier.lua +++ b/luatest/output_beautifier.lua @@ -75,7 +75,6 @@ function OutputBeautifier.mt:initialize() self.pipes.stdout = ffi_io.create_pipe() end self.stderr = '' - self.enable_capture = nil end -- Replace standard output descriptors with pipes. @@ -91,9 +90,6 @@ end -- Start fibers that reads from pipes and prints formatted output. -- Pass `track_pid` option to automatically stop forwarder once process is finished. function OutputBeautifier.mt:enable(options) - if options and options.enable_capture ~= nil then - self.enable_capture = options.enable_capture == false - end if self.fibers then return end @@ -167,17 +163,18 @@ function OutputBeautifier.mt:run(fd, pipe) table.remove(lines) end for _, line in pairs(lines) do - line_color_code = self:color_for_line(line) or line_color_code - if not self.runner or self.enable_capture then + if log_file ~= nil then + -- Redirect all output to the log file if unified logging + -- is enabled. + log_file.fh:write(table.concat({prefix, line, '\n'})) + else + line_color_code = self:color_for_line(line) or line_color_code io.stdout:write( table.concat( {colored_prefix, line_color_code, line, self.class.RESET_TERM,'\n'} ) ) end - if log_file ~= nil then - log_file.fh:write(table.concat({prefix, line, '\n'})) - end fiber.yield() end end) diff --git a/luatest/runner.lua b/luatest/runner.lua index a3e7091..dc7ef9d 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -73,7 +73,7 @@ function Runner.run(args, options) rawset(_G, 'log_file', {fh = fh}) local output_beautifier = OutputBeautifier:new({prefix = log_prefix, runner = true}) - output_beautifier:enable({enable_capture = options.enable_capture}) + output_beautifier:enable() output_beautifier:hijack_output() -- `tee` copy logs to file and also to standard output, but we need From 42ab21410fe732622224229ae7bdc2543f64f897 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 11:22:46 +0300 Subject: [PATCH 2/6] Do not hijack runner stderr for unified logging This is ugly. Instead, let's redirect logs directly to the pipe created by the OutputBeautifier. No changelog because the feature was added by commit f8a1c10baa482 ("Add logging to unified file"), which hasn't been released yet. --- luatest/output_beautifier.lua | 14 +++----------- luatest/runner.lua | 11 ++++------- 2 files changed, 7 insertions(+), 18 deletions(-) diff --git a/luatest/output_beautifier.lua b/luatest/output_beautifier.lua index 5d98cc0..7a83891 100644 --- a/luatest/output_beautifier.lua +++ b/luatest/output_beautifier.lua @@ -59,10 +59,9 @@ end -- @string object.prefix String to prefix each output line with. -- @string[opt] object.color Color name for prefix. -- @string[opt] object.color_code Color code for prefix. --- @boolean[opt] object.runner Mark OutputBeautifier object is created for runner process. -- @return input object. function OutputBeautifier:new(object) - checks('table', {prefix = 'string', color = '?string', color_code = '?string', runner = '?boolean'}) + checks('table', {prefix = 'string', color = '?string', color_code = '?string'}) return self:from(object) end @@ -70,20 +69,13 @@ function OutputBeautifier.mt:initialize() self.color_code = self.color_code or self.class.COLOR_BY_NAME[self.color] or OutputBeautifier:next_color_code() - self.pipes = {stderr = ffi_io.create_pipe()} - if not self.runner then - self.pipes.stdout = ffi_io.create_pipe() - end + self.pipes = {stdout = ffi_io.create_pipe(), stderr = ffi_io.create_pipe()} self.stderr = '' end -- Replace standard output descriptors with pipes. --- Stdout descriptor of the runner process will not be replaced --- because it is used for displaying all captured data from other processes. function OutputBeautifier.mt:hijack_output() - if not self.runner then - ffi_io.dup2_io(self.pipes.stdout[1], io.stdout) - end + ffi_io.dup2_io(self.pipes.stdout[1], io.stdout) ffi_io.dup2_io(self.pipes.stderr[1], io.stderr) end diff --git a/luatest/runner.lua b/luatest/runner.lua index dc7ef9d..7c01352 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -72,17 +72,14 @@ function Runner.run(args, options) local fh = fio.open(options.log_file, {'O_CREAT', 'O_WRONLY'}, tonumber('640', 8)) rawset(_G, 'log_file', {fh = fh}) - local output_beautifier = OutputBeautifier:new({prefix = log_prefix, runner = true}) + local output_beautifier = OutputBeautifier:new({prefix = log_prefix}) output_beautifier:enable() - output_beautifier:hijack_output() -- `tee` copy logs to file and also to standard output, but we need -- process all captured data through the OutputBeatifier object. - -- Data will be redirected back to stderr of the current process. - -- `/dev/fd/2` is a symlink to `/proc/self/fd`, where `/proc/self` is - -- a symlink to `/proc/`. So `/dev/fd/2` is equal to `/proc//fd/2` - -- and it means "stderr of the current process". - log_cfg = string.format("| tee %s > /dev/fd/2", log_cfg) + -- So we redirect stdout to the pipe created by OutputBeautifier. + log_cfg = string.format("| tee %s > /dev/fd/%d", + log_cfg, output_beautifier.pipes.stdout[1]) end -- Logging cannot be initialized without configuring the `box` engine -- on a version less than 2.5.1 (see more details at [1]). Otherwise, From 0fb1839694caed656d9ebaab3c3e41872d75bbb4 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 11:50:17 +0300 Subject: [PATCH 3/6] Drop log verbosity levels In the scope of unified logging, new options -vv and -vvv were introduced. They set the luatest log level to VERBOSE and DEBUG, respectively. Actually, there's no need to suppress any logging because it goes to a file and doesn't spam the output. Besides, it's ugly that we mix luatest logging with luatest output verbosity. Let's drop the levels and use log.info instead of log.verbose or log.debug everywhere in luatest. No changelog because the feature was added by commit f8a1c10baa482 ("Add logging to unified file"), which hasn't been released yet. --- luatest/helpers.lua | 2 +- luatest/hooks.lua | 4 ++-- luatest/log.lua | 8 -------- luatest/process.lua | 2 +- luatest/runner.lua | 19 ++++--------------- luatest/server.lua | 12 ++++++------ 6 files changed, 14 insertions(+), 33 deletions(-) diff --git a/luatest/helpers.lua b/luatest/helpers.lua index 88b8a19..b5e3cc7 100644 --- a/luatest/helpers.lua +++ b/luatest/helpers.lua @@ -69,7 +69,7 @@ function helpers.retrying(config, fn, ...) if (clock.time() - started_at) > timeout then return fn(...) end - log.verbose('Retrying in %d sec due to error: %s', delay, result) + log.info('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 04c76ab..985bf4e 100644 --- a/luatest/hooks.lua +++ b/luatest/hooks.lua @@ -241,7 +241,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) + log.info('Run hook %s', hooks_type) local group = test.group local hook -- Support for group.setup/teardown methods (legacy API) @@ -256,7 +256,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) + log.info('Run hook %s', hooks_type) local group = test.group local hook = group['run_' .. hooks_type] if hook then diff --git a/luatest/log.lua b/luatest/log.lua index f6183d2..a09c8ac 100644 --- a/luatest/log.lua +++ b/luatest/log.lua @@ -30,14 +30,6 @@ function log.info(msg, ...) return _log('info', msg, ...) end -function log.verbose(msg, ...) - return _log('verbose', msg, ...) -end - -function log.debug(msg, ...) - return _log('debug', msg, ...) -end - function log.warn(msg, ...) return _log('warn', msg, ...) end diff --git a/luatest/process.lua b/luatest/process.lua index bb54618..89622cd 100644 --- a/luatest/process.lua +++ b/luatest/process.lua @@ -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 %d", pid) + log.info("Killing GC'ed process %d", pid) Process.kill_pid(pid, nil, {quiet = true}) end) end diff --git a/luatest/runner.lua b/luatest/runner.lua index 7c01352..eb1773d 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -96,10 +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> ... - require('log').cfg{ - log = log_cfg, - level = options.log_level or 5, - } + require('log').cfg{log = log_cfg} end if options.help then @@ -132,8 +129,6 @@ Options: -h, --help: Print this help --version: Print version information -v, --verbose: Increase output verbosity for luatest runnner - -vv, Increase log verbosity to VERBOSE level for luatest runnner - -vvv, Increase log verbosity to DEBUG level for luatest runnner -q, --quiet: Set verbosity to minimum -c, --no-capture Disable capture -b Print full backtrace (don't remove luatest frames) @@ -189,12 +184,6 @@ function Runner.parse_cmd_line(args) result.version = true elseif arg == '--verbose' or arg == '-v' then result.verbosity = GenericOutput.VERBOSITY.VERBOSE - elseif arg == '-vv' then - result.verbosity = GenericOutput.VERBOSITY.VERBOSE - result.log_level = 6 -- verbose - elseif arg == '-vvv' then - result.verbosity = GenericOutput.VERBOSITY.VERBOSE - result.log_level = 7 -- debug elseif arg == '--quiet' or arg == '-q' then result.verbosity = GenericOutput.VERBOSITY.QUIET elseif arg == '--fail-fast' or arg == '-f' then @@ -350,13 +339,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) + log.info('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) + log.info('Directory %s removed via cleanup procedure', Server.vardir) end end @@ -540,7 +529,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) + log.info('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 ff06830..60f4418 100644 --- a/luatest/server.lua +++ b/luatest/server.lua @@ -127,7 +127,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) + log.info('Server %s used in %s test', object.alias, t.name) end end return v(...) @@ -513,7 +513,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) + log.info('Artifacts of server %s already saved to %s', self.alias, self.artifacts) return end local ok, err = fio.copytree(self.workdir, self.artifacts) @@ -522,7 +522,7 @@ 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', + log.info('Artifacts of server %s saved from %s to %s', self.alias, self.workdir, self.artifacts) self.artifacts_saved = true end @@ -530,7 +530,7 @@ 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', + log.info('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 @@ -559,7 +559,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) + log.info('Connection to server %s (pid: %d) closed', self.alias, self.process.pid) self.net_box = nil end @@ -895,7 +895,7 @@ 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) + log.info('Trying to grep %s in server\'s log file %s', pattern, filename) local function fail(msg) local err = errno.strerror() From 5a63cc93b4b6e2fffb402b4a95964d4217b9a237 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 13:59:47 +0300 Subject: [PATCH 4/6] Improve assertion logging * Log all assertions, not just a few select ones. * Don't log assertion arguments because that would be too verbose. Instead, log only the file and the line where the assertion is checked. It should be enough for debugging. * Log where helpers.retrying is called. Also, fix formatting of fractional seconds. * Log test errors and failures so that one can figure out where the test failed by just looking at the unified log, without the luatest output. No changelog because the feature was added by commit d985997f1c57b ("Add more logs"), which hasn't been released yet. --- luatest/assertions.lua | 18 +++++++++++++----- luatest/helpers.lua | 6 +++++- luatest/runner.lua | 4 ++++ test/luatest_test.lua | 5 ----- 4 files changed, 22 insertions(+), 11 deletions(-) diff --git a/luatest/assertions.lua b/luatest/assertions.lua index ac07df8..fb5e73d 100644 --- a/luatest/assertions.lua +++ b/luatest/assertions.lua @@ -11,6 +11,7 @@ local pp = require('luatest.pp') local log = require('luatest.log') local utils = require('luatest.utils') local tarantool = require('tarantool') +local fio = require('fio') local ffi = require('ffi') local prettystr = pp.tostring @@ -271,7 +272,6 @@ 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 @@ -378,7 +378,6 @@ 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 @@ -502,8 +501,6 @@ 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) @@ -646,7 +643,6 @@ end -- @param ... arguments for function function M.assert_error_msg_contains(expected_partial, fn, ...) local no_error, error_msg = pcall_wrapper(2, 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', @@ -891,4 +887,16 @@ function M.assert_not_minus_zero(value, message) end end +-- Log all checked assertions for debugging. +for func_name, func in pairs(M) do + if func_name:startswith('assert') and type(func) == 'function' then + M[func_name] = function(...) + local info = debug.getinfo(2, 'Sl') + log.info('Checking assertion at %s:%s', + fio.basename(info.short_src), info.currentline) + return func(...) + end + end +end + return M diff --git a/luatest/helpers.lua b/luatest/helpers.lua index b5e3cc7..e9d6179 100644 --- a/luatest/helpers.lua +++ b/luatest/helpers.lua @@ -4,6 +4,7 @@ local clock = require('clock') local fiber = require('fiber') +local fio = require('fio') local log = require('luatest.log') local helpers = {} @@ -69,7 +70,10 @@ function helpers.retrying(config, fn, ...) if (clock.time() - started_at) > timeout then return fn(...) end - log.info('Retrying in %d sec due to error: %s', delay, result) + local info = debug.getinfo(2, 'Sl') + log.info('Retrying at %s:%s in %0.3f sec due to error:', + fio.basename(info.short_src), info.currentline, delay) + log.info(result) fiber.sleep(delay) end end diff --git a/luatest/runner.lua b/luatest/runner.lua index eb1773d..d17f932 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -548,6 +548,10 @@ end function Runner.mt:invoke_test_function(test) local err = self:protected_call(test.group, test.method, test.name) + if err.status == 'fail' or err.status == 'error' then + log.error(err.message) + log.error(err.trace) + end self:update_status(test, err) end diff --git a/test/luatest_test.lua b/test/luatest_test.lua index 7db1ec8..ba6e750 100644 --- a/test/luatest_test.lua +++ b/test/luatest_test.lua @@ -103,11 +103,6 @@ g.test_success_if_tnt_specific = function() t.assert_equals(helper.assert_failure(t.success_if, {}).status, 'success') end -g.test_assert_aliases = function () - t.assert_is(t.assert, t.assert_eval_to_true) - t.assert_is(t.assert_not, t.assert_eval_to_false) -end - g.test_assert_covers = function() local subject = t.assert_covers subject({a = 1, b = 2, c = 3}, {}) From 63b6c7589e16abaa0c29b2c645df34b26197fbd1 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 14:50:20 +0300 Subject: [PATCH 5/6] Do not pretty format log arguments This is bad because it quotes all strings although most of the times we don't need it. This also makes `luatest.log` work differently from the built-in logger while we want them to be interchangeable. We don't need pretty-printing anymore because we don't log assertion arguments. If the caller needs pretty-printing, they can do it manually. This effectively reverts commit 15dbf758473f0 ("Improve luatest.log function if a nil value is passed") and a good part of commit a005329785a1d ("Add syntax sugar for more convenient logging"). --- CHANGELOG.md | 2 +- luatest/log.lua | 11 ++--------- luatest/pp.lua | 24 +++++++++--------------- 3 files changed, 12 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3954bb8..0989b27 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,6 @@ - Add logging to unified file (gh-324). - 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). - Add `justrun` helper as a tarantool runner and output catcher (gh-365). @@ -23,6 +22,7 @@ - Strip useless `...` lines from error trace. - Fix error trace reporting for functions executed with `Server:exec()` (gh-396). +- Remove pretty-printing of `luatest.log` arguments. ## 1.0.1 diff --git a/luatest/log.lua b/luatest/log.lua index a09c8ac..c6741ac 100644 --- a/luatest/log.lua +++ b/luatest/log.lua @@ -1,22 +1,15 @@ local tarantool_log = require('log') local utils = require('luatest.utils') -local pp = require('luatest.pp') -- Utils for logging local log = {} local default_level = 'info' local function _log(level, msg, ...) - if not utils.version_current_ge_than(2, 5, 1) then - return + if utils.version_current_ge_than(2, 5, 1) then + return tarantool_log[level](msg, ...) end - local args = {} - for i = 1, select('#', ...) do - local v = select(i, ...) - table.insert(args, pp.tostringlog(v)) - end - return tarantool_log[level](msg, unpack(args)) end --- Extra wrapper for `__call` function diff --git a/luatest/pp.lua b/luatest/pp.lua index d3c8801..eeeb226 100644 --- a/luatest/pp.lua +++ b/luatest/pp.lua @@ -21,7 +21,7 @@ local TABLE_TOSTRING_SEP_LEN = string.len(TABLE_TOSTRING_SEP) -- Final function called in format_table() to format the resulting list of -- string describing the table. -local function _table_tostring_format_result(tbl, result, indentLevel, printTableRefs, isLogLine) +local function _table_tostring_format_result(tbl, result, indentLevel, printTableRefs) local dispOnMultLines = false -- set dispOnMultLines to true if the maximum LINE_LENGTH would be exceeded with the values @@ -46,7 +46,7 @@ local function _table_tostring_format_result(tbl, result, indentLevel, printTabl end -- now reformat the result table (currently holding element strings) - if dispOnMultLines and not isLogLine then + if dispOnMultLines then local indentString = string.rep(" ", indentLevel - 1) result = { "{\n ", @@ -77,7 +77,7 @@ function Formatter.mt:initialize(printTableRefs) self.recursionTable = {} end -function Formatter.mt:format_table(tbl, indentLevel, isLogLine) +function Formatter.mt:format_table(tbl, indentLevel) indentLevel = indentLevel or 1 self.recursionTable[tbl] = true @@ -133,16 +133,16 @@ function Formatter.mt:format_table(tbl, indentLevel, isLogLine) count = count + 1 result[count] = entry end - return _table_tostring_format_result(tbl, result, indentLevel, self.printTableRefs, isLogLine) + return _table_tostring_format_result(tbl, result, indentLevel, self.printTableRefs) end end -function Formatter.mt:format(v, indentLevel, isLogLine) +function Formatter.mt:format(v, indentLevel) local type_v = type(v) if "string" == type_v then return string.format("%q", v) elseif "table" == type_v then - return self:format_table(v, indentLevel, isLogLine) + return self:format_table(v, indentLevel) elseif "number" == type_v then -- eliminate differences in formatting between various Lua versions if v ~= v then @@ -169,24 +169,18 @@ end -- -- * string are enclosed with " by default, or with ' if string contains a " -- * tables are expanded to show their full content, with indentation in case of nested tables -function pp.tostring(value, is_logline) +function pp.tostring(value) local formatter = Formatter:new(pp.TABLE_REF_IN_ERROR_MSG) - local result = formatter:format(value, nil, is_logline) + local result = formatter:format(value) if formatter.recursionDetected and not pp.TABLE_REF_IN_ERROR_MSG then -- some table contain recursive references, -- so we must recompute the value by including all table references -- else the result looks like crap - return Formatter:new(true):format(value, nil, is_logline) + return Formatter:new(true):format(value) end return result end --- This function helps with displaying `value` of any type without line breaks ('\n') --- for logging. It is a simple wrapper over the tostring() function. -function pp.tostringlog(value) - return pp.tostring(value, true) -end - local function has_new_line(s) return (string.find(s, '\n', 1, true) ~= nil) end From 0dfcc0d58a2e8ddffe432c7b6389696936c59d0c Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 29 Oct 2024 15:01:03 +0300 Subject: [PATCH 6/6] Quote some logged strings Now, that auto-quoting is disabled in the log, let's quote server names and conditions because without quoting they look ugly. No changelog as this is a minor change related to the previous commit. --- luatest/replica_set.lua | 8 ++++---- luatest/server.lua | 20 ++++++++++---------- 2 files changed, 14 insertions(+), 14 deletions(-) diff --git a/luatest/replica_set.lua b/luatest/replica_set.lua index f5e19a5..6b1716f 100644 --- a/luatest/replica_set.lua +++ b/luatest/replica_set.lua @@ -72,7 +72,7 @@ function ReplicaSet:initialize() else self.servers = {} end - log.info('Replica set %s initialized', self.id) + log.info('Replica set %q initialized', self.id) end --- Build a server object for the replica set. @@ -148,7 +148,7 @@ function ReplicaSet:delete_server(alias) if server_index then table.remove(self.servers, server_index) else - log.warn('Server %s does not exist in replica set %s', alias, self.id) + log.warn('Server %q does not exist in replica set %q', alias, self.id) end end @@ -174,7 +174,7 @@ function ReplicaSet:start(opts) server:wait_until_ready() end end - log.info('All servers started in replica set %s', self.id) + log.info('All servers started in replica set %q', self.id) end --- Stop all servers in the replica set. @@ -236,7 +236,7 @@ function ReplicaSet:wait_for_fullmesh(opts) end end end, self) - log.info('Full mesh is ready in replica set %s', self.id) + log.info('Full mesh is ready in replica set %q', self.id) end return ReplicaSet diff --git a/luatest/server.lua b/luatest/server.lua index 60f4418..34917de 100644 --- a/luatest/server.lua +++ b/luatest/server.lua @@ -127,7 +127,7 @@ function Server:new(object, extra) if not object.tests[t.name] then object.tests[t.name] = t t.servers[object.id] = object - log.info('Server %s used in %s test', object.alias, t.name) + log.info('Server %q used in %s test', object.alias, t.name) end end return v(...) @@ -461,7 +461,7 @@ function Server:start(opts) self:wait_until_ready() end - log.info('Server %s (pid: %d) started', self.alias, self.process.pid) + log.info('Server %q (pid: %d) started', self.alias, self.process.pid) end --- Restart the server with the given parameters. @@ -495,7 +495,7 @@ function Server:restart(params, opts) }, {wait_until_ready = '?boolean'}) if not self.process then - log.warn('Cannot restart server %s since its process not started', self.alias) + log.warn('Cannot restart server %q since its process not started', self.alias) end self:stop() @@ -504,7 +504,7 @@ function Server:restart(params, opts) end self:start(opts) - log.info('Server %s (pid: %d) restarted', self.alias, self.process.pid) + log.info('Server %q (pid: %d) restarted', self.alias, self.process.pid) end -- Save server artifacts by copying the working directory. @@ -513,7 +513,7 @@ end -- following string: `Failed to copy artifacts for server (alias: , workdir: )`. function Server:save_artifacts() if self.artifacts_saved then - log.info('Artifacts of server %s already saved to %s', self.alias, self.artifacts) + log.info('Artifacts of server %q already saved to %s', self.alias, self.artifacts) return end local ok, err = fio.copytree(self.workdir, self.artifacts) @@ -522,7 +522,7 @@ function Server:save_artifacts() :format(self.alias, fio.basename(self.workdir)) log.error(('%s: %s'):format(self.artifacts, err)) end - log.info('Artifacts of server %s saved from %s to %s', + log.info('Artifacts of server %q saved from %s to %s', self.alias, self.workdir, self.artifacts) self.artifacts_saved = true end @@ -530,7 +530,7 @@ 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.info('Wait for %s condition for server %s (pid: %d) within %d sec', + log.info('Wait for %q condition for server %q (pid: %d) within %d sec', cond_desc, server.alias, server.process.pid, WAIT_TIMEOUT) local deadline = clock.time() + WAIT_TIMEOUT while true do @@ -559,7 +559,7 @@ function Server:stop() self:coverage('shutdown') end self.net_box:close() - log.info('Connection to server %s (pid: %d) closed', self.alias, self.process.pid) + log.info('Connection to server %q (pid: %d) closed', self.alias, self.process.pid) self.net_box = nil end @@ -582,7 +582,7 @@ function Server:stop() error(('Memory leak during process execution (alias: %s, workdir: %s, pid: %s)\n%s') :format(self.alias, workdir, pid, stderr)) end - log.info('Process of server %s (pid: %d) killed', self.alias, self.process.pid) + log.info('Process of server %q (pid: %d) killed', self.alias, self.process.pid) self.process = nil end end @@ -895,7 +895,7 @@ 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.info('Trying to grep %s in server\'s log file %s', pattern, filename) + log.info('Trying to grep %q in server\'s log file %s', pattern, filename) local function fail(msg) local err = errno.strerror()