From 78484d99915f993fa2621de780996a38efcef68a Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 20 Oct 2022 22:59:21 -0600 Subject: [PATCH 1/4] Switch verbosity macros to use group argument As noted in [this comment](https://github.com/JuliaLogging/LoggingExtras.jl/pull/64/files#r903295686), there's currently a semantic error with the verbosity macros where even if my verbosity is explicitly set to 0 or 1, but my log level is `Info`, then a message like: ```julia @errorv 2 "more detailed error message than you normally want to see" ``` will still be logged, since the current logic just does `Error - 2`. With the change proposed in this PR, we get the following change in behavior: * If `LoggingExtras.withlevel` or an alternative filter doesn't inspect the group.verbosity argument, then the verbose macros act just like the normal logging macros * If `withlevel` _is_ used, then the above case acts as expected; i.e. the `@errorv 2 msg` case only logs if `withlevel(Info; verbosity=2)` is set. I opted to wrap the verbosity level in a new `LoggingExtras.Verbosity` struct so that if the `group` argument is ever used for something else as an `Int`, it won't accidentally conflict with the verbosity filtering. We'll still clobber that argument if anyone else tries to use it, but it shouldn't affect cases where people _aren't_ using the verbosity macros. Fixes https://github.com/JuliaWeb/HTTP.jl/issues/938. --- src/verbosity.jl | 44 ++++++++++++++++++++++++-------------------- test/runtests.jl | 6 ++++-- 2 files changed, 28 insertions(+), 22 deletions(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index f83c129..dd8a1a4 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -18,19 +18,24 @@ 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 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`. +for a given log level. The verbosity argument is passed as the `group` argument +to the core logging logic as a `LoggingExtras.Verbosity` object. -An `LoggingExtras.LevelOverrideLogger`can then be used to filter on the `level` argument. +Note these "verbose" logging messages will only be filtered if a filter logger is used. +A `LoggingExtras.EarlyFilteredLogger`can be used to filter on the `group.verbosity` 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. +[`LoggintExtras.withlevel(f, level; verbosity)`](@ref) function is provided to temporarily +wrap the current logger with a log level and verbosity to filter while `f` is executed. """ +struct Verbosity + verbosity::Int +end + "$vlogmacrodocs" macro debugv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg (Logging.Debug - $verbosity) $msg $(exs...))), + esc(:($Base.@debug $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), __source__, ) end @@ -38,7 +43,7 @@ end "$vlogmacrodocs" macro infov(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg (Logging.Info - $verbosity) $msg $(exs...))), + esc(:($Base.@info $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), __source__, ) end @@ -46,7 +51,7 @@ end "$vlogmacrodocs" macro warnv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg (Logging.Warn - $verbosity) $msg $(exs...))), + esc(:($Base.@warn $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), __source__, ) end @@ -54,7 +59,7 @@ end "$vlogmacrodocs" macro errorv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg (Logging.Error - $verbosity) $msg $(exs...))), + esc(:($Base.@error $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), __source__, ) end @@ -62,7 +67,7 @@ end "$vlogmacrodocs" macro logmsgv(verbosity::Int, level, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg ($level - $verbosity) $msg $(exs...))), + esc(:($Base.@logmsg $level $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), __source__, ) end @@ -75,17 +80,16 @@ 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. + +For convenience, a `verbosity` keyword argument can be passed which also +filters the "verbose logging" messages; see [`@debugv`](@ref), [`@infov`](@ref), +[`@warnv`](@ref), [`@errorv`](@ref), and [`@logmsgv`](@ref). """ 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 + with_logger(EarlyFilteredLogger( + args -> !(args.group isa Verbosity) || verbosity >= args.group.verbosity, + LevelOverrideLogger(level, current_logger())) + ) do + f() end end diff --git a/test/runtests.jl b/test/runtests.jl index 544aac7..3633691 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -255,7 +255,8 @@ end with_logger(logger) do @infov 1 "info 1 message" end - @test isempty(logger.logs) + # if no verbosity filter is used, message is just like @info + @test !isempty(logger.logs) logger = TestLogger(min_level=Info) with_logger(logger) do @@ -274,7 +275,8 @@ end end end @test length(logger.logs) == 2 - @test map(x -> x.level, logger.logs) == [Debug, Debug-1] + @test logger.logs[1].group == LoggingExtras.Verbosity(0) + @test logger.logs[2].group == LoggingExtras.Verbosity(1) logger = TestLogger(min_level=Info) with_logger(logger) do From c1374010f648266fd440b97b7ee00e1e61249481 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Thu, 20 Oct 2022 23:13:08 -0600 Subject: [PATCH 2/4] additional test --- test/runtests.jl | 3 +++ 1 file changed, 3 insertions(+) diff --git a/test/runtests.jl b/test/runtests.jl index 3633691..0024392 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -272,6 +272,9 @@ end @debugv 0 "debug 0 message" @debugv 1 "debug 1 message" @debugv 2 "debug 2 message" + # error message *also* isn't logged since + # level *and* verbosity must match + @errorv 2 "error 2 message" end end @test length(logger.logs) == 2 From 04b6ab0af30a54a6edf53b4e3b8b43f744e1a18e Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Fri, 21 Oct 2022 14:41:20 -0600 Subject: [PATCH 3/4] Update src/verbosity.jl Co-authored-by: Frames Catherine White --- src/verbosity.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index dd8a1a4..d0e2e70 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -35,7 +35,7 @@ end "$vlogmacrodocs" macro debugv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@debug $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), + :($Base.@debug $msg _group=$(Verbosity(verbosity)) $(esc.(exs)...))), __source__, ) end From 9256f48ea91f0592db4c5732d3c2fed8d1dc7915 Mon Sep 17 00:00:00 2001 From: Jacob Quinn Date: Fri, 21 Oct 2022 14:51:29 -0600 Subject: [PATCH 4/4] inject Verbosity into quote expansion --- src/verbosity.jl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/verbosity.jl b/src/verbosity.jl index d0e2e70..e3f41ab 100644 --- a/src/verbosity.jl +++ b/src/verbosity.jl @@ -35,7 +35,7 @@ end "$vlogmacrodocs" macro debugv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - :($Base.@debug $msg _group=$(Verbosity(verbosity)) $(esc.(exs)...))), + esc(:($Base.@debug $msg _group=$(Verbosity(verbosity)) $(exs...))), __source__, ) end @@ -43,7 +43,7 @@ end "$vlogmacrodocs" macro infov(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@info $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), + esc(:($Base.@info $msg _group=$(Verbosity(verbosity)) $(exs...))), __source__, ) end @@ -51,7 +51,7 @@ end "$vlogmacrodocs" macro warnv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@warn $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), + esc(:($Base.@warn $msg _group=$(Verbosity(verbosity)) $(exs...))), __source__, ) end @@ -59,7 +59,7 @@ end "$vlogmacrodocs" macro errorv(verbosity::Int, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@error $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), + esc(:($Base.@error $msg _group=$(Verbosity(verbosity)) $(exs...))), __source__, ) end @@ -67,7 +67,7 @@ end "$vlogmacrodocs" macro logmsgv(verbosity::Int, level, msg, exs...) return restore_callsite_source_position!( - esc(:($Base.@logmsg $level $msg _group=LoggingExtras.Verbosity($verbosity) $(exs...))), + esc(:($Base.@logmsg $level $msg _group=$(Verbosity(verbosity)) $(exs...))), __source__, ) end