Add test verbose env var and show when starting/finishing testsets (JuliaLang#59295)

Author: IanButterworth

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]).

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"

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...))
 

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