From 92a8a6ff2405e115a0748388eb535f2a151a4669 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 22 Oct 2024 18:20:36 +0300 Subject: [PATCH 1/2] Fix utils.strip_luatest_trace * Strip uselss `...` and `eval` lines. * Scan the stack trace backwards so as to skip `[C]`, `...`, and `eval` lines that were called by luatest internal files, not vice versa. * Don't strip lines related to luatest test files (from luatest/test), even though they match the luatest internal file pattern, because we do want to see stack traces when we test luatest. Needed for #396 --- CHANGELOG.md | 1 + luatest/utils.lua | 34 +++++++++++++++++++++++++++----- test/luaunit/utility_test.lua | 37 +++++++++++++++++++++++++++++++++++ 3 files changed, 67 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 956c0b5..b1a16b3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,7 @@ - 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. ## 1.0.1 diff --git a/luatest/utils.lua b/luatest/utils.lua index cb97f22..014179e 100644 --- a/luatest/utils.lua +++ b/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 diff --git a/test/luaunit/utility_test.lua b/test/luaunit/utility_test.lua index 95b840c..1afa7b9 100644 --- a/test/luaunit/utility_test.lua +++ b/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 + [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 + [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 + [C]: in function 'xpcall' + /tmp/luatest/luatest/capturing.lua:74: in function + [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/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: in function 'test.test_fail_server']] + ) end function g.test_eps_value() From 292bf80d69968b99761cd9d68bb544a9910d3b31 Mon Sep 17 00:00:00 2001 From: Vladimir Davydov Date: Tue, 22 Oct 2024 20:06:43 +0300 Subject: [PATCH 2/2] 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()` to save the trace. Closes #396 --- CHANGELOG.md | 2 ++ luatest/assertions.lua | 24 ++++++++++++++++----- luatest/runner.lua | 10 +++++++++ luatest/server.lua | 23 ++++++++++++++------ test/fixtures/trace.lua | 47 +++++++++++++++++++++++++++++++++++++++++ test/runner_test.lua | 27 +++++++++++++++++++++++ 6 files changed, 122 insertions(+), 11 deletions(-) create mode 100644 test/fixtures/trace.lua diff --git a/CHANGELOG.md b/CHANGELOG.md index b1a16b3..3954bb8 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 693eafa..ac07df8 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 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', diff --git a/luatest/runner.lua b/luatest/runner.lua index 97f479a..a3e7091 100644 --- a/luatest/runner.lua +++ b/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 diff --git a/luatest/server.lua b/luatest/server.lua index 131f259..ff06830 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) + return { + class = 'LuatestErrorWrapper', + error = e, + trace = debug.traceback('', 3):sub(2), + } + 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 0000000..da0cf1f --- /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 7c6309b..e31f96b 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