From 701e5513899524b66f895f5fde4c7055a3e83e59 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/assertions.lua | 24 ++++++++++++++++----- luatest/runner.lua | 11 +++++++++- luatest/server.lua | 27 +++++++++++++++++------ test/fixtures/trace.lua | 47 +++++++++++++++++++++++++++++++++++++++++ test/runner_test.lua | 27 +++++++++++++++++++++++ 6 files changed, 126 insertions(+), 12 deletions(-) create mode 100644 test/fixtures/trace.lua diff --git a/CHANGELOG.md b/CHANGELOG.md index b1a16b3b..3954bb82 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/luatest/assertions.lua b/luatest/assertions.lua index 693eafa9..49717684 100644 --- a/luatest/assertions.lua +++ b/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 utils.is_luatest_error(err) and + err.status == 'wrapped_by_exec' then + err = err.message + 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', diff --git a/luatest/runner.lua b/luatest/runner.lua index 97f479a8..742572c4 100644 --- a/luatest/runner.lua +++ b/luatest/runner.lua @@ -475,7 +475,16 @@ 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 - return {status = e.status, message = e.message, trace = trace} + local status = e.status + if status == 'wrapped_by_exec' then + -- This is an error wrapped by Server:exec() to save the trace. + -- Concatenate the current trace with the saved trace. + assert(e.trace ~= nil) + trace = e.trace .. '\n' .. + trace:sub(string.len('stack traceback:\n') + 1) + status = 'error' + end + return {status = status, message = e.message, trace = trace} else return {status = 'error', message = e, trace = trace} end diff --git a/luatest/server.lua b/luatest/server.lua index 131f259d..dd258e59 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,23 @@ 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 = 'wrapped_by_exec', + 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