Switch verbosity macros to use group argument (#73)

* 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 JuliaWeb/HTTP.jl#938.

* additional test

* Update src/verbosity.jl

Co-authored-by: Frames Catherine White <[email protected]>

* inject Verbosity into quote expansion

Co-authored-by: Frames Catherine White <[email protected]>

Author: quinnj

src/verbosity.jl

@@ -18,51 +18,56 @@ 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=$(Verbosity(verbosity)) $(exs...))),
         __source__,
     )
 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=$(Verbosity(verbosity)) $(exs...))),
         __source__,
     )
 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=$(Verbosity(verbosity)) $(exs...))),
         __source__,
     )
 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=$(Verbosity(verbosity)) $(exs...))),
         __source__,
     )
 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=$(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

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
@@ -271,10 +272,14 @@ 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
-    @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