diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index 9728974..75b27ea 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -17,9 +17,9 @@ jobs: fail-fast: false matrix: version: - - '1.8' - '1.10' - '1.12' + - '1.13' os: - ubuntu-latest - macOS-latest @@ -34,8 +34,6 @@ jobs: arch: x86 - os: windows-latest arch: x64 - - os: windows-latest - version: '1.8' steps: - uses: actions/checkout@v4 - uses: julia-actions/setup-julia@v2 diff --git a/Project.toml b/Project.toml index 0953b1a..8f41086 100644 --- a/Project.toml +++ b/Project.toml @@ -1,6 +1,6 @@ name = "ReTestItems" uuid = "817f1d60-ba6b-4fd5-9520-3cf149f6a823" -version = "1.35.2" +version = "1.35.3" [deps] Dates = "ade2ca70-3891-5945-98fb-dc099432e06a" diff --git a/src/ReTestItems.jl b/src/ReTestItems.jl index 1994295..637a6bc 100644 --- a/src/ReTestItems.jl +++ b/src/ReTestItems.jl @@ -56,6 +56,52 @@ else # @testset does not yet support `failfast` CompatDefaultTestSet(a...; failfast::Bool=false, kw...) = DefaultTestSet(a...; kw...) end +# TESTSET_PRINT_ENABLE is process-wide mutable configuration on Julia <= 1.12. +# It became dynamically scoped configuration on Julia 1.13. +function _with_testset_print_enabled(f, enabled::Bool) + print_enabled = Test.TESTSET_PRINT_ENABLE + if print_enabled isa Base.RefValue + previous = print_enabled[] + print_enabled[] = enabled + try + return f() + finally + print_enabled[] = previous + end + else + return Base.ScopedValues.with(f, print_enabled => enabled) + end +end + +function _with_testset(f, testset::Test.AbstractTestSet) + # Test tracked the current test set stack in task-local storage on Julia <= 1.12. + # It moved the current test set and depth to ScopedValues in Julia 1.13. + if isdefined(Test, :CURRENT_TESTSET) + return Base.ScopedValues.with( + f, + Test.CURRENT_TESTSET => testset, + Test.TESTSET_DEPTH => Test.get_testset_depth() + 1, + ) + end + Test.push_testset(testset) + try + return f() + finally + popped = Test.pop_testset() + @assert popped === testset + end +end + +function _set_testset_time_end!(testset::DefaultTestSet, time_end::Float64) + # Each finished test set has one end time. The field became atomic in Julia 1.13. + if isdefined(Test, :CURRENT_TESTSET) + @atomic testset.time_end = time_end + else + testset.time_end = time_end + end + return testset +end + struct NoTestException <: Exception msg::String end @@ -431,39 +477,40 @@ function _runtests_in_current_env( if nworkers == 0 length(cfg.worker_init_expr.args) > 0 && error("worker_init_expr is set, but will not run because number of workers is 0.") # This is where we disable printing for the serial executor case. - Test.TESTSET_PRINT_ENABLE[] = false - ctx = TestContext(proj_name, ntestitems) - # we use a single TestSetupModules - ctx.setups_evaled = TestSetupModules() - for (i, testitem) in enumerate(testitems.testitems) - testitem.workerid[] = Libc.getpid() - testitem.eval_number[] = i - @atomic :monotonic testitems.count += 1 - run_number = 1 - max_runs = 1 + max(cfg.retries, testitem.retries) - is_non_pass = false - while run_number ≤ max_runs - res = runtestitem(testitem, ctx; cfg.test_end_expr, cfg.verbose_results, cfg.logs, failfast=cfg.testitem_failfast) - ts = res.testset - print_errors_and_captured_logs(testitem, run_number; cfg.logs) - report_empty_testsets(testitem, ts) - if cfg.gc_between_testitems - @debugv 2 "Running GC" - GC.gc(true) + _with_testset_print_enabled(false) do + ctx = TestContext(proj_name, ntestitems) + # we use a single TestSetupModules + ctx.setups_evaled = TestSetupModules() + for (i, testitem) in enumerate(testitems.testitems) + testitem.workerid[] = Libc.getpid() + testitem.eval_number[] = i + @atomic :monotonic testitems.count += 1 + run_number = 1 + max_runs = 1 + max(cfg.retries, testitem.retries) + is_non_pass = false + while run_number ≤ max_runs + res = runtestitem(testitem, ctx; cfg.test_end_expr, cfg.verbose_results, cfg.logs, failfast=cfg.testitem_failfast) + ts = res.testset + print_errors_and_captured_logs(testitem, run_number; cfg.logs) + report_empty_testsets(testitem, ts) + if cfg.gc_between_testitems + @debugv 2 "Running GC" + GC.gc(true) + end + testitem.is_non_pass[] = is_non_pass = any_non_pass(ts) + if is_non_pass && run_number != max_runs + run_number += 1 + @info "Retrying $(repr(testitem.name)). Run=$run_number." + else + break + end end - testitem.is_non_pass[] = is_non_pass = any_non_pass(ts) - if is_non_pass && run_number != max_runs - run_number += 1 - @info "Retrying $(repr(testitem.name)). Run=$run_number." - else + if cfg.failfast && is_non_pass + cancel!(testitems) + print_failfast_cancellation(testitem) break end end - if cfg.failfast && is_non_pass - cancel!(testitems) - print_failfast_cancellation(testitem) - break - end end elseif !isempty(testitems.testitems) # Try to free up memory on the coordinator before starting workers, since @@ -496,7 +543,6 @@ function _runtests_in_current_env( end end end - Test.TESTSET_PRINT_ENABLE[] = true # reenable printing so our `finish` prints # Let users know if tests are done, and if all of them ran (or if we failed fast). # Print this above the final report as there might have been other logs printed # since a failfast-cancellation was printed, but print it ASAP after tests finish @@ -505,9 +551,10 @@ function _runtests_in_current_env( record_results!(testitems) cfg.report && write_junit_file(proj_name, dirname(projectfile), testitems.graph.junit) @debugv 1 "Calling Test.finish(testitems)" - Test.finish(testitems) # print summary of total passes/failures/errors + _with_testset_print_enabled(true) do + Test.finish(testitems) # print summary of total passes/failures/errors + end finally - Test.TESTSET_PRINT_ENABLE[] = true @debugv 1 "Cleaning up test setup logs" foreach(Iterators.filter(endswith(".log"), readdir(RETESTITEMS_TEMP_FOLDER[], join=true))) do logfile try @@ -533,7 +580,6 @@ function start_worker(proj_name, nworker_threads::String, worker_init_expr::Expr remote_fetch(w, quote Base.set_active_project($proj) using ReTestItems, Test - Test.TESTSET_PRINT_ENABLE[] = false const GLOBAL_TEST_CONTEXT = ReTestItems.TestContext($proj_name, $ntestitems) GLOBAL_TEST_CONTEXT.setups_evaled = ReTestItems.TestSetupModules() nthreads_str = $nworker_threads @@ -610,21 +656,21 @@ function record_worker_terminated!(testitem, worker::Worker, run_number::Int) end function record_test_error!(testitem, msg, elapsed_seconds::Real=0.0) - Test.TESTSET_PRINT_ENABLE[] = false ts = DefaultTestSet(testitem.name) err = ErrorException(msg) Test.record(ts, Test.Error(:nontest_error, Test.Expr(:tuple), err, Base.ExceptionStack([(exception=err, backtrace=Union{Ptr{Nothing}, Base.InterpreterIP}[])]), LineNumberNode(testitem.line, testitem.file))) - try - Test.finish(ts) - catch e2 - e2 isa TestSetException || rethrow() + _with_testset_print_enabled(false) do + try + Test.finish(ts) + catch e2 + e2 isa TestSetException || rethrow() + end end # Since we're manually constructing a TestSet here to report tests that already ran and # were killed, we need to manually set how long those tests were running (if known). - ts.time_end = ts.time_start + elapsed_seconds - Test.TESTSET_PRINT_ENABLE[] = true + _set_testset_time_end!(ts, ts.time_start + elapsed_seconds) push!(testitem.testsets, ts) push!(testitem.stats, PerfStats()) # No data since testitem didn't complete return testitem @@ -1101,7 +1147,6 @@ function runtestitem( push!(test_end_body.args, :(using $(Symbol(ctx.projectname)))) end end - Test.push_testset(ts) # This allows us to identify if the code is running inside a `@testitem`, which is # useful for e.g. macros that behave differently conditional on being in a `@testitem`. # This was added so we could have a `@test_foo` macro exapnd to a `@testset` if already @@ -1109,56 +1154,58 @@ function runtestitem( prev = get(task_local_storage(), :__TESTITEM_ACTIVE__, false) task_local_storage()[:__TESTITEM_ACTIVE__] = true try - for setup in ti.setups - # TODO(nhd): Consider implementing some affinity to setups, so that we can - # prefer to send testitems to the workers that have already eval'd setups. - # Or maybe allow user-configurable grouping of test items by worker? - # Or group them by file by default? - - # ensure setup has been evaled before - @debugv 1 "Ensuring setup for test item $(repr(name)) $(setup)$(_on_worker())." - ts_mod = ensure_setup!(ctx, setup, ti.testsetups, logs) - # eval using in our @testitem module - @debugv 1 "Importing setup for test item $(repr(name)) $(setup)$(_on_worker())." - # We look up the testsetups from Main (since tests are eval'd in their own - # temporary anonymous module environment.) - push!(body.args, Expr(:using, Expr(:., :Main, ts_mod))) - # ts_mod is a gensym'd name so that setup modules don't clash - # so we set a const alias inside our @testitem module to make things work - push!(body.args, :(const $setup = $ts_mod)) - end - @debugv 1 "Setup for test item $(repr(name)) done$(_on_worker())." - - # add our `@testitem` quoted code to module body expr - append!(body.args, ti.code.args) - mod_expr = :(module $(gensym(name)) end) - softscope_all!(body) - mod_expr.args[3] = body - - # add the `test_end_expr` to a module to be run after the test item - append!(test_end_body.args, test_end_expr.args) - softscope_all!(test_end_body) - test_end_mod_expr = :(module $(gensym(name * " test_end")) end) - test_end_mod_expr.args[3] = test_end_body - - # eval the testitem into a temporary module, so that all results can be GC'd - # once the test is done and sent over the wire. (However, note that anonymous modules - # aren't always GC'd right now: https://github.com/JuliaLang/julia/issues/48711) - # disabled for now since there were issues when tests tried serialize/deserialize - # with things defined in an anonymous module - # environment = Module() - @debugv 1 "Running test item $(repr(name))$(_on_worker())." - _, stats = @timed_with_compilation _redirect_logs(logs == :eager ? DEFAULT_STDOUT[] : logpath(ti)) do - # Always run the test_end_mod_expr, even if the test item fails / throws - try - with_source_path(() -> Core.eval(Main, mod_expr), ti.file) - finally - has_test_end_expr && @debugv 1 "Running test_end_expr for test item $(repr(name))$(_on_worker())." - with_source_path(() -> Core.eval(Main, test_end_mod_expr), ti.file) + _with_testset(ts) do + for setup in ti.setups + # TODO(nhd): Consider implementing some affinity to setups, so that we can + # prefer to send testitems to the workers that have already eval'd setups. + # Or maybe allow user-configurable grouping of test items by worker? + # Or group them by file by default? + + # ensure setup has been evaled before + @debugv 1 "Ensuring setup for test item $(repr(name)) $(setup)$(_on_worker())." + ts_mod = ensure_setup!(ctx, setup, ti.testsetups, logs) + # eval using in our @testitem module + @debugv 1 "Importing setup for test item $(repr(name)) $(setup)$(_on_worker())." + # We look up the testsetups from Main (since tests are eval'd in their own + # temporary anonymous module environment.) + push!(body.args, Expr(:using, Expr(:., :Main, ts_mod))) + # ts_mod is a gensym'd name so that setup modules don't clash + # so we set a const alias inside our @testitem module to make things work + push!(body.args, :(const $setup = $ts_mod)) + end + @debugv 1 "Setup for test item $(repr(name)) done$(_on_worker())." + + # add our `@testitem` quoted code to module body expr + append!(body.args, ti.code.args) + mod_expr = :(module $(gensym(name)) end) + softscope_all!(body) + mod_expr.args[3] = body + + # add the `test_end_expr` to a module to be run after the test item + append!(test_end_body.args, test_end_expr.args) + softscope_all!(test_end_body) + test_end_mod_expr = :(module $(gensym(name * " test_end")) end) + test_end_mod_expr.args[3] = test_end_body + + # eval the testitem into a temporary module, so that all results can be GC'd + # once the test is done and sent over the wire. (However, note that anonymous modules + # aren't always GC'd right now: https://github.com/JuliaLang/julia/issues/48711) + # disabled for now since there were issues when tests tried serialize/deserialize + # with things defined in an anonymous module + # environment = Module() + @debugv 1 "Running test item $(repr(name))$(_on_worker())." + _, stats = @timed_with_compilation _redirect_logs(logs == :eager ? DEFAULT_STDOUT[] : logpath(ti)) do + # Always run the test_end_mod_expr, even if the test item fails / throws + try + with_source_path(() -> Core.eval(Main, mod_expr), ti.file) + finally + has_test_end_expr && @debugv 1 "Running test_end_expr for test item $(repr(name))$(_on_worker())." + with_source_path(() -> Core.eval(Main, test_end_mod_expr), ti.file) + end + nothing # return nothing as the first return value of @timed_with_compilation end - nothing # return nothing as the first return value of @timed_with_compilation + @debugv 1 "Done running test item $(repr(name))$(_on_worker())." end - @debugv 1 "Done running test item $(repr(name))$(_on_worker())." catch err err isa InterruptException && rethrow() # Handle exceptions thrown outside a `@test` in the body of the @testitem: @@ -1184,9 +1231,7 @@ function runtestitem( finally # Make sure all test setup logs are commited to file foreach(ts->isassigned(ts.logstore) && flush(ts.logstore[]), ti.testsetups) - ts1 = Test.pop_testset() task_local_storage()[:__TESTITEM_ACTIVE__] = prev - @assert ts1 === ts if finish_test if catch_test_error try diff --git a/src/junit_xml.jl b/src/junit_xml.jl index 1f0e560..88d770c 100644 --- a/src/junit_xml.jl +++ b/src/junit_xml.jl @@ -19,7 +19,10 @@ JUnitCounts() = JUnitCounts(nothing, 0.0, 0, 0, 0, 0) function JUnitCounts(ts::Test.DefaultTestSet) timestamp = unix2datetime(ts.time_start) - time = isnothing(ts.time_end) ? 0.0 : (ts.time_end - ts.time_start) + # Before Test.finish, time_end is nothing through Julia 1.12 and 0.0 on 1.13. + # JUnit durations are nonnegative, so unfinished or inconsistent times become zero. + time_end = ts.time_end + time = isnothing(time_end) ? 0.0 : max(0.0, time_end - ts.time_start) (; tests, failures, errors, skipped) = test_counts(ts) return JUnitCounts(timestamp, time, tests, failures, errors, skipped) end diff --git a/src/workers.jl b/src/workers.jl index 458a549..e7cf934 100644 --- a/src/workers.jl +++ b/src/workers.jl @@ -186,7 +186,7 @@ function Worker(; # end copied from Distributed.launch ## start the worker process color = get(worker_redirect_io, :color, false) ? "yes" : "no" # respect color of target io - cmd = `$(Base.julia_cmd()) $exeflags --startup-file=no --color=$color -e 'using ReTestItems; ReTestItems.Workers.startworker()'` + cmd = `$(Base.julia_cmd()) $exeflags --startup-file=no --color=$color -e 'using ReTestItems; ReTestItems._with_testset_print_enabled(false) do; ReTestItems.Workers.startworker(); end'` proc = open(detach(setenv(addenv(cmd, env), dir=dir)), "r+") pid = Libc.getpid(proc) diff --git a/test/integrationtests.jl b/test/integrationtests.jl index a5ff91e..310afe3 100644 --- a/test/integrationtests.jl +++ b/test/integrationtests.jl @@ -588,40 +588,41 @@ end runtests(path; nworkers=1) end end + output = replace(c.output, r" on worker \d+" => "", r"\e\[\d+m~?" => "") if Base.Sys.iswindows() @test occursin( - "\e[36m\e[1mCaptured logs\e[22m\e[39m for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at", - replace(c.output, r" on worker \d+" => "") + "Captured logs for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at", + output, ) else @test occursin(""" - \e[36m\e[1mCaptured logs\e[22m\e[39m for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at \e[39m\e[1m$(path):1\e[22m + Captured logs for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at $(path):1 SetupThatErrors msg """, - replace(c.output, r" on worker \d+" => "")) + output) @test occursin(""" - \e[36m\e[1mCaptured logs\e[22m\e[39m for test setup \"SetupThatErrors\" (dependency of \"bad setup, bad test\") at \e[39m\e[1m$(path):1\e[22m + Captured logs for test setup \"SetupThatErrors\" (dependency of \"bad setup, bad test\") at $(path):1 SetupThatErrors msg """, - replace(c.output, r" on worker \d+" => "")) + output) # Since the test setup never succeeds it will be run mutliple times. Here we test # that we don't accumulate logs from all previous failed attempts (which would get # really spammy if the test setup is used by 100 test items). @test !occursin(""" - \e[36m\e[1mCaptured logs\e[22m\e[39m for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at \e[39m\e[1m$(path):1\e[22m + Captured logs for test setup \"SetupThatErrors\" (dependency of \"bad setup, good test\") at $(path):1 SetupThatErrors msg SetupThatErrors msg """, - replace(c.output, r" on worker \d+" => "") + output, ) @test !occursin(""" - \e[36m\e[1mCaptured logs\e[22m\e[39m for test setup \"SetupThatErrors\" (dependency of \"bad setup, bad test\") at \e[39m\e[1m$(path):1\e[22m + Captured logs for test setup \"SetupThatErrors\" (dependency of \"bad setup, bad test\") at $(path):1 SetupThatErrors msg SetupThatErrors msg """, - replace(c.output, r" on worker \d+" => "") + output, ) end # iswindows end diff --git a/test/internals.jl b/test/internals.jl index aea8e56..794bae1 100644 --- a/test/internals.jl +++ b/test/internals.jl @@ -4,6 +4,24 @@ using ReTestItems @testset "internals.jl" verbose=true begin +@testset "_with_testset_print_enabled" begin + using ReTestItems: _with_testset_print_enabled + + initial = Test.TESTSET_PRINT_ENABLE[] + for enabled in (false, true) + @test _with_testset_print_enabled(enabled) do + Test.TESTSET_PRINT_ENABLE[] + end == enabled + @test Test.TESTSET_PRINT_ENABLE[] == initial + end + + @test_throws ErrorException _with_testset_print_enabled(false) do + @test !Test.TESTSET_PRINT_ENABLE[] + error("test exception") + end + @test Test.TESTSET_PRINT_ENABLE[] == initial +end + @testset "get_starting_testitems" begin using ReTestItems: get_starting_testitems, TestItems, @testitem graph = ReTestItems.FileNode("") # we don't use the graph info for this test @@ -207,7 +225,7 @@ end # `include_testfiles!` testset end ts = DefaultTestSet("Testset containing a passing test") - ts.n_passed = 1 + Test.record(ts, Test.Pass(:test, nothing, nothing, nothing)) @test_nowarn report_empty_testsets(ti, ts) ts = DefaultTestSet("Testset containing a failed test") diff --git a/test/junit_xml.jl b/test/junit_xml.jl index a82a105..9dee5a8 100644 --- a/test/junit_xml.jl +++ b/test/junit_xml.jl @@ -16,11 +16,14 @@ using DeepDiffs: deepdiff function remove_variables(str) return replace(str, # Replace timestamps and times with "0" - r" timestamp=\\\"[0-9-T:.]*\\\"" => " timestamp=\"0\"", - r" time=\\\"[0-9]*.[0-9]*\\\"" => " time=\"0\"", + r" timestamp=\\\"[^\\\"]*\\\"" => " timestamp=\"0\"", + r" time=\\\"[^\\\"]*\\\"" => " time=\"0\"", # Replace tag `value` in a with "0" # e.g. "" - r" value=\"[-]?[\d]*[.]?[\d]*?[e]?[-]?[\d]?\"(?=>)" => " value=\"0\"", + r"()" => s"\g<1>0\g<2>", + # Rendered values for failed expressions are version specific. Julia 1.13 + # omits them when displaying comparisons between literal values. + r"\n *Evaluated:[^\n]*" => "", # Omit stacktrace info between "Stacktrace" and the line containing "". # Stacktraces are version specific. r" Stacktrace:[\s\S]*(?=\n\s* " Stacktrace:\n [omitted]", @@ -195,6 +198,16 @@ end end end +@testset "JUnitCounts produces nonnegative durations" begin + using ReTestItems: JUnitCounts + + ts = Test.DefaultTestSet("unfinished") + @test JUnitCounts(ts).time == 0.0 + + ReTestItems._set_testset_time_end!(ts, ts.time_start - 1.0) + @test JUnitCounts(ts).time == 0.0 +end + @testset "JUnit properties / DataDog tags" begin # The reference tests ensure the properties are written as we expect, # BUT they can't test the values (since they will differ between runs) @@ -224,15 +237,25 @@ end using Dates: datetime2unix, DateTime function get_test_suite(suite_name, test_name) - ts = @testset "$test_name" begin - @test true - @testset "inner" begin + time_start = datetime2unix(DateTime(2023, 01, 15, 16, 42)) + ts = if isdefined(Test, :CURRENT_TESTSET) + @testset "$test_name" time_start=time_start begin + @test true + @testset "inner" begin + @test true + end + end + else + @testset "$test_name" begin @test true + @testset "inner" begin + @test true + end end end # Make the test time deterministic to make testing report output easier - ts.time_start = datetime2unix(DateTime(2023, 01, 15, 16, 42)) - ts.time_end = datetime2unix(DateTime(2023, 01, 15, 16, 42, 30)) + isdefined(Test, :CURRENT_TESTSET) || (ts.time_start = time_start) + ReTestItems._set_testset_time_end!(ts, datetime2unix(DateTime(2023, 01, 15, 16, 42, 30))) # should be able to construct a TestCase from a TestSet tc = JUnitTestCase(ts) @@ -276,13 +299,21 @@ end using Dates: datetime2unix, DateTime function get_test_suite(suite_name, test_name) - ts = @testset "$test_name" begin - # would rather make this false, but failing @test makes the ReTestItems test fail as well - @test true + time_start = datetime2unix(DateTime(2023, 01, 15, 16, 42)) + ts = if isdefined(Test, :CURRENT_TESTSET) + @testset "$test_name" time_start=time_start begin + # would rather make this false, but failing @test makes the ReTestItems test fail as well + @test true + end + else + @testset "$test_name" begin + # would rather make this false, but failing @test makes the ReTestItems test fail as well + @test true + end end # Make the test time deterministic to make testing report output easier - ts.time_start = datetime2unix(DateTime(2023, 01, 15, 16, 42)) - ts.time_end = datetime2unix(DateTime(2023, 01, 15, 16, 42, 30)) + isdefined(Test, :CURRENT_TESTSET) || (ts.time_start = time_start) + ReTestItems._set_testset_time_end!(ts, datetime2unix(DateTime(2023, 01, 15, 16, 42, 30))) # should be able to construct a TestCase from a TestSet tc = JUnitTestCase(ts) diff --git a/test/macros.jl b/test/macros.jl index 08fac93..fe863a4 100644 --- a/test/macros.jl +++ b/test/macros.jl @@ -165,6 +165,13 @@ end using IOCapture # run `testset_func` as if not already inside a testset, so it prints results immediately. function toplevel_testset(testset_func) + if isdefined(Test, :CURRENT_TESTSET) + return Base.ScopedValues.with( + testset_func, + Test.CURRENT_TESTSET => Test.FallbackTestSet(), + Test.TESTSET_DEPTH => 0, + ) + end old = get(task_local_storage(), :__BASETESTNEXT__, nothing) try if old !== nothing