Propagate stack trace from Server:exec()

CHANGELOG.md

@@ -20,6 +20,9 @@
 - Fix reporting of an assertion failure in `Server:exec()` in case verbose
   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

luatest/utils.lua

@@ -61,23 +61,47 @@ end
 
 -- Check if line of stack trace comes from inside luatest.
 local function is_luatest_internal_line(s)
-    return s:find('[/\\]luatest[/\\]') or s:find('bin[/\\]luatest')
+    if s:find('bin[/\\]luatest') then
+        return true
+    end
+    if s:find('[/\\]luatest[/\\]') then
+        -- Do not strip lines originating from luatest test files because
+        -- we want to see stack traces when we test luatest.
+        return not s:find('[/\\]luatest[/\\]test[/\\]')
+    end
+    return false
 end
 
 function utils.strip_luatest_trace(trace)
     local lines = trace:split('\n')
-    local result = {lines[1]} -- always keep 1st line
+
+    -- Scan the stack trace backwards (from caller to callee) and strip all
+    -- frames related to luatest, as well as `[C]:`, `...`, `eval:` frames
+    -- called by them because they don't change context.
+    local result = {}
     local keep = true
-    for i = 2, table.maxn(lines) do
+    for i = table.maxn(lines), 2, -1 do
         local line = lines[i]
-        -- `[C]:` lines don't change context
-        if not line:find('^%s+%[C%]:') then
+        if not (line:find('^%s+%[C%]:') or
+                line:find('^%s+%.%.%.$') or
+                line:find('^%s+eval:')) then
             keep = not is_luatest_internal_line(line)
         end
         if keep then
             table.insert(result, line)
         end
     end
+
+    -- Always keep the 1st line because it's the header ('stack traceback:').
+    table.insert(result, lines[1])
+
+    -- Since we scanned the stack trace backwards, we need to reverse
+    -- the result.
+    for i = 1, math.floor(#result / 2) do
+        local v = result[#result - i + 1]
+        result[#result - i + 1] = result[i]
+        result[i] = v
+    end
     return table.concat(result, '\n')
 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/luaunit/utility_test.lua

@@ -847,6 +847,43 @@ function g.test_stripStackTrace()
         [[stack traceback:
     luaunit2/example_with_luaunit.lua:124: in function 'test1_withFailure']]
     )
+
+    t.assert_equals(subject([[stack traceback:
+    /tmp/luatest/luatest/utils.lua:55: in function 'luatest_error'
+    /tmp/luatest/luatest/assertions.lua:66: in function 'failure'
+    /tmp/luatest/luatest/assertions.lua:71: in function 'fail_fmt'
+    /tmp/luatest/luatest/assertions.lua:341: in function 'assert_le'
+    /tmp/luatest/test/example_test.lua:37: in function 'check'
+    /tmp/luatest/test/example_test.lua:40: in function </tmp/luatest/test/example_test.lua:34>
+    [C]: in function 'xpcall'
+    eval:9: in main chunk
+    [C]: at 0x5da8d110ced6
+    /tmp/luatest/luatest/server.lua:745: in function 'exec'
+    /tmp/luatest/test/example_test.lua:34: in function 'test.test_fail_server'
+    /tmp/luatest/luatest/runner.lua:472: in function </tmp/luatest/luatest/runner.lua:471>
+    [C]: in function 'xpcall'
+    /tmp/luatest/luatest/runner.lua:471: in function 'super'
+    /tmp/luatest/luatest/capturing.lua:106: in function 'protected_call'
+    /tmp/luatest/luatest/runner.lua:559: in function 'super'
+    /tmp/luatest/luatest/hooks.lua:290: in function 'invoke_test_function'
+    /tmp/luatest/luatest/runner.lua:554: in function 'super'
+    ...
+    [C]: in function 'xpcall'
+    /tmp/luatest/luatest/utils.lua:39: in function 'run_tests'
+    /tmp/luatest/luatest/runner.lua:381: in function </tmp/luatest/luatest/runner.lua:366>
+    [C]: in function 'xpcall'
+    /tmp/luatest/luatest/capturing.lua:74: in function </tmp/luatest/luatest/capturing.lua:72>
+    [C]: in function 'xpcall'
+    /tmp/luatest/luatest/runner.lua:55: in function 'fn'
+    .../vlad/src/tarantool/luatest/luatest/sandboxed_runner.lua:14: in function 'run'
+    /tmp/luatest/luatest/cli_entrypoint.lua:4: in function </tmp/luatest/luatest/cli_entrypoint.lua:3>
+    /tmp/luatest/bin/luatest:5: in main chunk]]
+        ),
+        [[stack traceback:
+    /tmp/luatest/test/example_test.lua:37: in function 'check'
+    /tmp/luatest/test/example_test.lua:40: in function </tmp/luatest/test/example_test.lua:34>
+    /tmp/luatest/test/example_test.lua:34: in function 'test.test_fail_server']]
+    )
 end
 
 function g.test_eps_value()

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