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

Author: Oleg Chaplashkin

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
 

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',

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

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')

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

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')
 

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

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

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: <alias>, workdir: <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