test_logs macro - tests + minor fixes and updates

stdlib/Test/src/logging.jl

@@ -60,11 +60,13 @@ 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`.
+A different number of tuple elements may be used to match other log metadata,
+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 `==` by default, with the special cases that `Symbol`s may be used for
+the standard log levels, and `Regex`s in the pattern will match string or
+Symbol fields using `ismatch`.
 
 # Examples
 
@@ -79,12 +81,12 @@ Consider a function which logs a warning, and several debug messages:
 
 We can test the info message using
 
-    @test_logs (Info,"Doing foo with n=2") foo(2)
+    @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)
+    @test_logs (:info,"Doing foo with n=2") (:debug,"Iteration 1") (:debug,"Iteration 2") min_level=Debug foo(2)
 
 """
 macro test_logs(exs...)
@@ -94,7 +96,7 @@ macro test_logs(exs...)
     kwargs = Any[]
     for e in exs[1:end-1]
         if e isa Expr && e.head == :(=)
-            push!(kwargs, Expr(:kw, e.args...))
+            push!(kwargs, esc(Expr(:kw, e.args...)))
         else
             push!(args, esc(e))
         end
@@ -119,9 +121,23 @@ function ismatch_logs(f, patterns...; kwargs...)
     return true
 end
 
+# TODO: Use a version of parse_level from stdlib/Logging, when it exists.
+function parse_level(level::Symbol)
+    if      level == :belowminlevel  return  Base.BelowMinLevel
+    elseif  level == :debug          return  Base.Debug
+    elseif  level == :info           return  Base.Info
+    elseif  level == :warn           return  Base.Warn
+    elseif  level == :error          return  Base.Error
+    elseif  level == :abovemaxlevel  return  Base.AboveMaxLevel
+    else
+        throw(ArgumentError("Unknown log level $level"))
+    end
+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))
+logfield_ismatch(a::Symbol, b::LogLevel) = parse_level(a) == b
 
 function ismatch(pattern::Tuple, r::LogRecord)
     stdfields = (r.level, r.message, r._module, r.group, r.id, r.file, r.line)

stdlib/Test/test/runtests.jl

@@ -2,6 +2,8 @@
 
 using Test
 
+import Base: Debug, Info
+
 @testset "@test" begin
     @test true
     @test 1 == 1
@@ -49,6 +51,27 @@ end
     @test_skip false
     @test_skip gobbeldygook
 end
+@testset "@test_logs" begin
+    function foo(n)
+        @info "Doing foo with n=$n"
+        for i=1:n
+            @debug "Iteration $i"
+        end
+    end
+    # Basic
+    @test_logs (Info,"Doing foo with n=2") foo(2)
+    # Log pattern matching
+    # - Regex
+    @test_logs (Info,r"^Doing foo with n=[0-9]+$") foo(10)
+    @test_logs (Info,r"^Doing foo with n=[0-9]+$") foo(1)
+    # - Level symbols
+    @test_logs (:debug,) min_level=Debug @debug "foo"
+    @test_logs (:info,)  @info  "foo"
+    @test_logs (:warn,)  @warn  "foo"
+    @test_logs (:error,) @error "foo"
+    # Debug level log collection
+    @test_logs (Info,"Doing foo with n=2") (Debug,"Iteration 1") (Debug,"Iteration 2") min_level=Debug foo(2)
+end
 @testset "@test_warn" begin
     @test 1234 === @test_nowarn(1234)
     @test 5678 === @test_warn("WARNING: foo", begin warn("foo"); 5678; end)