From 6091d505d4315a7d202952e01e104b3192b9165a Mon Sep 17 00:00:00 2001 From: Morten Piibeleht Date: Wed, 20 Jul 2022 19:25:02 +1200 Subject: [PATCH] Improve how the at-quietly logs are handled in the tests (#1882) * Change loading of TestUtilities Create a more uniform pattern for loading the module to make sure that we do not accidentally load it several times as the tests runs, resetting the output log file, if that is enabled. * Store at-quietly logs in separate files And also print the log ID in the test output if the logs are enabled, so that it would be easy to find the corresponding log. --- .gitignore | 1 + test/TestUtilities.jl | 53 ++++++++++++++++++++++++++++---------- test/deploydocs.jl | 4 +-- test/doctests/fix/tests.jl | 3 +-- test/examples/make.jl | 5 ++-- test/missingdocs/make.jl | 4 +-- test/runtests.jl | 2 +- test/utilities.jl | 3 +-- 8 files changed, 51 insertions(+), 24 deletions(-) diff --git a/.gitignore b/.gitignore index 8818dc77e3..2e1de3f888 100644 --- a/.gitignore +++ b/.gitignore @@ -12,6 +12,7 @@ test/errors/build/ test/prerender/build/ test/themes/dev/ test/workdir/builds/ +test/quietly-logs/ docs/dev/ docs/build/ docs/build-pdf/ diff --git a/test/TestUtilities.jl b/test/TestUtilities.jl index 415ac81127..ea80484a21 100644 --- a/test/TestUtilities.jl +++ b/test/TestUtilities.jl @@ -1,26 +1,52 @@ -module TestUtilities +isdefined(Main, :TestUtilities) || @eval Main module TestUtilities using Test import IOCapture export @quietly, trun -const QUIETLY_LOG = joinpath(@__DIR__, "quietly.log") +const QUIETLY_LOG_DIR = joinpath(@__DIR__, "quietly-logs") +const QUIETLY_LOG_COUNTER = Ref{Int}(0) -__init__() = isfile(QUIETLY_LOG) && rm(QUIETLY_LOG) +quietly_logs_enabled() = haskey(ENV, "DOCUMENTER_TEST_QUIETLY") + +function quietly_logfile(n) + logid = lpad(n, 4, '0') + logid, joinpath(QUIETLY_LOG_DIR, "quietly.$(logid).log") +end +function quietly_next_log() + quietly_logs_enabled() || return nothing, nothing + isdir(QUIETLY_LOG_DIR) || mkdir(QUIETLY_LOG_DIR) + # Find the next availble log file + logid, logfile = quietly_logfile(QUIETLY_LOG_COUNTER[]) + while isfile(logfile) + QUIETLY_LOG_COUNTER[] += 1 + logid, logfile = quietly_logfile(QUIETLY_LOG_COUNTER[]) + end + return logid, logfile +end + +function __init__() + # We only clean up the old log files if DOCUMENTER_TEST_QUIETLY is set + quietly_logs_enabled() || return + isdir(QUIETLY_LOG_DIR) && rm(QUIETLY_LOG_DIR, recursive=true) +end struct QuietlyException <: Exception + logid :: Union{String,Nothing} exception backtrace end function Base.showerror(io::IO, e::QuietlyException) - println(io, "@quietly hit an exception ($(typeof(e.exception))):") + prefix = isnothing(e.logid) ? "@quietly" : "@quietly[$logid]" + println(io, "$(prefix) hit an exception ($(typeof(e.exception))):") showerror(io, e.exception, e.backtrace) end function _quietly(f, expr, source) c = IOCapture.capture(f; rethrow = InterruptException) - haskey(ENV, "DOCUMENTER_TEST_QUIETLY") && open(QUIETLY_LOG; write=true, append=true) do io + logid, logfile = quietly_next_log() + isnothing(logid) || open(logfile; write=true, append=true) do io println(io, "@quietly: c.error = $(c.error) / $(sizeof(c.output)) bytes of output captured") println(io, "@quietly: $(source.file):$(source.line)") println(io, "@quietly: typeof(result) = ", typeof(c.value)) @@ -35,34 +61,35 @@ function _quietly(f, expr, source) println(io, c.value) end end + prefix = isnothing(logid) ? "@quietly" : "@quietly[$logid]" if c.error @error """ - An error was thrown in @quietly, $(sizeof(c.output)) bytes of output captured + $(prefix): an error was thrown, $(sizeof(c.output)) bytes of output captured $(typeof(c.value)) at $(source.file):$(source.line) in expression: $(expr) """ if !isempty(c.output) - printstyled("$("="^21) @quietly: output from the expression $("="^21)\n"; color=:magenta) + printstyled("$("="^21) $(prefix): output from the expression $("="^21)\n"; color=:magenta) print(c.output) last(c.output) != "\n" && println() - printstyled("$("="^27) @quietly: end of output $("="^28)\n"; color=:magenta) + printstyled("$("="^27) $(prefix): end of output $("="^28)\n"; color=:magenta) end - throw(QuietlyException(c.value, c.backtrace)) + throw(QuietlyException(logid, c.value, c.backtrace)) elseif c.value isa Test.DefaultTestSet && !is_success(c.value) @error """ - @quietly: a testset with failures, $(sizeof(c.output)) bytes of output captured + $(prefix): a testset with failures, $(sizeof(c.output)) bytes of output captured $(typeof(c.value)) at $(source.file):$(source.line) in expression: $(expr) """ TestSet = c.value if !isempty(c.output) - printstyled("$("="^21) @quietly: output from the expression $("="^21)\n"; color=:magenta) + printstyled("$("="^21) $(prefix): output from the expression $("="^21)\n"; color=:magenta) print(c.output) last(c.output) != "\n" && println() - printstyled("$("="^27) @quietly: end of output $("="^28)\n"; color=:magenta) + printstyled("$("="^27) $(prefix): end of output $("="^28)\n"; color=:magenta) end return c.value else - printstyled("@quietly: success, $(sizeof(c.output)) bytes of output hidden\n"; color=:magenta) + printstyled("$(prefix): success, $(sizeof(c.output)) bytes of output hidden\n"; color=:magenta) return c.value end end diff --git a/test/deploydocs.jl b/test/deploydocs.jl index 4cdc444716..4d2b92eb57 100644 --- a/test/deploydocs.jl +++ b/test/deploydocs.jl @@ -1,7 +1,7 @@ -isdefined(@__MODULE__, :TestUtilities) || include("TestUtilities.jl") using Documenter: Documenter, deploydocs using Documenter.Utilities: git -using Test, ..TestUtilities +using Test +include("TestUtilities.jl"); using Main.TestUtilities struct TestDeployConfig <: Documenter.DeployConfig repo_path :: String diff --git a/test/doctests/fix/tests.jl b/test/doctests/fix/tests.jl index 98cd27bbe9..f5254b49d1 100644 --- a/test/doctests/fix/tests.jl +++ b/test/doctests/fix/tests.jl @@ -2,10 +2,9 @@ # # DOCUMENTER_TEST_DEBUG= JULIA_DEBUG=all julia test/doctests/fix/tests.jl # -isdefined(@__MODULE__, :TestUtilities) || (include("../../TestUtilities.jl"); using .TestUtilities) module DocTestFixTest using Documenter, Test -using ..TestUtilities: @quietly +include("../../TestUtilities.jl"); using Main.TestUtilities: @quietly # Type to reliably show() objects across Julia versions: @eval Main begin diff --git a/test/examples/make.jl b/test/examples/make.jl index b300582a7c..d7b4fa312b 100644 --- a/test/examples/make.jl +++ b/test/examples/make.jl @@ -1,3 +1,6 @@ +using Documenter +include("../TestUtilities.jl"); using Main.TestUtilities + # Defines the modules referred to in the example docs (under src/) and then builds them. # It can be called separately to build the examples/, or as part of the test suite. @@ -159,8 +162,6 @@ function withassets(f, assets...) end # Build example docs -using Documenter -isdefined(@__MODULE__, :TestUtilities) || (include("../TestUtilities.jl"); using .TestUtilities) examples_root = @__DIR__ builds_directory = joinpath(examples_root, "builds") diff --git a/test/missingdocs/make.jl b/test/missingdocs/make.jl index 648370f888..98f6b8d6db 100644 --- a/test/missingdocs/make.jl +++ b/test/missingdocs/make.jl @@ -1,7 +1,7 @@ -isdefined(@__MODULE__, :TestUtilities) || include("../TestUtilities.jl") module MissingDocsTests -using Test, ..TestUtilities +using Test using Documenter +include("../TestUtilities.jl"); using Main.TestUtilities module MissingDocs export f diff --git a/test/runtests.jl b/test/runtests.jl index 68bf61872c..aca3fe2d79 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -1,6 +1,6 @@ using Test import Documenter -include("TestUtilities.jl"); using .TestUtilities +include("TestUtilities.jl"); using Main.TestUtilities @testset "Documenter" begin # Build the example docs diff --git a/test/utilities.jl b/test/utilities.jl index 7ff548db9a..ba7392602b 100644 --- a/test/utilities.jl +++ b/test/utilities.jl @@ -1,9 +1,8 @@ module UtilitiesTests - using Test using Logging: Info import Base64: stringmime -include("TestUtilities.jl"); using .TestUtilities +include("TestUtilities.jl"); using Main.TestUtilities import Documenter using Documenter.Utilities: git