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 d985997
("Add more logs"), which hasn't been released yet.

Author: locker

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.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

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
 

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}, {})