From 95e132ec10fff6f9564c265390849b56183d8b70 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Tue, 2 Sep 2025 15:30:24 -0400 Subject: [PATCH] Test: Expand verbose mode --- NEWS.md | 3 ++ stdlib/Test/docs/src/index.md | 33 ++++++++++++++++++++ stdlib/Test/src/Test.jl | 56 ++++++++++++++++++++++++++++++++-- stdlib/Test/test/runtests.jl | 57 +++++++++++++++++++++++++++++++++++ 4 files changed, 147 insertions(+), 2 deletions(-) diff --git a/NEWS.md b/NEWS.md index a925f8700531b..90422772f8021 100644 --- a/NEWS.md +++ b/NEWS.md @@ -48,6 +48,9 @@ New library functions --------------------- * `ispositive(::Real)` and `isnegative(::Real)` are provided for performance and convenience ([#53677]). +* The `Test` module now supports the `JULIA_TEST_VERBOSE` environment variable. When set to `true`, + it enables verbose testset entry/exit messages with timing information and sets the default `verbose=true` + for `DefaultTestSet` to show detailed hierarchical test summaries ([#59295]). * Exporting function `fieldindex` to get the index of a struct's field ([#58119]). * `Base.donotdelete` is now public. It prevents deadcode elemination of its arguments ([#55774]). * `Sys.sysimage_target()` returns the CPU target string used to build the current system image ([#58970]). diff --git a/stdlib/Test/docs/src/index.md b/stdlib/Test/docs/src/index.md index ab06531152554..893efeaccbade 100644 --- a/stdlib/Test/docs/src/index.md +++ b/stdlib/Test/docs/src/index.md @@ -177,6 +177,39 @@ Foo Tests | 8 8 0.0s Arrays 3 | 2 2 0.0s ``` +### Environment Variable Support + +The `Test` module supports the `JULIA_TEST_VERBOSE` environment variable for controlling +verbose behavior globally: + +- When `JULIA_TEST_VERBOSE=true`, testsets will automatically use `verbose=true` by default, + and additionally print "Starting testset" and "Finished testset" messages with timing + information as testsets are entered and exited. +- When `JULIA_TEST_VERBOSE=false` or unset, testsets use `verbose=false` by default and + no entry/exit messages are printed. + +This environment variable provides a convenient way to enable comprehensive verbose output +for debugging test suites without modifying the test code itself. + +```julia +$ JULIA_TEST_VERBOSE=true julia -e ' +using Test +@testset "Example" begin + @test 1 + 1 == 2 + @testset "Nested" begin + @test 2 * 2 == 4 + end +end' + +Starting testset: Example + Starting testset: Nested + Finished testset: Nested (0.0s) +Finished testset: Example (0.0s) +Test Summary: | Pass Total Time +Example | 2 2 0.0s + Nested | 1 1 0.0s +``` + If we do have a test failure, only the details for the failed test sets will be shown: ```julia-repl; filter = r"[0-9\.]+s" diff --git a/stdlib/Test/src/Test.jl b/stdlib/Test/src/Test.jl index 25a8a82df57ae..a80efe6f95563 100644 --- a/stdlib/Test/src/Test.jl +++ b/stdlib/Test/src/Test.jl @@ -10,6 +10,13 @@ All tests belong to a *test set*. There is a default, task-level test set that throws on the first failure. Users can choose to wrap their tests in (possibly nested) test sets that will store results and summarize them at the end of the test set with `@testset`. + +Environment variables: + +* `JULIA_TEST_VERBOSE`: Set to `true` to enable verbose test output, including + testset entry/exit messages and detailed hierarchical test summaries. +* `JULIA_TEST_FAILFAST`: Set to `true` to stop testing on the first failure. +* `JULIA_TEST_RECORD_PASSES`: Set to `true` to record passed tests (for debugging). """ module Test @@ -1226,7 +1233,7 @@ mutable struct DefaultTestSet <: AbstractTestSet results_lock::ReentrantLock results::Vector{Any} end -function DefaultTestSet(desc::AbstractString; verbose::Bool = false, showtiming::Bool = true, failfast::Union{Nothing,Bool} = nothing, source = nothing, rng = nothing) +function DefaultTestSet(desc::AbstractString; verbose::Bool = something(Base.ScopedValues.get(VERBOSE_TESTSETS)), showtiming::Bool = true, failfast::Union{Nothing,Bool} = nothing, source = nothing, rng = nothing) if isnothing(failfast) # pass failfast state into child testsets parent_ts = get_testset() @@ -2103,9 +2110,19 @@ const TESTSET_PRINT_ENABLE = ScopedValue{Bool}(true) const TEST_RECORD_PASSES = LazyScopedValue{Bool}(OncePerProcess{Bool}() do return Base.get_bool_env("JULIA_TEST_RECORD_PASSES", false) end) +const VERBOSE_TESTSETS = LazyScopedValue{Bool}(OncePerProcess{Bool}() do + return Base.get_bool_env("JULIA_TEST_VERBOSE", false) +end) macro with_testset(ts, expr) - :(@with(CURRENT_TESTSET => $(esc(ts)), TESTSET_DEPTH => get_testset_depth() + 1, $(esc(expr)))) + quote + print_testset_verbose(:enter, $(esc(ts))) + try + @with(CURRENT_TESTSET => $(esc(ts)), TESTSET_DEPTH => get_testset_depth() + 1, $(esc(expr))) + finally + print_testset_verbose(:exit, $(esc(ts))) + end + end end """ @@ -2127,6 +2144,41 @@ function get_testset_depth() something(Base.ScopedValues.get(TESTSET_DEPTH)) end +""" +Print testset entry/exit messages when JULIA_TEST_VERBOSE is set +""" +function print_testset_verbose(action::Symbol, ts::AbstractTestSet) + something(Base.ScopedValues.get(VERBOSE_TESTSETS)) || return + indent = " " ^ get_testset_depth() + desc = if hasfield(typeof(ts), :description) + ts.description + elseif isa(ts, ContextTestSet) + string(ts.context_name, " = ", ts.context) + else + string(typeof(ts)) + end + if action === :enter + println("$(indent)Starting testset: $desc") + elseif action === :exit + duration_str = "" + # Calculate duration for testsets that have timing information + if hasfield(typeof(ts), :time_start) && hasfield(typeof(ts), :showtiming) + if ts.showtiming + current_time = time() + dur_s = current_time - ts.time_start + if dur_s < 60 + duration_str = " ($(round(dur_s, digits = 1))s)" + else + m, s = divrem(dur_s, 60) + s = lpad(string(round(s, digits = 1)), 4, "0") + duration_str = " ($(round(Int, m))m$(s)s)" + end + end + end + println("$(indent)Finished testset: $desc$duration_str") + end +end + _args_and_call((args..., f)...; kwargs...) = (args, kwargs, f(args...; kwargs...)) _materialize_broadcasted(f, args...) = Broadcast.materialize(Broadcast.broadcasted(f, args...)) diff --git a/stdlib/Test/test/runtests.jl b/stdlib/Test/test/runtests.jl index f84ec18b22661..796d1bed86d93 100644 --- a/stdlib/Test/test/runtests.jl +++ b/stdlib/Test/test/runtests.jl @@ -2033,3 +2033,60 @@ end @test occursin("Error in testset", output) @test occursin("1 == 2", output) end + +@testset "JULIA_TEST_VERBOSE" begin + # Test the verbose testset entry/exit functionality + Base.ScopedValues.@with Test.VERBOSE_TESTSETS => true begin + # Capture output + output = mktemp() do fname, f + redirect_stdout(f) do + @testset "Verbose Test" begin + @test true + @testset "Nested Verbose Test" begin + sleep(0.01) # Add some duration + @test 1 + 1 == 2 + end + end + end + seekstart(f) + read(f, String) + end + + # Check that verbose messages are present + @test occursin("Starting testset: Verbose Test", output) + @test occursin("Finished testset: Verbose Test", output) + @test occursin("Starting testset: Nested Verbose Test", output) + @test occursin("Finished testset: Nested Verbose Test", output) + + # Check that timing information is included in exit messages + @test occursin(r"Finished testset: Nested Verbose Test \([0-9\.]+s\)", output) + + # Check indentation for nested testsets + lines = split(output, '\n') + entering_nested = findfirst(line -> occursin("Starting testset: Nested Verbose Test", line), lines) + exiting_nested = findfirst(line -> occursin("Finished testset: Nested Verbose Test", line), lines) + + if entering_nested !== nothing && exiting_nested !== nothing + # Both nested messages should have more indentation than outer messages + @test startswith(lines[entering_nested], " ") + @test startswith(lines[exiting_nested], " ") + end + end + + # Test that verbose output is disabled by default + Base.ScopedValues.@with Test.VERBOSE_TESTSETS => false begin + output = mktemp() do fname, f + redirect_stdout(f) do + @testset "Non-Verbose Test" begin + @test true + end + end + seekstart(f) + read(f, String) + end + + # Should not contain verbose messages + @test !occursin("Starting testset:", output) + @test !occursin("Finished testset:", output) + end +end