Logging improvements

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
 

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

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

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

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

luatest/output_beautifier.lua

@@ -59,41 +59,29 @@ 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
 
 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)

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

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

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