From c4d9c7ac5911974e9fe53a2b2bcb26c01cacf5a9 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 22 Oct 2024 20:06:43 +0300 Subject: [PATCH] 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 --- CHANGELOG.md | 2 ++ luatest/runner.lua | 4 ++++ luatest/server.lua | 23 ++++++++++++++------ test/fixtures/trace.lua | 47 +++++++++++++++++++++++++++++++++++++++++ test/runner_test.lua | 27 +++++++++++++++++++++++ 5 files changed, 97 insertions(+), 6 deletions(-) create mode 100644 test/fixtures/trace.lua diff --git a/CHANGELOG.md b/CHANGELOG.md index 245a46b6..2cd9e5a3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,8 @@ - Added `assert_items_exclude`. - Strip useless `...` lines from error trace. - Make `assert_error_*` ignore errors raised by assertion failures. +- Fix error trace reporting for functions executed with `Server:exec()` + (gh-396). ## 1.0.1 diff --git a/luatest/runner.lua b/luatest/runner.lua index 97f479a8..8d61d8ba 100644 --- a/luatest/runner.lua +++ b/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} diff --git a/luatest/server.lua b/luatest/server.lua index 131f259d..ce1f9d53 100644 --- a/luatest/server.lua +++ b/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 diff --git a/test/fixtures/trace.lua b/test/fixtures/trace.lua new file mode 100644 index 00000000..da0cf1f4 --- /dev/null +++ b/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 diff --git a/test/runner_test.lua b/test/runner_test.lua index 7c6309b3..e31f96b7 100644 --- a/test/runner_test.lua +++ b/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