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()`
in `LuatestError` and set `trace` for it.

Closes #396

Author: locker

CHANGELOG.md

@@ -20,6 +20,8 @@
 - Fix reporting of an assertion failure in `Server:exec()` in case verbose
   error serialization is enabled in Tarantool (gh-376).
 - Added `assert_items_exclude`.
+- Fix error trace reporting for functions executed with `Server:exec()`
+  (gh-396).
 
 ## 1.0.1
 

luatest/runner.lua

@@ -475,6 +475,10 @@ function Runner.mt:protected_call(instance, method, pretty_name)
         -- transform error into a table, adding the traceback information
         local trace = debug.traceback('', 3):sub(2)
         if utils.is_luatest_error(e) then
+            if e.trace ~= nil then
+                trace = e.trace .. '\n' ..
+                        trace:sub(string.len('stack traceback:\n') + 1)
+            end
             return {status = e.status, message = e.message, trace = trace}
         else
             return {status = 'error', message = e, trace = trace}

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)
+            if not (type(e) == 'table' and e.class == 'LuatestError') then
+                e = {class = 'LuatestError', status = 'error', message = e}
+            end
+            e.trace = debug.traceback('', 3):sub(2)
+            return e
+        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

test/server_test.lua

@@ -208,10 +208,11 @@ g.test_net_box_exec = function()
 
     do
         local _l_fn, fn = l(), function() error('X_x') end
-        t.assert_error_msg_equals(
-            efmt(_l_fn, 'X_x'),
-            exec, fn
-        )
+        t.assert_error_covers({
+            class = 'LuatestError',
+            status = 'error',
+            message = efmt(_l_fn, 'X_x'),
+        }, exec, fn)
     end
 
     do
@@ -512,20 +513,24 @@ end)
 g.test_error_level_is_correct = function()
     local c = require('net.box').connect(g.s.net_box_uri)
 
-    t.assert_error_msg_contains( -- error in exec
-        "My error", g.s.exec, g.s,
-        function() error("My error") end)
+    t.assert_error_covers({ -- error in exec
+        class = 'LuatestError',
+        status = 'error',
+        message = "My error",
+    }, g.s.exec, g.s, function() error("My error", 0) end)
 
     t.assert_error_msg_contains( -- error in eval
         "eval", g.s.eval, g.s,
         [[error("My error")]])
 
-    t.assert_error_msg_contains( -- error in closures
-        "My error", g.s.exec, g.s,
-        function()
-            local function internal() error("My error") end
-            internal()
-        end)
+    t.assert_error_covers({ -- error in closures
+        class = 'LuatestError',
+        status = 'error',
+        message = "My error",
+    }, g.s.exec, g.s, function()
+        local function internal() error("My error", 0) end
+        internal()
+    end)
 
     t.assert_error_msg_contains( -- error in tx netbox connection
         "My error", c.eval, c,
@@ -535,16 +540,20 @@ g.test_error_level_is_correct = function()
         "My error", g.s.eval, g.s,
         [[box.begin() error("My error")]])
 
-    t.assert_error_msg_contains( -- error in tx exec
-        "My error", g.s.exec, g.s,
-        function() box.begin() error("My error") end)
-
-    t.assert_error_msg_contains( -- error in tx closures
-        "My error", g.s.exec, g.s,
-        function()
-            local function internal() box.begin() error("My error") end
-            internal()
-        end)
+    t.assert_error_covers({ -- error in tx exec
+        class = 'LuatestError',
+        status = 'error',
+        message = "My error",
+    }, g.s.exec, g.s, function() box.begin() error("My error", 0) end)
+
+    t.assert_error_covers({ -- error in tx closures
+        class = 'LuatestError',
+        status = 'error',
+        message = "My error",
+    }, g.s.exec, g.s, function()
+        local function internal() box.begin() error("My error", 0) end
+        internal()
+    end)
 end
 
 g.after_test('test_error_level_is_correct', function()