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/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 88b8a19..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.verbose('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/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..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 @@ -30,14 +23,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/output_beautifier.lua b/luatest/output_beautifier.lua index b9cf587..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,30 +69,19 @@ 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 = '' - self.enable_capture = nil 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 -- 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 +155,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/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 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/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/runner.lua b/luatest/runner.lua index a3e7091..d17f932 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}) - output_beautifier:enable({enable_capture = options.enable_capture}) - output_beautifier:hijack_output() + local output_beautifier = OutputBeautifier:new({prefix = log_prefix}) + output_beautifier:enable() -- `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, @@ -99,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 @@ -135,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) @@ -192,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 @@ -353,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 @@ -543,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 @@ -562,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/luatest/server.lua b/luatest/server.lua index ff06830..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.verbose('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.verbose('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.verbose('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.verbose('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.verbose('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.verbose('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() 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}, {})