Propagate stack trace from Server:exec()

If a function executed with `Server:exec()` fails, luatest prints the
stack trace only up to the `Server:exec()` call. If the failure happens
to be in a nested function, this makes it impossible to figure out what
happened.

Let's propagate the error stack trace from the server to the runner
and make the runner concatenate it with its own stack trace. To achieve
that, we wrap errors raised by the function executed by `Serer:exec()`
to save the trace.

Closes #396

Author: locker

CHANGELOG.md

@@ -21,6 +21,8 @@
   error serialization is enabled in Tarantool (gh-376).
 - Added `assert_items_exclude`.
 - Strip useless `...` lines from error trace.
+- Fix error trace reporting for functions executed with `Server:exec()`
+  (gh-396).
 
 ## 1.0.1
 

luatest/assertions.lua

@@ -164,12 +164,26 @@ local function pcall_check_trace(level, fn, ...)
     return ok, err
 end
 
+--
+-- Wrapper around pcall that:
+-- * checks the stack trace for box errors;
+-- * unwraps the error if it was wrapped by Server:exec().
+--
+local function pcall_wrapper(level, fn, ...)
+    local ok, err = pcall_check_trace(level + 1, fn, ...)
+    if not ok and type(err) == 'table' and
+            err.class == 'LuatestErrorWrapper' then
+        err = err.error
+    end
+    return ok, err
+end
+
 --- Check that calling fn raises an error.
 --
 -- @func fn
 -- @param ... arguments for function
 function M.assert_error(fn, ...)
-    local ok, err = pcall_check_trace(2, fn, ...)
+    local ok, err = pcall_wrapper(2, fn, ...)
     if ok then
         failure("Expected an error when calling function but no error generated", nil, 2)
     end
@@ -565,7 +579,7 @@ function M.assert_str_matches(value, pattern, start, final, message)
 end
 
 local function _assert_error_msg_equals(stripFileAndLine, expectedMsg, func, ...)
