-
Notifications
You must be signed in to change notification settings - Fork 21
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Alternative approach to debug logging utilities. #64
Conversation
Alternative to what's proposed in JuliaLogging#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.
I like the idea of I will think more and reply more |
The verbosity stuff kind of seems like it is replicating the numerical priority stuff (which is mixed in with the categorical log level). |
I'm not quite following you here; the verbosity is meant as a 2nd axis along which we can have a numerical ordering of log messages, in addition to the log level. It's like a sub-ordering for each log level that we can filter on. In my previous PR, it was just Yeah, I agree it's a little unfortunate that we can't use |
As an additional note: I think the |
I believe this is because
Yes, I am tempted to say YAGNI, and suggest we defer this solution until we are sure your previous solution of just extra levels of |
Ok, just pushed a cleanup. Sorry for the continual churn, but I'm a boulder rolling down the logging mountain right now and my rough edges are getting chipped off along the way. I realized that being able to do the So here's the latest iteration; changes include:
As an FYI, I'm working on active branches of HTTP.jl/CSV.jl/Arrow.jl while iterating here and porting things over to this new system; hence the evolutions as I run into things here and there. |
No, this is good.
No, this is fine. IMO, group should default to The problem with |
Yes! Very much. Ok, I like how this has ended up here. @oxinabox are you ok w/ what's here now? I can add some tests in the morning, but I've gotten the HTTP.jl logging story in pretty good shape and I'd like to get it merged up. |
I will try and take a look in a few hours. Ping me on slack if I don't. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't really understand the second axis and why it is necessary? It seems like all verbosity type messages should be various debug levels instead? How can an error, for example, be important just in verbose mode?
handle_message(logger.logger, args...; kwargs...) | ||
|
||
function shouldlog(logger::LevelOverrideLogger, level, args...) | ||
level >= logger.level && shouldlog(logger.logger, level, args...) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This doesn't seem to override?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The 1st way it overrides is by only returning its own level
from min_enabled_level
(other loggers typically return the max
of itself and child loggers). Also in this case, it's only checking its own level and then dispatching to it's nested logger shouldlog
; as far as I understand, loggers don't typically check levels in shouldlog
because it happens before w/ min_enabled_level
.
We're also just overriding the level; if there are other filters from the nested logger, then those will still be respected. If the nested logger does check levels in their shouldlog
, then those will be respected. It's a bit tricky because it's hard to know exactly what the nested logger is going to do in shouldlog
, but from initial tests, this seems to be working as expected.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It looks like the comp_shouldlog
which is called by all the composable loggers in the package checks both level
and shouldlog
.
LoggingExtras.jl/src/LoggingExtras.jl
Line 35 in 396afbb
min_enabled_level(logger) <= level && shouldlog(logger, args...) |
There is a comment above it saying that because the loggering system itself won't check the level
of child loggers.
I think I ran into a bug before I had this with something like TeeLogger(MinLevelFilter(Debug, ...), MinLevelFilter(Warn, ...))
Which should have the TeeLogger
saying it's minlevel is Debug
since it needs to recieve Debug level messages.
But then those need only to be accepted by one of the loggers and not by the other.
I think this can possibly be fixed by moving the logic from the recieving logger, up into the sending logger.
Which would better match how the logging system works outside the compositional structure.
So it only forwards to children that say they can accept it.
(vs right now where the child decides that it won't log it because of it's level)
I could be wrong here and this could all work
A test would prove it one way or the other
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Can a test be added to check this case please
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This shouldlog
method is exercised in the tests here:
LoggingExtras.jl/test/runtests.jl
Line 254 in 73f17b8
LoggingExtras.with(level=Debug, verbosity=1) do |
Debug
level is "overriding" the TestLogger Info
level.
Is there a more specific/different test desired here?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yes,
I want to see:
LoggingExtras.with(level=Debug, verbosity=1) do
with_logger(MinLevelLogger(Info, test_logger)) do
@debug "This should show up, even though it is behind 2 info level filters"
end
end
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm not sure this can be made to work due to the way MinLevelLogger has it's shouldlog
and min_level_enabled
defined; i.e. the presence of a MinLevelLogger
in a stack of loggers effectively "poisons" any other kind of level filtering. It's min_enabled_level
calls max
of its own level and its child logger, so it's going to raise the level of a LevelOverrideLogger. And because MinLevelLogger shouldlog
calls comp_shouldlog
of its child logger, and because comp_shouldlog
checks the min_enabled_level
of the child logger, it means LevelOverrideLogger gets overridden, even if we were to get back the min_enabled check.
It's a similar issue if LevelOverride wraps a MinLevelLogger; the LevelOverride will pass the level check, but then it calls the shouldlog
of its child logger and the MinLevelLogger
will "take over" as mentioned above.
I don't see an immediate/easy way to detangle all that without going big with an overhaul of all the other compositional loggers here, so I'm inclined to just put a note in the docs that the LevelOverrideLogger should be used independently from other level-filtering loggers.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think I know how to fix it.
Which is a big overhaul of all the other compositional loggers.
But I don't think it will take me long.
Let's put that test case in.
Mark it broken, and open an issue cross referencing it, then merge this.
Then later tonight or tomorrow I will fix it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ok, added the broken test.
I initially tried making them extra log levels, but you run into at least one awkwardness in that the global IMO, it's come to make sense because for a given log level, I sometimes just want to specify that certain messages will be spit out a higher verbosity levels than others. Sure it probably makes the most sense for Debug, but lets even take Here's the HTTP.jl draft PR where you can see how these verbose levels are used in a real setting: JuliaWeb/HTTP.jl#826. |
This seems like a bug in Base. If it is just ignoring what your logger says what is even the point? |
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Co-authored-by: Frames Catherine White <oxinabox@ucc.asn.au>
Ok, added tests. This is good to go from my perspective. |
I mean, you have 1000 debug levels to work with (https://julialogging.github.io/tutorials/logging-basics/#Log-levels):
so you could use e.g. |
Yeah, I guess we could still try to use log level for this. Honestly it's just a bit more awkward in the following ways:
Neither of these are deal-breakers. It would have the advantage of not "hijacking" the |
My instinct is that this is the better way to go. In particular, that what one ones is numerical verbosity for the debug debug levels. There is one place in Base that does infact use
I feel like we must be able to overload something to fix that, no? Cross-ref also JuliaLang/julia#33418 |
This would be a nice enhancement to Base, but not possible as of now. Apologize if I'm just slow over here (it's first thing in the morning for me), but @oxinabox, are you in favor of sticking just with log levels for the functionality here? Or in favor of using the |
Looking at the HTTP PR, I guess the main motivation here is to have a way for users to pass a verbosity level and have that "upgrade" the visibility of messages. Is that correct? The "pure" way would be to have HTTP always emit messages and have the user install a logger with the proper log levels for increasing the visibility of messages. |
I am in favor of log levels for the functionality here.
Or HTTP could install a compositional logger via Aside: we have an example for doing this via transformer logger in read me |
Yes, that's correct.
I think this is a non-starter for 90% of users. It's much too onerous to require every user to understand they have to use So yes, a big part of my work in all this is trying to find the right APIs so that it's as easy/convenient as possible to flip the logging "switches" to enable/disable certain functionality. I think the current HTTP.jl approach is still "pure" because it's using I'll work on updating this PR to go the log level approach; I agree that it would be nice to avoid hijacking the |
Alternatively HTTP could just emit info-level messages instead of debug-messages for verbose > 0 I suppose? |
Ok, this PR is updated. The "user facing API" didn't change at all, so the usage is still doing It's nice and simple, but my biggest gripe is just that we now get log messages like: ┌ LogLevel(-1001): Set-Cookie: 1P_JAR=2022-05-24-16; expires=Thu, 23-Jun-2022 16:03:11 GMT; path=/; domain=.google.com; Secure (from www.google.com)
└ @ HTTP.CookieRequest ~/.julia/dev/HTTP/src/CookieRequest.jl:86
┌ LogLevel(-1001): Set-Cookie: AEC=AakniGOCHstCJyha30RHuX-l46hunmduqLgWlZg9nc-LKITsjxIWJXDiKA; expires=Sun, 20-Nov-2022 16:03:11 GMT; path=/; domain=.google.com; Secure; HttpOnly; SameSite=lax (from www.google.com)
└ @ HTTP.CookieRequest ~/.julia/dev/HTTP/src/CookieRequest.jl:86
┌ LogLevel(-1001): Set-Cookie: NID=511=lwLMr3GxxeUl2WvNw2j5I35wjflzBVjVGYb3dPs5rZyxLTrBx1NkxR2iXxQEJcXrJlaRjzDzhBXTWeY5aKnJG7-Xoc_ov5JJqNqP-aYGQmhnIaET_BqgyNmSn5UZE-1ncUAXvInXlVS6Tsvbbh9oRDTF6bvuBQeGsio8TDytu4g; expires=Wed, 23-Nov-2022 16:03:11 GMT; path=/; domain=.google.com; HttpOnly (from www.google.com)
└ @ HTTP.CookieRequest ~/.julia/dev/HTTP/src/CookieRequest.jl:86 so the I'd like to get this merged soonish if possible and get a release out so we can get moving on downstream packages if everyone is good to go here. |
|
||
macro debugv(verbosity::Int, msg, exs...) | ||
return restore_callsite_source_position!( | ||
esc(:($Base.@logmsg (Logging.Debug - $verbosity) $msg $(exs...))), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should be
esc(:($Base.@logmsg (Logging.Debug - $verbosity) $msg $(exs...))), | |
esc(:($Base.@logmsg (Logging.Info - $verbosity) $msg $(exs...))), |
right?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't think so?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why not? Now this will not be within the Debug level range
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Or I guess, +
instead of -
.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For me, I think of it like this: there are really two dimensions we're talking about: severity and verbosity. Sometimes, people view the log level severity spectrum as also corresponding to verbosity, but that's not quite right; the severity is more about the type of log, and how it should be seen in various scenarios. i.e. Debug
is for non-normal/production cases where you're trying to see additional development-related information that's going on. Info
is general things that happen/major changes in state or milestones. Warn
is there's something non-fatal that was encountered. Error
is something bad happened.
Verbosity, on the other hand, is the level of detail we want to see for a given severity. Now, I'll readily admit this principle doesn't seem super applicable/useful for non-Debug log levels, but for debugging, it really does make a strong point, and indeed many systems also include a Trace
log level in this vein: sometimes you want even more debug information than Debug
. But I would argue even for Error
or Warn
, there are theoretical cases where you might want to emit more verbose messages than the default if requested by the user (e.g. for an @inbounds
error, maybe I want to see the full collection being indexed, where as by default you almost surely want some kind of compact printing).
All that to say, instead of actually introducing two dimensions for severity and verbosity, we're hijacking the fact that the log levels themselves are so spread out in the integer domain to say that log levels in between the standard severity levels correspond to verbosity instead of actually different categorical/types of logs. So in the same vein of the severity spectrum at least roughly/partly ordered by verbosity (i.e. I would expect more Trace
or Debug
messages than Error
or Warn
), we're saying that Debug - 1
is like Debug
, but one level more verbose. And Debug - 2
is also like debug, but 2 levels more verbose, and 1 more level verbose than Debug - 1
. So the levels less than the severity level, but greater than the next lower severity level constitute the possible "verbosity" levels for that severity level.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this is actually kinda unfortunate positioning.
because we want @debugv 0
to be the same as @debug
and to be the "most significant debug level"
Ideally we would have that Debug +0
is in the middle of the range that highlights as Debug
so that Debug+1
and Debug-1
can both be considered as more or less significant debug-levelled values.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I looked briefly at changing this, but it didn't seem like an easy/obvious fix with my first attempt, mainly because of the directionality of log levels and filtering. Filtering always relies on filtering out lower levels, so it doesn't work to just invert our verbosity to be + instead of -.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, that is why i wish Debug +0
was in the middle of the range that highlights as Debug
.
Can we have this changed up-stream in Julia, and then just live with the bad highlighting until 1.9 comes out?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thinking about this some more, I think I'd like to go back to the approach of using the group
variable for verbosity. I think trying to leverage log levels has just muddied the waters too much. I also realized that there's one feature that "doesn't work" with the log-level approach: if I have a scenario like here, where, in the normal case, I just want to ignore any errors, but if I'm in a "verbose" mode, I'd like to at least log those kinds of errors, it doesn't work w/ our current log-level approach. Because @errorv 2 msg
just becomes LogLevel.Error - 2
, and that means it will always get printed, because it's "above" the default Info
level.
So I think this has clarified in my mind that verbosity is really a 2nd dimension, in addition to log level, that I want to be able to filter on separately. i.e. if my verbosity=1
, then I don't want to see the overly verbose @errorv 2 msg
log. It also cements in my mind that log levels, while kind of a proxy for verbosity, just aren't. They're categorical values that give specific "types" to log messages.
If no one is strongly opposed, I'm going to move the LoggingExtras.@[x]v
macros back to that approach.
I think another benefit of that approach is we should "fix" the log level printing color issue? Since we're not modifying the actual log level at all?
Is it important that the forced messages in HTTP still have debug level? I suppose an alternative would be to just have conditional
etc. This way you can explain the (I am not trying to be difficult, the functionality in this PR just still seems "weird" to me). |
Sorry @fredrikekre, yeah, I can tell you're not really following what I'm going for here. One of the key problems is that, not just in HTTP.jl, but in other packages like CSV.jl and Arrow.jl where we have several nested layers of function calls potentially, we don't want to have to thread the
I don't really see it as "switching" the logger as much as "temporarily wrapping the existing" logger. I'm not really sure what else to tell you on this; these aren't Info-related messages? They're for debugging. The user is passing an additional argument to increase verbosity of printing while a request is happening and the normal "logging" way of doing that is by enabling Debug log messages. I've tried to explain the goals/reasoning here in several posts in this PR already in case you may have missed them. If this ultimately feels too weird to people here, that's fine; as I originally stated in my 1st PR, I'm happy to just make a separate DebugLogging.jl package with just this stuff in it. I was just trying to avoid having another package with a few logging utilities in it and this felt like a more natural home. This has ultimately been very helpful to get @oxinabox's thoughts/review and I've learned and refined the approach from that considerably. |
I agree with these.
This is true and could be done with a It may be worth folks being aware there is actually a set of broadly agreed standards for log levels. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
basically looks good to me.
Resolve my comments as you see fit.
only blocking one is
https://github.com/JuliaLogging/LoggingExtras.jl/pull/64/files#r883899251
which assuming you do and it passes, merge when happy.
If it doesn't ping me on slack and we can workout how to fix this.
Potentially I can PR this PR.
Thanks for all the help @oxinabox! |
Alternative to what's proposed in #63. In particular, the pieces
proposed here include:
@debugv 1 "hey"
=>@debug "hey" verbosity=1
)LevelOverrideLogger
for overriding the level of any nested loggerLoggingExtras.with
function for very easily passing a temporarylog 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:
verbose::Int=0
keyword arg to high-level user-facingAPI 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 verbosedebug 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 canjust wrap the invocation in
LoggingExtras.with
and then sprinkle@debugv N
callsat any nested depth I'd like.
debug logging. I don't have to fiddle with configuring a logger or messing w/ global state,
I just pass
verbose=1
orverbose=3
and any verbose logs will be written out.If this approach sounds reasonable, I can clean up this PR w/ docs/examples/tests.