From f4d3ba4f2815e039caf11350513059d586fddc7e 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 ++++++++++++++++++++ test/server_test.lua | 55 ++++++++++++++++++++++++----------------- 6 files changed, 129 insertions(+), 29 deletions(-) create mode 100644 test/fixtures/trace.lua diff --git a/CHANGELOG.md b/CHANGELOG.md index 956c0b52..56b65688 100644 --- a/CHANGELOG.md +++ b/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 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 diff --git a/test/server_test.lua b/test/server_test.lua index 5b061159..04c1c71e 100644 --- a/test/server_test.lua +++ b/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()