Skip to content

Put testset exceptions in the test record. #44

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Oct 15, 2025
Merged

Put testset exceptions in the test record. #44

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
87f190e
Put testset exceptions in the test record.
maleadt Oct 14, 2025
85c923f
Try to fix a race.
maleadt Oct 15, 2025
d98c8ef
Don't unnecessarily sleep.
maleadt Oct 15, 2025
4cf1055
Fix typo.
maleadt Oct 15, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
107 changes: 69 additions & 38 deletions src/ParallelTestRunner.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,8 +68,10 @@ end
abstract type AbstractTestRecord end

struct TestRecord <: AbstractTestRecord
test::Any
output::String
value::Any # AbstractTestSet or TestSetException
output::String # captured stdout/stderr

# stats
time::Float64
bytes::UInt64
gctime::Float64
Expand Down Expand Up @@ -165,7 +167,7 @@ function print_test_finished(record::TestRecord, wrkr, test, ctx::TestIOContext)
end
end

function print_test_errorred(::Type{TestRecord}, wrkr, test, ctx::TestIOContext, test_time)
function print_test_failed(record::TestRecord, wrkr, test, ctx::TestIOContext)
lock(ctx.lock)
try
printstyled(ctx.stderr, test, color = :red)
Expand All @@ -174,7 +176,7 @@ function print_test_errorred(::Type{TestRecord}, wrkr, test, ctx::TestIOContext,
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |"
, color = :red
)
time_str = @sprintf("%7.2f", test_time)
time_str = @sprintf("%7.2f", record.time)
printstyled(ctx.stderr, lpad(time_str, ctx.elapsed_align + 1, " "), " │", color = :red)

