Move logging test tools to Test

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)

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
+

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