diff --git a/stdlib/Test/src/Test.jl b/stdlib/Test/src/Test.jl index 2f620142ab233..9e7df8bf89661 100644 --- a/stdlib/Test/src/Test.jl +++ b/stdlib/Test/src/Test.jl @@ -15,7 +15,7 @@ and summarize them at the end of the test set with `@testset`. """ module Test -export @test, @test_throws, @test_broken, @test_skip, @test_warn, @test_nowarn +export @test, @test_throws, @test_broken, @test_skip, @test_warn, @test_nowarn, @test_logs export @testset # Legacy approximate testing functions, yet to be included export @inferred @@ -489,7 +489,11 @@ function do_test_throws(result::ExecutionResult, @nospecialize(orig_expr), @nosp end #----------------------------------------------------------------------- -# Test for warning messages +# Test for log messages + +include("logging.jl") + +# Test for warning messages (deprecated) ismatch_warn(s::AbstractString, output) = contains(output, s) ismatch_warn(s::Regex, output) = ismatch(s, output) diff --git a/stdlib/Test/src/logging.jl b/stdlib/Test/src/logging.jl new file mode 100644 index 0000000000000..caef69670c372 --- /dev/null +++ b/stdlib/Test/src/logging.jl @@ -0,0 +1,130 @@ +import Base: Info, + shouldlog, handle_message, min_enabled_level, catch_exceptions +import Base: ismatch + +#------------------------------------------------------------------------------- +# Log records +struct LogRecord + level + message + _module + group + id + file + line + kwargs +end +LogRecord(args...; kwargs...) = LogRecord(args..., kwargs) + +#------------------------------------------------------------------------------- +# Logger with extra test-related state +mutable struct TestLogger <: AbstractLogger + logs::Vector{LogRecord} + min_level::LogLevel + catch_exceptions::Bool + shouldlog_args +end + +TestLogger(; min_level=Info, catch_exceptions=false) = TestLogger(LogRecord[], min_level, catch_exceptions, nothing) +min_enabled_level(logger::TestLogger) = logger.min_level + +function shouldlog(logger::TestLogger, level, _module, group, id) + logger.shouldlog_args = (level, _module, group, id) + true +end + +function handle_message(logger::TestLogger, level, msg, _module, + group, id, file, line; kwargs...) + push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs)) +end + +# Catch exceptions for the test logger only if specified +catch_exceptions(logger::TestLogger) = logger.catch_exceptions + +function collect_test_logs(f; kwargs...) + logger = TestLogger(; kwargs...) + with_logger(f, logger) + logger.logs +end + + +#------------------------------------------------------------------------------- +# Log testing tools + +""" + @test_logs [log_patterns...] [keywords] expression + +Collect a list of log records generated by `expression` using +`collect_test_logs`, and check that they match the sequence `log_patterns`. +The `keywords` provide some simple filtering of log records: the `min_level` +keyword controls the minimum log level which will be collected for the test. + +The most useful log pattern is a simple tuple of the form `(level,message)`. +More or less tuple elements may be added corresponding to the arguments to +passed to `AbstractLogger` via the `handle_message` function: +`(level,message,module,group,id,file,line)`. Elements which are present will +be matched pairwise with the log record fields using `==` or `ismatch` when the +pattern field is a `Regex`. + +# Examples + +Consider a function which logs a warning, and several debug messages: + + function foo(n) + @info "Doing foo with n=\$n" + for i=1:n + @debug "Iteration \$i" + end + end + +We can test the info message using + + @test_logs (Info,"Doing foo with n=2") foo(2) + +If we also wanted to test the debug messages, these need to be enabled with the +`min_level` keyword: + + @test_logs (Info,"Doing foo with n=2") (Debug,"Iteration 1") (Debug,"Iteration 2") min_level=Debug foo(2) + +""" +macro test_logs(exs...) + length(exs) >= 1 || throw(ArgumentError("""`@test_logs` needs at least one arguments. + Usage: `@test_logs [msgs...] expr_to_run`""")) + args = Any[] + kwargs = Any[] + for e in exs[1:end-1] + if e isa Expr && e.head == :(=) + push!(kwargs, Expr(:kw, e.args...)) + else + push!(args, esc(e)) + end + end + # TODO: Better error reporting in @test + ex = quote + @test ismatch_logs($(args...); $(kwargs...)) do + $(esc(exs[end])) + end + end + # Propagate source code location of @test_logs to @test macro + ex.args[2].args[2] = __source__ + ex +end + +function ismatch_logs(f, patterns...; kwargs...) + logs = collect_test_logs(f; kwargs...) + length(logs) == length(patterns) || return false + for (pattern,log) in zip(patterns, logs) + ismatch(pattern, log) || return false + end + return true +end + +logfield_ismatch(a, b) = a == b +logfield_ismatch(r::Regex, b) = ismatch(r, b) +logfield_ismatch(r::Regex, b::Symbol) = ismatch(r, String(b)) + +function ismatch(pattern::Tuple, r::LogRecord) + stdfields = (r.level, r.message, r._module, r.group, r.id, r.file, r.line) + all(logfield_ismatch(p,f) for (p,f) in zip(pattern, stdfields[1:length(pattern)])) +end + diff --git a/test/logging.jl b/test/logging.jl index ea62967a71c62..8443f35bbf353 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -1,103 +1,13 @@ -import Base: LogLevel, BelowMinLevel, Debug, Info, Warn, Error, AboveMaxLevel, - shouldlog, handle_message, min_enabled_level, catch_exceptions +import Base: BelowMinLevel, Debug, Info, Warn, Error, + handle_message, shouldlog -import Base: ismatch +import Test: collect_test_logs, TestLogger -# Test helpers - -#-------------------------------------------------- -# A logger which does nothing, except enable exceptions to propagate -struct AllowExceptionsLogger <: AbstractLogger ; end -handle_message(logger::AllowExceptionsLogger) = nothing -catch_exceptions(logger::AllowExceptionsLogger) = false - -#------------------------------------------------------------------------------- -# Log records -struct LogRecord - level - message - _module - group - id - file - line - kwargs -end -LogRecord(args...; kwargs...) = LogRecord(args..., kwargs) - -#------------------------------------------------------------------------------- -# Logger with extra test-related state -mutable struct TestLogger <: AbstractLogger - logs::Vector{LogRecord} - min_level::LogLevel - shouldlog_args -end - -TestLogger(min_level=BelowMinLevel) = TestLogger(LogRecord[], min_level, nothing) -min_enabled_level(logger::TestLogger) = logger.min_level - -function shouldlog(logger::TestLogger, level, _module, group, id) - logger.shouldlog_args = (level, _module, group, id) - true -end - -function handle_message(logger::TestLogger, level, msg, _module, - group, id, file, line; kwargs...) - push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs)) -end - -function collect_test_logs(f; min_level=Debug) - logger = TestLogger(min_level) - with_logger(f, logger) - logger.logs -end - - -#-------------------------------------------------- -# Log testing tools -macro test_logs(exs...) - length(exs) >= 1 || throw(ArgumentError("""`@test_logs` needs at least one arguments. - Usage: `@test_logs [msgs...] expr_to_run`""")) - args = Any[] - kwargs = Any[] - for e in exs[1:end-1] - if e isa Expr && e.head == :(=) - push!(kwargs, Expr(:kw, e.args...)) - else - push!(args, esc(e)) - end - end - # TODO: Better error reporting in @test - ex = quote - @test ismatch_logs($(args...); $(kwargs...)) do - $(esc(exs[end])) - end - end - # Propagate source code location of @test_logs to @test macro - ex.args[2].args[2] = __source__ - ex -end - -function ismatch_logs(f, patterns...; min_level=BelowMinLevel, kwargs...) - logs = collect_test_logs(f; min_level=min_level, kwargs...) - length(logs) == length(patterns) || return false - for (pattern,log) in zip(patterns, logs) - ismatch(pattern, log) || return false - end - return true -end - -function ismatch(ref::Tuple, r::LogRecord) - stdfields = (r.level, r.message, r._module, r.group, r.id, r.file, r.line) - ref == stdfields[1:length(ref)] -end - -#------------------------------------------------------------------------------- #------------------------------------------------------------------------------- @testset "Logging" begin @testset "Basic logging" begin - @test_logs (Debug, "a") @debug "a" + @test_logs (Debug, "a") min_level=Debug @debug "a" @test_logs (Info, "a") @info "a" @test_logs (Warn, "a") @warn "a" @test_logs (Error, "a") @error "a" @@ -171,10 +81,11 @@ end @testset "Log message exception handling" begin # Exceptions in message creation are caught by default - @test_logs (Error,) @info "foo $(1÷0)" - # Exceptions propagate if explicitly disabled for the logger type - @test_throws DivideError with_logger(AllowExceptionsLogger()) do - @info "foo $(1÷0)" + @test_logs (Error,) catch_exceptions=true @info "foo $(1÷0)" + # Exceptions propagate if explicitly disabled for the logger (by default + # for the test logger) + @test_throws DivideError collect_test_logs() do + @info "foo $(1÷0)" end end @@ -212,7 +123,7 @@ end @testset "Log filtering, global logger" begin old_logger = global_logger() logs = let - logger = TestLogger(Warn) + logger = TestLogger(min_level=Warn) global_logger(logger) @info "b" @warn "c" @@ -234,16 +145,16 @@ end end disable_logging(BelowMinLevel) - @test_logs (Debug, "a") (Info, "b") (Warn, "c") (Error, "d") log_each_level() + @test_logs (Debug, "a") (Info, "b") (Warn, "c") (Error, "d") min_level=Debug log_each_level() disable_logging(Debug) - @test_logs (Info, "b") (Warn, "c") (Error, "d") log_each_level() + @test_logs (Info, "b") (Warn, "c") (Error, "d") min_level=Debug log_each_level() disable_logging(Info) - @test_logs (Warn, "c") (Error, "d") log_each_level() + @test_logs (Warn, "c") (Error, "d") min_level=Debug log_each_level() disable_logging(Warn) - @test_logs (Error, "d") log_each_level() + @test_logs (Error, "d") min_level=Debug log_each_level() disable_logging(Error) @test_logs log_each_level()