failed_str = "failed at $(now())\n"
Expand All @@ -183,6 +185,24 @@ function print_test_errorred(::Type{TestRecord}, wrkr, test, ctx::TestIOContext,
failed_str = lpad(failed_str, fail_align, " ")
printstyled(ctx.stderr, failed_str, color = :red)

# TODO: print other stats?

flush(ctx.stderr)
finally
unlock(ctx.lock)
end
end

function print_test_crashed(::Type{TestRecord}, wrkr, test, ctx::TestIOContext)
lock(ctx.lock)
try
printstyled(ctx.stderr, test, color = :red)
printstyled(
ctx.stderr,
lpad("($wrkr)", ctx.name_align - textwidth(test) + 1, " "), " |",
" "^ctx.elapsed_align, " crashed at $(now())\n", color = :red
Comment on lines +196 to +203
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could this still print the time? It's sometimes helpful to know how long it takes to crash

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Crashes are highly unlikely, since we now catch every exception worker-side, so I rather wanted to keep the reporting logic as simple as possible. Besides, the testset right below will always report the time it took, even without --verbose:

               │          │ ──────────────── CPU ──────────────── │
Test  (Worker) │ Time (s) │ GC (s) │ GC % │ Alloc (MB) │ RSS (MB) │
basic      (2) |         crashed at 2025-10-15T08:32:27.239

Test Summary: | Error  Total  Time
  Overall     |     1      1  5.6s
    basic     |     1      1  3.8s
    FAILURE

)

flush(ctx.stderr)
finally
unlock(ctx.lock)
Expand All @@ -209,8 +229,15 @@ function runtest(::Type{TestRecord}, f, name, init_code, color)

mktemp() do path, io
stats = redirect_stdio(stdout=io, stderr=io) do
@timed @testset $name begin
$f
@timed try
@testset $name begin
$f
end
catch err
isa(err, Test.TestSetException) || rethrow()

# return the error to package it into a TestRecord
err
end
end
close(io)
Expand Down Expand Up @@ -665,13 +692,13 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
# Message types for the printer channel
# (:started, test_name, worker_id)
# (:finished, test_name, worker_id, record)
# (:errored, test_name, worker_id, test_time)
# (:crashed, test_name, worker_id, test_time)
printer_channel = Channel{Tuple}(100)

printer_task = @async begin
last_status_update = Ref(time())
try
while isopen(printer_channel)
while isopen(printer_channel) || isready(printer_channel)
got_message = false
while isready(printer_channel)
# Try to get a message from the channel (with timeout)
Expand All @@ -692,13 +719,17 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
test_name, wrkr, record = msg[2], msg[3], msg[4]

clear_status()
print_test_finished(record, wrkr, test_name, io_ctx)
if record.value isa Exception
print_test_failed(record, wrkr, test_name, io_ctx)
else
print_test_finished(record, wrkr, test_name, io_ctx)
end

elseif msg_type == :errored
test_name, wrkr, test_time = msg[2], msg[3], msg[4]
elseif msg_type == :crashed
test_name, wrkr = msg[2], msg[3]

clear_status()
print_test_errorred(RecordType, wrkr, test_name, io_ctx, test_time)
print_test_crashed(RecordType, wrkr, test_name, io_ctx)
end
end

Expand All @@ -707,7 +738,8 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
update_status()
last_status_update[] = time()
end
sleep(0.1)

isopen(printer_channel) && sleep(0.1)
end
catch ex
if isa(ex, InterruptException)
Expand Down Expand Up @@ -766,16 +798,15 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
break
end

# return any other exception as the result
# XXX: also put this in a test record?
ex
end
test_t1 = time()
push!(results, (test, result, test_t0, test_t1))

# act on the results
if result isa AbstractTestRecord
put!(printer_channel, (:finished, test, wrkr, result::RecordType))
@assert result isa RecordType
put!(printer_channel, (:finished, test, wrkr, result))

if memory_usage(result) > max_worker_rss
# the worker has reached the max-rss limit, recycle it
Expand All @@ -784,13 +815,12 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
end
else
@assert result isa Exception
put!(printer_channel, (:errored, test, wrkr, test_t1-test_t0))
put!(printer_channel, (:crashed, test, wrkr))
if do_quickfail
stop_work()
end

# the worker encountered some failure, recycle it
# so future tests get a fresh environment
# the worker encountered some serious failure, recycle it
p = recycle_worker(p)
end

Expand Down Expand Up @@ -903,32 +933,33 @@ function runtests(mod::Module, ARGS; test_filter = Returns(true), RecordType = T
push!(completed_tests, testname)

# decode or fake a testset
if isa(result, AbstractTestRecord)
testset = result.test
historical_durations[testname] = stop - start
else
testset = create_testset(testname; start, stop)
if isa(result, RemoteException) &&
isa(result.captured.ex, Test.TestSetException)
for i in 1:result.captured.ex.pass
if result isa AbstractTestRecord
if result.value isa Test.AbstractTestSet
testset = result.value
historical_durations[testname] = stop - start
else
# TODO: improve the Test stdlib to keep track of the exact failure
# instead of flattening into an exception without provenance
@assert result.value isa Test.TestSetException
testset = create_testset(testname; start, stop)
for i in 1:result.value.pass
Test.record(testset, Test.Pass(:test, nothing, nothing, nothing, LineNumberNode(@__LINE__, @__FILE__)))
end
for i in 1:result.captured.ex.broken
for i in 1:result.value.broken
Test.record(testset, Test.Broken(:test, nothing))
end
for t in result.captured.ex.errors_and_fails
for t in result.value.errors_and_fails
Test.record(testset, t)
end
else
if !isa(result, Exception)
result = ErrorException(string("Unknown result type : ", typeof(result)))
end
# If this test raised an exception that is not a remote testset exception,
# i.e. not a RemoteException capturing a TestSetException that means
# the test runner itself had some problem, so we may have hit a segfault,
# deserialization errors or something similar. Record this testset as Errored.
Test.record(testset, Test.Error(:nontest_error, testname, nothing, Base.ExceptionStack(NamedTuple[(;exception = result, backtrace = [])]), LineNumberNode(1)))
end
else
# If this test raised an exception that is not a remote testset
# exception, that means the test runner itself had some problem, so we
# may have hit a segfault, deserialization errors or something similar.
# Record this testset as Errored.
@assert result isa Exception
testset = create_testset(testname; start, stop)
Test.record(testset, Test.Error(:nontest_error, testname, nothing, Base.ExceptionStack(NamedTuple[(;exception = result, backtrace = [])]), LineNumberNode(1)))
end

with_testset(testset) do
Expand Down
9 changes: 6 additions & 3 deletions test/runtests.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -121,21 +121,24 @@ end

@testset "crashing test" begin
custom_tests = Dict(
"crash" => quote
"abort" => quote
abort() = ccall(:abort, Nothing, ())
abort()
end
)

println("NOTE: The next test is expected to crash a worker process, which may print some output to the terminal.")
print("""NOTE: The next test is expected to crash a worker process,
which may print some output to the terminal.
""")
io = IOBuffer()
@test_throws Test.FallbackTestSetException("Test run finished with errors") begin
runtests(ParallelTestRunner, ["--verbose"]; custom_tests, stdout=io, stderr=io)
end
println()

str = String(take!(io))
@test contains(str, r"crash .+ started at")
@test contains(str, r"abort .+ started at")
@test contains(str, r"abort .+ crashed at")
@test contains(str, "FAILURE")
@test contains(str, "Error During Test")
@test contains(str, "ProcessExitedException")
Expand Down