From 677d925a581053aa74947466ff9b05df6ecf8b1c Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Tue, 17 May 2022 01:01:58 -0600 Subject: [PATCH 01/15] Alternative approach to debug logging utilities. Alternative to what's proposed in #63. In particular, the pieces proposed here include: * More general "verbosity" argument separate and supporing any log level * Convenience macros for passing verbosity (i.e. `@debugv 1 "hey"` => `@debug "hey" verbosity=1`) * A `LevelOverrideLogger` for overriding the level of any nested logger * A convenience `LoggingExtras.with` function for *very* easily passing a temporary log level and/or verbosity while a function is run. My thoughts have evolved here for supporting package developers wishing to have an easy way to support multiple levels of debug verbosity logging. The approach I'm converging on is: * Package devs support accepting a `verbose::Int=0` keyword arg to high-level user-facing API functions; *very early on*, this keyword arg is "handled" by checking the level and wrapping the remaining function body in a `LoggingExtras.with` call to enable verbose debug logging. An important key here is that as a package dev, I *don't* have to thread the `verbose` keyword through a potentially messy nested call graph of a function. I can just wrap the invocation in `LoggingExtras.with` and then sprinkle `@debugv N` calls at any nested depth I'd like. * For users, this also provides an extremely easy/intuitive interface for enabling verbose debug logging. I don't have to fiddle with configuring a logger or messing w/ global state, I just pass `verbose=1` or `verbose=3` and any verbose logs will be written out. If this approach sounds reasonable, I can clean up this PR w/ docs/examples/tests. --- src/LoggingExtras.jl | 6 +++++- src/overridelogger.jl | 15 +++++++++++++++ src/util.jl | 22 ++++++++++++++++++++++ src/verbosity.jl | 24 ++++++++++++++++++++++++ 4 files changed, 66 insertions(+), 1 deletion(-) create mode 100644 src/overridelogger.jl create mode 100644 src/util.jl create mode 100644 src/verbosity.jl diff --git a/src/LoggingExtras.jl b/src/LoggingExtras.jl index 904a8ec..cc74ab8 100644 --- a/src/LoggingExtras.jl +++ b/src/LoggingExtras.jl @@ -10,7 +10,8 @@ import Base.CoreLogging: export TeeLogger, TransformerLogger, FileLogger, ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger, - DatetimeRotatingFileLogger, FormatLogger + DatetimeRotatingFileLogger, FormatLogger, + @debugv, @infov, @warnv, @errorv, @logmsgv ###### # Re export Logging.jl from stdlib @@ -50,6 +51,9 @@ include("minlevelfiltered.jl") include("filelogger.jl") include("formatlogger.jl") include("datetime_rotation.jl") +include("overridelogger.jl") +include("verbosity.jl") +include("util.jl") include("deprecated.jl") end # module diff --git a/src/overridelogger.jl b/src/overridelogger.jl new file mode 100644 index 0000000..8c50cff --- /dev/null +++ b/src/overridelogger.jl @@ -0,0 +1,15 @@ +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...) + level >= logger.level && shouldlog(logger.logger, level, args...) +end + +min_enabled_level(logger::LevelOverrideLogger) = logger.level +catch_exceptions(logger::LevelOverrideLogger) = catch_exceptions(logger.logger) diff --git a/src/util.jl b/src/util.jl new file mode 100644 index 0000000..106f16e --- /dev/null +++ b/src/util.jl @@ -0,0 +1,22 @@ +function with(f; level::Union{Int, LogLevel}=Info, verbosity::Int=0) + with_logger(genlogger(level, verbosity)) do + f() + end +end + +genlogger(l, v) = ActiveFilteredLogger( + LogVerbosityCheck(v), + TransformerLogger( + args -> merge(args, (kwargs=Base.structdiff(values(args.kwargs), (verbosity=0,)),)), + LevelOverrideLogger(l, current_logger()) + ) +) + +struct LogVerbosityCheck + verbosity::Int +end + +function (f::LogVerbosityCheck)(logargs) + kw = values(logargs.kwargs) + return !haskey(kw, :verbosity) || f.verbosity >= kw.verbosity +end \ No newline at end of file diff --git a/src/verbosity.jl b/src/verbosity.jl new file mode 100644 index 0000000..ae76b1e --- /dev/null +++ b/src/verbosity.jl @@ -0,0 +1,24 @@ +"""Calls @debug with the passed verbosity level""" +macro debugv(verbosity::Int64, msg, exs...) + return esc(:($Base.@debug $msg verbosity=$verbosity $(exs...))) +end + +"""Calls @info with the passed verbosity level""" +macro infov(verbosity::Int64, msg, exs...) + return esc(:($Base.@info $msg verbosity=$verbosity $(exs...))) +end + +"""Calls @warn with the passed verbosity level""" +macro warnv(verbosity::Int64, msg, exs...) + return esc(:($Base.@warn $msg verbosity=$verbosity $(exs...))) +end + +"""Calls @error with the passed verbosity level""" +macro errorv(verbosity::Int64, msg, exs...) + return esc(:($Base.@error $msg verbosity=$verbosity $(exs...))) +end + +"""Calls @error with the passed verbosity level""" +macro logmsgv(verbosity::Int64, level, msg, exs...) + return esc(:($Base.@logmsgv $level $msg verbosity=$verbosity $(exs...))) +end From 8226ad96f6cd11f3b698fb09cc7f67bba41c4282 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Tue, 17 May 2022 11:48:12 -0600 Subject: [PATCH 02/15] Simplify/cleanup --- src/LoggingExtras.jl | 1 - src/util.jl | 22 ------------ src/verbosity.jl | 81 ++++++++++++++++++++++++++++++++++++++------ 3 files changed, 71 insertions(+), 33 deletions(-) delete mode 100644 src/util.jl diff --git a/src/LoggingExtras.jl b/src/LoggingExtras.jl index cc74ab8..34df6e3 100644 --- a/src/LoggingExtras.jl +++ b/src/LoggingExtras.jl @@ -53,7 +53,6 @@ include("formatlogger.jl") include("datetime_rotation.jl") include("overridelogger.jl") include("verbosity.jl") -include("util.jl") include("deprecated.jl") end # module diff --git a/src/util.jl b/src/util.jl deleted file mode 100644 index 106f16e..0000000 --- a/src/util.jl +++ /dev/null @@ -1,22 +0,0 @@ -function with(f; level::Union{Int, LogLevel}=Info, verbosity::Int=0) - with_logger(genlogger(level, verbosity)) do - f() - end -end - -genlogger(l, v) = ActiveFilteredLogger( - LogVerbosityCheck(v), - TransformerLogger( - args -> merge(args, (kwargs=Base.structdiff(values(args.kwargs), (verbosity=0,)),)), - LevelOverrideLogger(l, current_logger()) - ) -) - -struct LogVerbosityCheck - verbosity::Int -end - -function (f::LogVerbosityCheck)(logargs) - kw = values(logargs.kwargs) - return !haskey(kw, :verbosity) || f.verbosity >= kw.verbosity -end \ No newline at end of file diff --git a/src/verbosity.jl b/src/verbosity.jl index ae76b1e..d5b5f1a 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -1,24 +1,85 @@ -"""Calls @debug with the passed verbosity level""" +function restore_callsite_source_position!(expr, src) + # 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 passed as the `group` argument +to the core logging logic, so care should be taken if other loggers are being used +that also use the group argument (which by default is passed the source file). + +The default logger doesn't have support for filtering on the `group` argument, +so an `LoggingExtras.EarlyFilteredLogger` can be used. For convenience, a +[`LoggintExtras.with(f; level, verbosity)`](@ref) function is provided to temporarily +wrap the current logger with a level/verbosity filter while `f` is executed. +""" + macro debugv(verbosity::Int64, msg, exs...) - return esc(:($Base.@debug $msg verbosity=$verbosity $(exs...))) + return restore_callsite_source_position!( + esc(:($Base.@debug $msg _group=$verbosity $(exs...))), + __source__, + ) end -"""Calls @info with the passed verbosity level""" macro infov(verbosity::Int64, msg, exs...) - return esc(:($Base.@info $msg verbosity=$verbosity $(exs...))) + return restore_callsite_source_position!( + esc(:($Base.@info $msg _group=$verbosity $(exs...))), + __source__, + ) end -"""Calls @warn with the passed verbosity level""" macro warnv(verbosity::Int64, msg, exs...) - return esc(:($Base.@warn $msg verbosity=$verbosity $(exs...))) + return restore_callsite_source_position!( + esc(:($Base.@warn $msg _group=$verbosity $(exs...))), + __source__, + ) end -"""Calls @error with the passed verbosity level""" macro errorv(verbosity::Int64, msg, exs...) - return esc(:($Base.@error $msg verbosity=$verbosity $(exs...))) + return restore_callsite_source_position!( + esc(:($Base.@error $msg _group=$verbosity $(exs...))), + __source__, + ) end -"""Calls @error with the passed verbosity level""" macro logmsgv(verbosity::Int64, level, msg, exs...) - return esc(:($Base.@logmsgv $level $msg verbosity=$verbosity $(exs...))) + return restore_callsite_source_position!( + esc(:($Base.@logmsg $level $msg _group=$verbosity $(exs...))), + __source__, + ) +end + +@eval @doc $vlogmacrodocs :(@logmsgv) +@eval @doc $vlogmacrodocs :(@debugv) +@eval @doc $vlogmacrodocs :(@infov) +@eval @doc $vlogmacrodocs :(@warnv) +@eval @doc $vlogmacrodocs :(@errorv) + +""" + LoggingExtras.with(f; level=Info, verbosity=0) + +Convenience function like `Logging.with_logger` to temporarily wrap +the current logger with a level/verbosity 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` and +`verbosity` levels before being passed on to be logged. +""" +function with(f; level::Union{Int, LogLevel}=Info, verbosity::Int=0) + with_logger(EarlyFilteredLogger( + args -> !(args.group isa Int) || verbosity >= args.group, + LevelOverrideLogger(level, current_logger())) + ) do + f() + end end From 99835e1419182f2ec1234f567cff9eae5589a93f Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Wed, 18 May 2022 16:46:30 -0600 Subject: [PATCH 03/15] Add docs --- README.md | 51 +++++++++++++++++++++++++++++++++++++++++++ src/LoggingExtras.jl | 2 +- src/overridelogger.jl | 7 ++++++ 3 files changed, 59 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index 9824a6a..d8da4b1 100644 --- a/README.md +++ b/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. @@ -364,6 +365,56 @@ Main | [Info] This is an informational message. Main | [Warn] This is a warning, should take a look. ``` +## `LevelOverrideLogger` (*Filter*) +Allows overriding the log level set by any nested logger. Useful when debug logging +and used in conjuction with `Logging.with_logger` or `LoggingExtras.with` to +temporarily modify the current logger with a custom level. + +```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 +``` + +# Utilities + +## Verbosity macros +Sometimes when logging, it is desirable to be able to specify a verbosity level in addition to +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.with(f; level=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 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.with(; level=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 diff --git a/src/LoggingExtras.jl b/src/LoggingExtras.jl index 34df6e3..cc8738f 100644 --- a/src/LoggingExtras.jl +++ b/src/LoggingExtras.jl @@ -10,7 +10,7 @@ import Base.CoreLogging: export TeeLogger, TransformerLogger, FileLogger, ActiveFilteredLogger, EarlyFilteredLogger, MinLevelLogger, - DatetimeRotatingFileLogger, FormatLogger, + DatetimeRotatingFileLogger, FormatLogger, LevelOverrideLogger, @debugv, @infov, @warnv, @errorv, @logmsgv ###### diff --git a/src/overridelogger.jl b/src/overridelogger.jl index 8c50cff..4034b12 100644 --- a/src/overridelogger.jl +++ b/src/overridelogger.jl @@ -1,3 +1,10 @@ +""" + 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 From 05fa158b87ab909468a4f55a9e297af3953324ac Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:05:52 -0600 Subject: [PATCH 04/15] Update src/overridelogger.jl Co-authored-by: Frames Catherine White --- src/overridelogger.jl | 1 + 1 file changed, 1 insertion(+) diff --git a/src/overridelogger.jl b/src/overridelogger.jl index 4034b12..49fc47b 100644 --- a/src/overridelogger.jl +++ b/src/overridelogger.jl @@ -15,6 +15,7 @@ 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 From 0d549f2df0b48ebf65b752422f8f99ec6e60a88b Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:06:11 -0600 Subject: [PATCH 05/15] Update README.md Co-authored-by: Frames Catherine White --- README.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/README.md b/README.md index d8da4b1..e375000 100644 --- a/README.md +++ b/README.md @@ -381,6 +381,9 @@ julia> with_logger(logger) do ┌ 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 From 8d0069c12da60ac6934d04221b0e9975fb216a5f Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:06:23 -0600 Subject: [PATCH 06/15] Update README.md Co-authored-by: Frames Catherine White --- README.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index e375000..b4c397e 100644 --- a/README.md +++ b/README.md @@ -366,7 +366,8 @@ Main | [Warn] This is a warning, should take a look. ``` ## `LevelOverrideLogger` (*Filter*) -Allows overriding the log level set by any nested logger. Useful when debug logging +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.with` to temporarily modify the current logger with a custom level. From fb99b13591f50f36853a1643bade07b688d05bc1 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:06:39 -0600 Subject: [PATCH 07/15] Update README.md Co-authored-by: Frames Catherine White --- README.md | 1 + 1 file changed, 1 insertion(+) diff --git a/README.md b/README.md index b4c397e..2e3a870 100644 --- a/README.md +++ b/README.md @@ -370,6 +370,7 @@ 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.with` 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 From a0a489e9fb9ac275394bb23180c835fa1a3a3889 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:09:31 -0600 Subject: [PATCH 08/15] Update src/verbosity.jl Co-authored-by: Frames Catherine White --- src/verbosity.jl | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index d5b5f1a..ba636d7 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -17,7 +17,9 @@ vlogmacrodocs = """ additional verbosity level `N` is passed to indicate differing verbosity levels for a given log level. The verbosity argument is passed as the `group` argument to the core logging logic, so care should be taken if other loggers are being used -that also use the group argument (which by default is passed the source file). +that also use the group argument. +Note: by default group is passed as the source file, however it is poor practice to rely on this in the first place. +Instead use the file argument for that. The default logger doesn't have support for filtering on the `group` argument, so an `LoggingExtras.EarlyFilteredLogger` can be used. For convenience, a From 84fa4cee3e12ff51de5de8e0138d067fc77dc656 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:09:39 -0600 Subject: [PATCH 09/15] Update README.md Co-authored-by: Frames Catherine White --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 2e3a870..82f1ad4 100644 --- a/README.md +++ b/README.md @@ -401,7 +401,7 @@ non-verbose counterparts, but allow specifying a verbosity level as well: For verbosity filtering, the `LoggingExtras.with(f; level=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 control in debug logging for long-running or complex user API function +This is very handy for allowing finer grained control in debug logging for long-running or complex user API function calls. For example: ```julia From 358652fbf5866e8ea84ba72e806fce156f9d5584 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 10:45:31 -0600 Subject: [PATCH 10/15] Update src/verbosity.jl Co-authored-by: Frames Catherine White --- src/verbosity.jl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index ba636d7..a313995 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -21,8 +21,8 @@ that also use the group argument. Note: by default group is passed as the source file, however it is poor practice to rely on this in the first place. Instead use the file argument for that. -The default logger doesn't have support for filtering on the `group` argument, -so an `LoggingExtras.EarlyFilteredLogger` can be used. For convenience, a +An `LoggingExtras.EarlyFilteredLogger`can then be used to filter on the `group` argument. +For convenience, the [`LoggintExtras.with(f; level, verbosity)`](@ref) function is provided to temporarily wrap the current logger with a level/verbosity filter while `f` is executed. """ From 6d92532def4da9f6886cff0015f6dd353e5347d7 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 14:31:49 -0600 Subject: [PATCH 11/15] add tests --- test/runtests.jl | 39 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 39 insertions(+) diff --git a/test/runtests.jl b/test/runtests.jl index eca0776..0d5fe39 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -223,6 +223,45 @@ end @test !logger.always_flush 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 logger.logs[1].group == 1 + + logger = TestLogger(min_level=Info) + with_logger(logger) do + LoggingExtras.with(level=Debug) do + @debug "debug message" + end + end + @test logger.logs[1].level == Debug + + logger = TestLogger(min_level=Info) + with_logger(logger) do + LoggingExtras.with(level=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 all(x -> x.level == Debug, logger.logs) + @test map(x -> x.group, logger.logs) == [0, 1] +end + @testset "Deprecations" begin testlogger = TestLogger(min_level=BelowMinLevel) From 8e84a78e0ed4f94dd6cb7bc6f1ba330b852617f8 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 19 May 2022 14:37:36 -0600 Subject: [PATCH 12/15] fix 32-bit --- src/verbosity.jl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index a313995..64c0775 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -27,35 +27,35 @@ For convenience, the wrap the current logger with a level/verbosity filter while `f` is executed. """ -macro debugv(verbosity::Int64, msg, exs...) +macro debugv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@debug $msg _group=$verbosity $(exs...))), __source__, ) end -macro infov(verbosity::Int64, msg, exs...) +macro infov(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@info $msg _group=$verbosity $(exs...))), __source__, ) end -macro warnv(verbosity::Int64, msg, exs...) +macro warnv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@warn $msg _group=$verbosity $(exs...))), __source__, ) end -macro errorv(verbosity::Int64, msg, exs...) +macro errorv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@error $msg _group=$verbosity $(exs...))), __source__, ) end -macro logmsgv(verbosity::Int64, level, msg, exs...) +macro logmsgv(verbosity::Int, level, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@logmsg $level $msg _group=$verbosity $(exs...))), __source__, From 73f17b8ace3d13db00a7e925483a1d9776c7eb7a Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Tue, 24 May 2022 10:03:47 -0600 Subject: [PATCH 13/15] Avoid using group arg for verbosity and just use more fine-grained log levels --- README.md | 2 +- src/verbosity.jl | 46 ++++++++++++++++++++++++---------------------- test/runtests.jl | 5 ++--- 3 files changed, 27 insertions(+), 26 deletions(-) diff --git a/README.md b/README.md index 82f1ad4..7749f99 100644 --- a/README.md +++ b/README.md @@ -390,7 +390,7 @@ The `LevelOverrideLogger` lets you *lower* (or *raise*) the level of the wrapped # Utilities ## Verbosity macros -Sometimes when logging, it is desirable to be able to specify a verbosity level in addition to +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: diff --git a/src/verbosity.jl b/src/verbosity.jl index 64c0775..f0e795c 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -15,49 +15,46 @@ vlogmacrodocs = """ "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 passed as the `group` argument -to the core logging logic, so care should be taken if other loggers are being used -that also use the group argument. -Note: by default group is passed as the source file, however it is poor practice to rely on this in the first place. -Instead use the file argument for that. +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.EarlyFilteredLogger`can then be used to filter on the `group` argument. +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 level/verbosity filter while `f` is executed. +wrap the current logger with a log level and verbosity subtracted to filter while `f` is executed. """ macro debugv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@debug $msg _group=$verbosity $(exs...))), + esc(:($Base.@logmsg (Logging.Debug - $verbosity) $msg $(exs...))), __source__, ) end macro infov(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@info $msg _group=$verbosity $(exs...))), + esc(:($Base.@logmsg (Logging.Info - $verbosity) $msg $(exs...))), __source__, ) end macro warnv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@warn $msg _group=$verbosity $(exs...))), + esc(:($Base.@logmsg (Logging.Warn - $verbosity) $msg $(exs...))), __source__, ) end macro errorv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@error $msg _group=$verbosity $(exs...))), + esc(:($Base.@logmsg (Logging.Error - $verbosity) $msg $(exs...))), __source__, ) end macro logmsgv(verbosity::Int, level, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg $level $msg _group=$verbosity $(exs...))), + esc(:($Base.@logmsg ($level - $verbosity) $msg $(exs...))), __source__, ) end @@ -69,19 +66,24 @@ end @eval @doc $vlogmacrodocs :(@errorv) """ - LoggingExtras.with(f; level=Info, verbosity=0) + LoggingExtras.with(f; level=Info) Convenience function like `Logging.with_logger` to temporarily wrap -the current logger with a level/verbosity filter while `f` is executed. +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` and -`verbosity` levels before being passed on to be logged. +log messages will first be checked that they meet the `level` +log level before being passed on to be logged. """ -function with(f; level::Union{Int, LogLevel}=Info, verbosity::Int=0) - with_logger(EarlyFilteredLogger( - args -> !(args.group isa Int) || verbosity >= args.group, - LevelOverrideLogger(level, current_logger())) - ) do - f() +function with(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 diff --git a/test/runtests.jl b/test/runtests.jl index 0d5fe39..acc8113 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -239,7 +239,7 @@ end with_logger(logger) do @infov 1 "info 1 message" end - @test logger.logs[1].group == 1 + @test isempty(logger.logs) logger = TestLogger(min_level=Info) with_logger(logger) do @@ -258,8 +258,7 @@ end end end @test length(logger.logs) == 2 - @test all(x -> x.level == Debug, logger.logs) - @test map(x -> x.group, logger.logs) == [0, 1] + @test map(x -> x.level, logger.logs) == [Debug, Debug-1] end @testset "Deprecations" begin From caf7b942cd38a9c30906b2a36cb623d9bcf95424 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Fri, 27 May 2022 12:38:57 -0600 Subject: [PATCH 14/15] address review comments --- README.md | 6 +++--- src/overridelogger.jl | 1 + src/verbosity.jl | 18 ++++++++++-------- test/runtests.jl | 4 ++-- 4 files changed, 16 insertions(+), 13 deletions(-) diff --git a/README.md b/README.md index 7749f99..db6d69c 100644 --- a/README.md +++ b/README.md @@ -368,7 +368,7 @@ 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.with` to +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`). @@ -399,7 +399,7 @@ non-verbose counterparts, but allow specifying a verbosity level as well: * `@warnv N msg` * `@errorv N msg` -For verbosity filtering, the `LoggingExtras.with(f; level=Info, verbosity=0)` utlility is provided +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: @@ -408,7 +408,7 @@ calls. For example: using LoggingExtras function complex_user_call(; verbose=0) - LoggingExtras.with(; level=Debug, verbosity=verbose) + 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" diff --git a/src/overridelogger.jl b/src/overridelogger.jl index 49fc47b..fa612e5 100644 --- a/src/overridelogger.jl +++ b/src/overridelogger.jl @@ -16,6 +16,7 @@ handle_message(logger::LevelOverrideLogger, args...; kwargs...) = function shouldlog(logger::LevelOverrideLogger, level, args...) # Ignore the logger.logger's own level and instead check the override level + @show level, logger.level level >= logger.level && shouldlog(logger.logger, level, args...) end diff --git a/src/verbosity.jl b/src/verbosity.jl index f0e795c..f83c129 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -1,4 +1,7 @@ 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) @@ -24,6 +27,7 @@ For convenience, the 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...))), @@ -31,6 +35,7 @@ macro debugv(verbosity::Int, msg, exs...) ) end +"$vlogmacrodocs" macro infov(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@logmsg (Logging.Info - $verbosity) $msg $(exs...))), @@ -38,6 +43,7 @@ macro infov(verbosity::Int, msg, exs...) ) end +"$vlogmacrodocs" macro warnv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@logmsg (Logging.Warn - $verbosity) $msg $(exs...))), @@ -45,6 +51,7 @@ macro warnv(verbosity::Int, msg, exs...) ) end +"$vlogmacrodocs" macro errorv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@logmsg (Logging.Error - $verbosity) $msg $(exs...))), @@ -52,6 +59,7 @@ macro errorv(verbosity::Int, msg, exs...) ) end +"$vlogmacrodocs" macro logmsgv(verbosity::Int, level, msg, exs...) return restore_callsite_source_position!( esc(:($Base.@logmsg ($level - $verbosity) $msg $(exs...))), @@ -59,14 +67,8 @@ macro logmsgv(verbosity::Int, level, msg, exs...) ) end -@eval @doc $vlogmacrodocs :(@logmsgv) -@eval @doc $vlogmacrodocs :(@debugv) -@eval @doc $vlogmacrodocs :(@infov) -@eval @doc $vlogmacrodocs :(@warnv) -@eval @doc $vlogmacrodocs :(@errorv) - """ - LoggingExtras.with(f; level=Info) + 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. @@ -74,7 +76,7 @@ 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 with(f; level::Union{Int, LogLevel}=Info, verbosity::Integer=0) +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 diff --git a/test/runtests.jl b/test/runtests.jl index acc8113..091df17 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -243,7 +243,7 @@ end logger = TestLogger(min_level=Info) with_logger(logger) do - LoggingExtras.with(level=Debug) do + LoggingExtras.withlevel(Debug) do @debug "debug message" end end @@ -251,7 +251,7 @@ end logger = TestLogger(min_level=Info) with_logger(logger) do - LoggingExtras.with(level=Debug, verbosity=1) do + LoggingExtras.withlevel(Debug; verbosity=1) do @debugv 0 "debug 0 message" @debugv 1 "debug 1 message" @debugv 2 "debug 2 message" From b20b42ec09b1c542259623c50067de00570c4042 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Fri, 27 May 2022 13:44:32 -0600 Subject: [PATCH 15/15] add broken test --- src/overridelogger.jl | 1 - test/runtests.jl | 10 ++++++++++ 2 files changed, 10 insertions(+), 1 deletion(-) diff --git a/src/overridelogger.jl b/src/overridelogger.jl index fa612e5..49fc47b 100644 --- a/src/overridelogger.jl +++ b/src/overridelogger.jl @@ -16,7 +16,6 @@ handle_message(logger::LevelOverrideLogger, args...; kwargs...) = function shouldlog(logger::LevelOverrideLogger, level, args...) # Ignore the logger.logger's own level and instead check the override level - @show level, logger.level level >= logger.level && shouldlog(logger.logger, level, args...) end diff --git a/test/runtests.jl b/test/runtests.jl index 091df17..d5e50c9 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -259,6 +259,16 @@ 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