Skip to content

Commit

Permalink
Extend stacktrace for failed tests not directly under testset (#49451)
Browse files Browse the repository at this point in the history
  • Loading branch information
@serenity4
serenity4 authored May 3, 2023
1 parent 43c9202 commit 5304baa
Show file tree
Hide file tree
Showing 3 changed files with 169 additions and 14 deletions.
1 change: 1 addition & 0 deletions NEWS.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -107,6 +107,7 @@ Standard library changes

* The `@test_broken` macro (or `@test` with `broken=true`) now complains if the test expression returns a
non-boolean value in the same way as a non-broken test. ([#47804])
* When a call to `@test` fails or errors inside a function, a larger stacktrace is now printed such that the location of the test within a `@testset` can be retrieved ([#49451])

#### Dates

Expand Down
73 changes: 59 additions & 14 deletions stdlib/Test/src/Test.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -47,23 +47,56 @@ const FAIL_FAST = Ref{Bool}(false)

# Backtrace utility functions
function ip_has_file_and_func(ip, file, funcs)
return any(fr -> (string(fr.file) == file && fr.func in funcs), StackTraces.lookup(ip))
return any(fr -> (in_file(fr, file) && fr.func in funcs), StackTraces.lookup(ip))
end
in_file(frame, file) = string(frame.file) == file

function scrub_backtrace(bt)
function test_location(bt, file_ts, file_t)
if (isnothing(file_ts) || isnothing(file_t))
return macrocall_location(bt, something(file_ts, @__FILE__))
else
return test_callsite(bt, file_ts, file_t)
end
end

function test_callsite(bt, file_ts, file_t)
# We avoid duplicate calls to `StackTraces.lookup`, as it is an expensive call.
# For that, we retrieve locations from lower to higher stack elements
# and only traverse parts of the backtrace which we haven't traversed before.
# The order will always be <internal functions> -> `@test` -> `@testset`.
internal = macrocall_location(bt, @__FILE__)::Int
test = internal - 1 + findfirst(ip -> any(frame -> in_file(frame, file_t), StackTraces.lookup(ip)), @view bt[internal:end])::Int
testset = test - 1 + macrocall_location(@view(bt[test:end]), file_ts)::Int

# If stacktrace locations differ, include frames until the `@testset` appears.
test != testset && return testset
# `@test` and `@testset` occurred at the same stacktrace location.
# This may happen if `@test` occurred directly in scope of the testset,
# or if `@test` occurred in a function that has been inlined in the testset.
frames = StackTraces.lookup(bt[testset])
outer_frame = findfirst(frame -> in_file(frame, file_ts) && frame.func == Symbol("macro expansion"), frames)::Int
# The `@test` call occurred directly in scope of a `@testset`.
# The __source__ from `@test` will be printed in the test message upon failure.
# There is no need to include more frames, but always include at least the internal macrocall location in the stacktrace.
in_file(frames[outer_frame], file_t) && return internal
# The `@test` call was inlined, so we still need to include the callsite.
return testset
end

macrocall_location(bt, file) = findfirst(ip -> ip_has_file_and_func(ip, file, (Symbol("macro expansion"),)), bt)

function scrub_backtrace(bt, file_ts, file_t)
do_test_ind = findfirst(ip -> ip_has_file_and_func(ip, @__FILE__, (:do_test, :do_test_throws)), bt)
if do_test_ind !== nothing && length(bt) > do_test_ind
bt = bt[do_test_ind + 1:end]
end
name_ind = findfirst(ip -> ip_has_file_and_func(ip, @__FILE__, (Symbol("macro expansion"),)), bt)
if name_ind !== nothing && length(bt) != 0
bt = bt[1:name_ind]
end
stop_at = test_location(bt, file_ts, file_t)
!isnothing(stop_at) && !isempty(bt) && return bt[1:stop_at]
return bt
end

function scrub_exc_stack(stack)
return Any[ (x[1], scrub_backtrace(x[2]::Vector{Union{Ptr{Nothing},Base.InterpreterIP}})) for x in stack ]
function scrub_exc_stack(stack, file_ts, file_t)
return Any[ (x[1], scrub_backtrace(x[2]::Vector{Union{Ptr{Nothing},Base.InterpreterIP}}, file_ts, file_t)) for x in stack ]
end

# define most of the test infrastructure without type specialization
Expand Down Expand Up @@ -185,7 +218,7 @@ struct Error <: Result

function Error(test_type::Symbol, orig_expr, value, bt, source::LineNumberNode)
if test_type === :test_error
bt = scrub_exc_stack(bt)
bt = scrub_exc_stack(bt, nothing, extract_file(source))
end
if test_type === :test_error || test_type === :nontest_error
bt_str = try # try the latest world for this, since we might have eval'd new code for show
Expand Down Expand Up @@ -1013,8 +1046,9 @@ mutable struct DefaultTestSet <: AbstractTestSet
time_start::Float64
time_end::Union{Float64,Nothing}
failfast::Bool
file::Union{String,Nothing}
end
function DefaultTestSet(desc::AbstractString; verbose::Bool = false, showtiming::Bool = true, failfast::Union{Nothing,Bool} = nothing)
function DefaultTestSet(desc::AbstractString; verbose::Bool = false, showtiming::Bool = true, failfast::Union{Nothing,Bool} = nothing, source = nothing)
if isnothing(failfast)
# pass failfast state into child testsets
parent_ts = get_testset()
Expand All @@ -1024,8 +1058,11 @@ function DefaultTestSet(desc::AbstractString; verbose::Bool = false, showtiming:
failfast = false
end
end
return DefaultTestSet(String(desc)::String, [], 0, false, verbose, showtiming, time(), nothing, failfast)
return DefaultTestSet(String(desc)::String, [], 0, false, verbose, showtiming, time(), nothing, failfast, extract_file(source))
end
extract_file(source::LineNumberNode) = extract_file(source.file)
extract_file(file::Symbol) = string(file)
extract_file(::Nothing) = nothing

struct FailFastError <: Exception end

Expand All @@ -1043,7 +1080,7 @@ function record(ts::DefaultTestSet, t::Union{Fail, Error}; print_result::Bool=TE
if !(t isa Error) || t.test_type !== :test_interrupted
print(t)
if !isa(t, Error) # if not gets printed in the show method
Base.show_backtrace(stdout, scrub_backtrace(backtrace()))
Base.show_backtrace(stdout, scrub_backtrace(backtrace(), ts.file, extract_file(t.source)))
end
println()
end
Expand Down Expand Up @@ -1489,7 +1526,11 @@ function testset_beginend_call(args, tests, source)
ex = quote
_check_testset($testsettype, $(QuoteNode(testsettype.args[1])))
local ret
local ts = $(testsettype)($desc; $options...)
local ts = if ($testsettype === $DefaultTestSet) && $(isa(source, LineNumberNode))
$(testsettype)($desc; source=$(QuoteNode(source.file)), $options...)
else
$(testsettype)($desc; $options...)
end
push_testset(ts)
# we reproduce the logic of guardseed, but this function
# cannot be used as it changes slightly the semantic of @testset,
Expand Down Expand Up @@ -1585,7 +1626,11 @@ function testset_forloop(args, testloop, source)
copy!(RNG, tmprng)

end
ts = $(testsettype)($desc; $options...)
ts = if ($testsettype === $DefaultTestSet) && $(isa(source, LineNumberNode))
$(testsettype)($desc; source=$(QuoteNode(source.file)), $options...)
else
$(testsettype)($desc; $options...)
end
push_testset(ts)
first_iteration = false
try
Expand Down
109 changes: 109 additions & 0 deletions stdlib/Test/test/runtests.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -722,6 +722,115 @@ end
rm(f; force=true)
end

@testset "provide informative location in backtrace for test failures" begin
win2unix(filename) = replace(filename, "\\" => '/')
utils = win2unix(tempname())
write(utils,
"""
function test_properties2(value)
@test isodd(value)
end
""")

included = win2unix(tempname())
write(included,
"""
@testset "Other tests" begin
@test 1 + 1 == 3
test_properties2(2)
end
test_properties2(8)
# Test calls to `@test` and `@testset` with no file/lineno information (__source__ == nothing).
eval(Expr(:macrocall, Symbol("@test"), nothing, :false))
eval(Expr(:macrocall, Symbol("@testset"), nothing, "Testset without source", quote
@test false
@test error("failed")
end))
""")

runtests = win2unix(tempname())
write(runtests,
"""
using Test
include("$utils")
function test_properties(value)
@test isodd(value)
end
@testset "Tests" begin
test_properties(8)
@noinline test_properties(8)
test_properties2(8)
include("$included")
end
""")
msg = read(pipeline(ignorestatus(`$(Base.julia_cmd()) --startup-file=no --color=no $runtests`), stderr=devnull), String)
msg = win2unix(msg)
regex = r"((?:Tests|Other tests|Testset without source): Test Failed (?:.|\n)*?)\n\nStacktrace:(?:.|\n)*?(?=\n(?:Tests|Other tests))"
failures = map(eachmatch(regex, msg)) do m
m = match(r"(Tests|Other tests|Testset without source): .*? at (.*?)\n Expression: (.*)(?:.|\n)*\n+Stacktrace:\n((?:.|\n)*)", m.match)
(; testset = m[1], source = m[2], ex = m[3], stacktrace = m[4])
end
@test length(failures) == 8 # 8 failed tests
@test count(contains("Error During Test"), split(msg, '\n')) == 1 # 1 error
test_properties_macro_source = runtests * ":6"
test_properties2_macro_source = utils * ":2"

fail = failures[1]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 6
@test fail.testset == "Tests" && fail.source == test_properties_macro_source && fail.ex == "isodd(value)"
@test count(contains(runtests * ":10"), lines) == 2 # @testset + test

fail = failures[2]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 6
@test fail.testset == "Tests" && fail.source == test_properties_macro_source && fail.ex == "isodd(value)"
@test count(contains(runtests * ":10"), lines) == 1 # @testset
@test count(contains(runtests * ":11"), lines) == 1 # test

fail = failures[3]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 6
@test fail.testset == "Tests" && fail.source == test_properties2_macro_source && fail.ex == "isodd(value)"
@test count(contains(runtests * ":10"), lines) == 1 # @testset
@test count(contains(runtests * ":12"), lines) == 1 # test

fail = failures[4]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 5
@test fail.testset == "Other tests" && fail.source == included * ":2" && fail.ex == "1 + 1 == 3"
@test count(contains(included * ":2"), lines) == 2 # @testset + test
@test count(contains(runtests * ":10"), lines) == 0 # @testset (stop at the innermost testset)

fail = failures[5]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 6
@test fail.testset == "Other tests" && fail.source == test_properties2_macro_source && fail.ex == "isodd(value)"
@test count(contains(included * ":2"), lines) == 1 # @testset
@test count(contains(included * ":3"), lines) == 1 # test
@test count(contains(runtests * ":10"), lines) == 0 # @testset (stop at the innermost testset)

fail = failures[6]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 8
@test fail.testset == "Tests" && fail.source == test_properties2_macro_source && fail.ex == "isodd(value)"
@test count(contains(runtests * ":10"), lines) == 1 # @testset
@test count(contains(runtests * ":14"), lines) == 1 # include
@test count(contains(included * ":5"), lines) == 1 # test

fail = failures[7]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 9
@test fail.testset == "Tests" && fail.source == "none:0" && fail.ex == "false"
@test count(contains(runtests * ":10"), lines) == 1 # @testset
@test count(contains(runtests * ":14"), lines) == 1 # include
@test count(contains(included * ":8"), lines) == 1 # test

fail = failures[8]; lines = split(fail.stacktrace, '\n')
@test length(lines)/2 ≤ 5
@test fail.testset == "Testset without source" && fail.source == included * ":10" && fail.ex == "false"
@test count(contains(included * ":10"), lines) == 2 # @testset + test
@test count(contains(runtests * ":10"), lines) == 0 # @testset (stop at the innermost testset)
end

let io = IOBuffer()
exc = Test.TestSetException(1,2,3,4,Vector{Union{Test.Error, Test.Fail}}())
Base.showerror(io, exc, backtrace())
Expand Down

0 comments on commit 5304baa

Please sign in to comment.