Merge pull request #64 from quinnj/jq/debugutilities

Alternative approach to debug logging utilities.

Author: quinnj

README.md

@@ -93,6 +93,7 @@ All of them, except `FormatLogger`, just wrap existing loggers.
  - The `FileLogger` is a simple logger sink that writes to file.
  - The `DatetimeRotatingFileLogger` is a logger sink that writes to file, rotating logs based upon a user-provided `DateFormat`.
  - The `FormatLogger` is a logger sink that simply formats the message and writes to the logger stream.
+ - The `LevelOverrideLogger` for overriding the log level of other loggers
 
 By combining `TeeLogger` with filter loggers you can arbitrarily route log messages, wherever you want.
 
@@ -374,6 +375,61 @@ Main | [Info] This is an informational message.
 Main | [Warn] This is a warning, should take a look.
 ```
 
+## `LevelOverrideLogger` (*Filter*)
+Allows overriding the minimum log level set by the logger it wraps.
+Useful when debug logging
+and used in conjuction with `Logging.with_logger` or `LoggingExtras.withlevel` to
+temporarily modify the current logger with a custom level.
+More generally useful if you want to use the current/global logger as a _sink_ but don't know if it is going to have a problematically high min log level set (as julia's default logger sets min level to `Info`).
+
+```julia
+julia> using LoggingExtras
+
+julia> logger = LevelOverrideLogger(Debug, global_logger())
+
+julia> with_logger(logger) do
+           @debug "This message will log since we're overriding the global Info default log level"
+       end
+┌ Debug: This message will log since we're overriding the global Info default log level
+└ @ Main REPL[33]:2
+```
+This is roughly complementary to the `MinLevelFilterLogger`.
+The `MinLevelFilterLogger` lets you effectively *raise* the level of any logger it wraps to meet the level you specify.
+The `LevelOverrideLogger` lets you *lower* (or *raise*) the level of the wrapped logger as it bypasses checks on it entirely.
+
+# Utilities
+
+## Verbosity macros
+Sometimes when logging, it is desirable to be able to specify a verbosity level along with
+the log level, and to be able to filter on verbosity levels. For example, you may want multiple levels
+of verbosity for `Debug` log statements. LoggingExtras.jl exports verbosity macros that act like their
+non-verbose counterparts, but allow specifying a verbosity level as well:
+  * `@debugv N msg`
+  * `@infov N msg`
+  * `@warnv N msg`
+  * `@errorv N msg`
+
+For verbosity filtering, the `LoggingExtras.withlevel(f, Info; verbosity=0)` utlility is provided
+for temporarily (i.e. while `f()` is executed) allowing log messages with `level` and `verbosity`.
+This is very handy for allowing finer grained control in debug logging for long-running or complex user API function
+calls. For example:
+
+```julia
+using LoggingExtras
+
+function complex_user_call(; verbose=0)
+    LoggingExtras.withlevel(Debug; verbosity=verbose)
+        # execute complex function body
+        @debugv 1 "a level 1 verbosity debug message"
+        @debugv 2 "a more verbose level 2 debug message"
+    end
+end
+```
+
+This allows easy control by the user to specify verbosity (by passing `verbose=2` or any > 0 value),
+and convenience for the function developer by being able to sprinkle `@debugv N msg` calls as desired,
+even in highly nested functions.
+
 # More Examples
 
 ## Filter out any overly long messages

src/LoggingExtras.jl

@@ -10,7 +10,8 @@ import Base.CoreLogging:
 
 export TeeLogger, TransformerLogger, FileLogger,
     ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger,
-    DatetimeRotatingFileLogger, FormatLogger
+    DatetimeRotatingFileLogger, FormatLogger, LevelOverrideLogger,
+    @debugv, @infov, @warnv, @errorv, @logmsgv
 
 ######
 # Re export Logging.jl from stdlib 
@@ -50,6 +51,8 @@ include("minlevelfiltered.jl")
 include("filelogger.jl")
 include("formatlogger.jl")
 include("datetime_rotation.jl")
+include("overridelogger.jl")
+include("verbosity.jl")
 include("deprecated.jl")
 
 end # module

src/overridelogger.jl

@@ -0,0 +1,23 @@
+"""
+    LevelOverrideLogger(level, logger)
+
+A logger that allows overriding the log level of a child level.
+Useful in debugging scenarios, where it is desirable to ignore
+the log level any other logger may have set.
+"""
+struct LevelOverrideLogger{T <: AbstractLogger} <: AbstractLogger
+    level::LogLevel
+    logger::T
+end
+
+
+handle_message(logger::LevelOverrideLogger, args...; kwargs...) =
+    handle_message(logger.logger, args...; kwargs...)
+
+function shouldlog(logger::LevelOverrideLogger, level, args...)
+    # Ignore the logger.logger's own level and instead check the override level
+    level >= logger.level && shouldlog(logger.logger, level, args...)
+end
+
+min_enabled_level(logger::LevelOverrideLogger) = logger.level
+catch_exceptions(logger::LevelOverrideLogger) = catch_exceptions(logger.logger)

src/verbosity.jl

@@ -0,0 +1,91 @@
+function restore_callsite_source_position!(expr, src)
+    @assert expr.head == :escape
+    @assert expr.args[1].head == :macrocall
+    @assert expr.args[1].args[2] isa LineNumberNode
+    # used to fix the logging source file + line
+    # since we're lowering our verbose logging macros to the
+    # Logging.jl macros; otherwise, they would always report this (verbosity.jl)
+    # file as the logging callsite
+    expr.args[1].args[2] = src
+    return expr
+end
+
+vlogmacrodocs = """
+    @debugv N msg args...
+    @infov N msg args...
+    @warnv N msg args...
+    @errorv N msg args...
+
+"Verbose" logging macros. Drop in replacements of standard logging macros, but an
+additional verbosity level `N` is passed to indicate differing verbosity levels
+for a given log level. The verbosity argument is subtracted from the base log level when passed down
+to the core logging logic, so `@debugv 1 msg` will essentially call `@logmsg Debug-1 msg`.
+
+An `LoggingExtras.LevelOverrideLogger`can then be used to filter on the `level` argument.
+For convenience, the
+[`LoggintExtras.with(f; level, verbosity)`](@ref) function is provided to temporarily
+wrap the current logger with a log level and verbosity subtracted to filter while `f` is executed.
+"""
+
+"$vlogmacrodocs"
+macro debugv(verbosity::Int, msg, exs...)
+    return restore_callsite_source_position!(
+        esc(:($Base.@logmsg (Logging.Debug - $verbosity) $msg $(exs...))),
+        __source__,
+    )
+end
+
+"$vlogmacrodocs"
+macro infov(verbosity::Int, msg, exs...)
+    return restore_callsite_source_position!(
+        esc(:($Base.@logmsg (Logging.Info - $verbosity) $msg $(exs...))),
+        __source__,
+    )
+end
+
+"$vlogmacrodocs"
+macro warnv(verbosity::Int, msg, exs...)
+    return restore_callsite_source_position!(
+        esc(:($Base.@logmsg (Logging.Warn - $verbosity) $msg $(exs...))),
+        __source__,
+    )
+end
+
+"$vlogmacrodocs"
+macro errorv(verbosity::Int, msg, exs...)
+    return restore_callsite_source_position!(
+        esc(:($Base.@logmsg (Logging.Error - $verbosity) $msg $(exs...))),
+        __source__,
+    )
+end
+
+"$vlogmacrodocs"
+macro logmsgv(verbosity::Int, level, msg, exs...)
+    return restore_callsite_source_position!(
+        esc(:($Base.@logmsg ($level - $verbosity) $msg $(exs...))),
+        __source__,
+    )
+end
+
+"""
+    LoggingExtras.withlevel(f, level; verbosity::Integer=0)
+
+Convenience function like `Logging.with_logger` to temporarily wrap
+the current logger with a level filter while `f` is executed.
+That is, the current logger will still be used for actual logging, but
+log messages will first be checked that they meet the `level`
+log level before being passed on to be logged.
+"""
+function withlevel(f, level::Union{Int, LogLevel}=Info; verbosity::Integer=0)
+    lvl = Base.CoreLogging._min_enabled_level[]
+    try
+        # by default, this global filter is Debug, but for debug logging
+        # we want to enable sub-Debug levels
+        Base.CoreLogging._min_enabled_level[] = BelowMinLevel
+        with_logger(LevelOverrideLogger(level - verbosity, current_logger())) do
+            f()
+        end
+    finally
+        Base.CoreLogging._min_enabled_level[] = lvl
+    end
+end

test/runtests.jl

@@ -239,6 +239,54 @@ end
     end
 end
 
+@testset "LevelOverrideLogger" begin
+    logger = TestLogger(min_level=Info)
+    with_logger(LevelOverrideLogger(Debug, logger)) do
+        @debug "debug message"
+        @info "info message"
+
+    end
+    @test length(logger.logs) == 2
+    @test map(x -> x.level, logger.logs) == [Debug, Info]
+end
+
+@testset "Verbosity utilities" begin
+    logger = TestLogger(min_level=Info)
+    with_logger(logger) do
+        @infov 1 "info 1 message"
+    end
+    @test isempty(logger.logs)
+
+    logger = TestLogger(min_level=Info)
+    with_logger(logger) do
+        LoggingExtras.withlevel(Debug) do
+            @debug "debug message"
+        end
+    end
+    @test logger.logs[1].level == Debug
+
+    logger = TestLogger(min_level=Info)
+    with_logger(logger) do
+        LoggingExtras.withlevel(Debug; verbosity=1) do
+            @debugv 0 "debug 0 message"
+            @debugv 1 "debug 1 message"
+            @debugv 2 "debug 2 message"
+        end
+    end
+    @test length(logger.logs) == 2
+    @test map(x -> x.level, logger.logs) == [Debug, Debug-1]
+
+    logger = TestLogger(min_level=Info)
+    with_logger(logger) do
+        with_logger(MinLevelLogger(current_logger(), Info)) do
+            LoggingExtras.withlevel(Debug; verbosity=1) do
+                @debug "This should show up, even though it is behind 2 info level filters"
+            end
+        end
+    end
+    @test_broken length(logger.logs) == 1
+end
+
 @testset "Deprecations" begin
     testlogger = TestLogger(min_level=BelowMinLevel)