-    local no_error, error_msg = pcall_check_trace(3, func, ...)
+    local no_error, error_msg = pcall_wrapper(3, func, ...)
     if no_error then
         local failure_message = string.format(
             'Function successfully returned: %s\nExpected error: %s',
@@ -631,7 +645,7 @@ end
 -- @func fn
 -- @param ... arguments for function
 function M.assert_error_msg_contains(expected_partial, fn, ...)
-    local no_error, error_msg = pcall_check_trace(2, 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(
@@ -654,7 +668,7 @@ end
 -- @func fn
 -- @param ... arguments for function
 function M.assert_error_msg_matches(pattern, fn, ...)
-    local no_error, error_msg = pcall_check_trace(2, fn, ...)
+    local no_error, error_msg = pcall_wrapper(2, fn, ...)
     if no_error then
         local failure_message = string.format(
             'Function successfully returned: %s\nExpected error matching: %s',
@@ -694,7 +708,7 @@ end
 -- @func fn
 -- @param ... arguments for function
 function M.assert_error_covers(expected, fn, ...)
-    local ok, actual = pcall_check_trace(2, fn, ...)
+    local ok, actual = pcall_wrapper(2, fn, ...)
     if ok then
         fail_fmt(2, nil,
                  'Function successfully returned: %s\nExpected error: %s',

luatest/runner.lua

@@ -474,6 +474,16 @@ function Runner.mt:protected_call(instance, method, pretty_name)
     end, function(e)
         -- transform error into a table, adding the traceback information
         local trace = debug.traceback('', 3):sub(2)
+        if type(e) == 'table' and e.class == 'LuatestErrorWrapper' then
+            -- This is an error wrapped by Server:exec() to save the trace.
+            -- Concatenate the current trace with the saved trace and restore
+            -- the original error.
+            assert(e.trace ~= nil)
+            assert(e.error ~= nil)
+            trace = e.trace .. '\n' ..
+                    trace:sub(string.len('stack traceback:\n') + 1)
+            e = e.error
+        end
         if utils.is_luatest_error(e) then
             return {status = e.status, message = e.message, trace = trace}
         else

luatest/server.lua

@@ -823,6 +823,10 @@ function Server:exec(fn, args, options)
         error(('bad argument #3 for exec at %s: an array is required'):format(utils.get_fn_location(fn)))
     end
 
+    -- Note that we wrap any error raised by the executed function to save
+    -- the original trace. It will be used by the runner to report the full
+    -- error trace, see Runner:protected_call().
+    --
     -- If the function fails an assertion in an open transaction, Tarantool
     -- will raise the "Transaction is active at return from function" error,
     -- thus overwriting the original error raised by the assertion. To avoid
@@ -836,12 +840,19 @@ function Server:exec(fn, args, options)
                 debug.setupvalue(fn, i, require(passthrough_ups[name]))
             end
         end
-        local result
-        if args == nil then
-            result = {pcall(fn)}
-        else
-            result = {pcall(fn, unpack(args))}
-        end
+        local result = {xpcall(function()
+            if args == nil then
+                return fn()
+            else
+                return fn(unpack(args))
+            end
+        end, function(e)
+            return {
+                class = 'LuatestErrorWrapper',
+                error = e,
+                trace = debug.traceback('', 3):sub(2),
+            }
+        end)}
         if not result[1] then
             box.rollback()
         end

test/fixtures/trace.lua

@@ -0,0 +1,47 @@
+local fio = require('fio')
+
+local t = require('luatest')
+local server = require('luatest.server')
+
+local g = t.group('fixtures.trace')
+
+local root = fio.dirname(fio.abspath('test.helpers'))
+
+g.before_all(function(cg)
+    cg.server = server:new{
+        env = {
+            LUA_PATH = root .. '/?.lua;' ..
+                root .. '/?/init.lua;' ..
+                root .. '/.rocks/share/tarantool/?.lua'
+        }
+    }
+    cg.server:start()
+end)
+
+g.after_all(function(cg)
+    cg.server:drop()
+end)
+
+g.test_error = function(cg)
+    local function outer()
+        cg.server:exec(function()
+            local function inner()
+                error('test error')
+            end
+            inner()
+        end)
+    end
+    outer()
+end
+
+g.test_fail = function(cg)
+    local function outer()
+        cg.server:exec(function()
+            local function inner()
+                t.assert(false)
+            end
+            inner()
+        end)
+    end
+    outer()
+end

test/runner_test.lua

@@ -224,3 +224,30 @@ g.test_show_help = function()
     local captured = capture:flush()
     t.assert_str_contains(captured.stdout, 'Usage: luatest')
 end
+
+g.test_trace = function()
+    local f = io.popen('bin/luatest test/fixtures/trace.lua')
+    local output = f:read('*a')
+    f:close()
+    t.assert_str_matches(
+        output,
+        ".*" ..
+        "[^\n]*trace%.lua:29: test error[^\n]*\n" ..
+        "stack traceback:\n" ..
+        "[^\n]*trace%.lua:29: in function 'inner'\n" ..
+        "[^\n]*trace%.lua:31: in function <[^\n]*trace%.lua:27>\n" ..
+        "[^\n]*trace%.lua:27: in function 'outer'\n" ..
+        "[^\n]*trace%.lua:34: in function 'fixtures%.trace%.test_error'\n" ..
+        ".*")
+    t.assert_str_matches(
+        output,
+        ".*" ..
+        "[^\n]*trace%.lua:41: expected: a value evaluating to true, " ..
+            "actual: false[^\n]*\n" ..
+        "stack traceback:\n" ..
+        "[^\n]*trace%.lua:41: in function 'inner'\n" ..
+        "[^\n]*trace%.lua:43: in function <[^\n]*trace%.lua:39>\n" ..
+        "[^\n]*trace%.lua:39: in function 'outer'\n" ..
+        "[^\n]*trace%.lua:46: in function 'fixtures%.trace%.test_fail'\n" ..
+        ".*")
+end