Enabled: always must skip two levels #216
Conversation
|
Let's not merge yet! I first want to add test cases in klog for |
| // the original logging site (e.g. file & line) should climb this many | ||
| // additional frames to find it. | ||
| // | ||
| // The CallDepth is given for LogSink.Info and LogSink.Error such that 1 means |
There was a problem hiding this comment.
Is this now fixed (Info -> enabled parallel to Enabled -> enabled)?
There was a problem hiding this comment.
Yes.
I have a test for this in kubernetes/klog#383. That test fails with current logr and passes with this PR.
We can merge it now.
There was a problem hiding this comment.
Shouldn't we remove this part of the comment?
klog does stack unwinding in `LogSink.Enabled` to implement per-source code verbosity thresholds (`-vmodule`). This worked for `logger.Info` and `logger.Error` because the code was written such that it matches how logr is implemented (Logger.Info -> Logger.Enabled -> LogSink.Enabled). It did not work for direct calls (`if logger.Enabled`) because then the call chain is `Logger.Enabled -> LogSink.Enabled`. That callchain is less common, so to fix this problem the callchains get arranges so that all calls go through one additional intermediate level. This is unnecessary extra work, but it is necessary to avoid breaking the more common normal logging calls with klog and -vmodule.
pohly
force-pushed
the
enabled-calldepth
branch
from
374a35a
to
a53aadb
Compare
pohly
changed the title
| // enabled ensures that Enabled and Info both call LogSink.Enabled with one | ||
| // intermediate stack frame. This wouldn't be necessary if Info had called | ||
| // LogSink.Enabled directly in logr v1.0.0, but it didn't and now that cannot | ||
| // be changed anymore because implementations depend on this behavior. |
There was a problem hiding this comment.
I'm not sure I understsand the "implementations depend on this behavior" point. It seems like we could either do
(Info, Error, Enabled) -> sink.Enabled
or
(Info, Error, Enabled) -> enabled -> sink.Enabled
And it would be correct, as long as it is consistent - right?
There was a problem hiding this comment.
I'm not sure I understsand the "implementations depend on this behavior" point.
I mean this code:
https://github.com/kubernetes/klog/blob/6632ba5cc9a5331c853a2c6dbc0fbb125e6e7b94/klogr.go#L55-L56
That code works with logr v1.2.0 for logger.Info.
If we switch to (Info, Error, Enabled) -> sink.Enabled, logger.Info will not work correctly in combination with -vmodule anymore when someone uses klog <= v2.100.1 and updates to a future logr release where we made that change.
We can change klog in v2.200.0 and make it depend on such a new logr release, but we cannot prevent the combination above.
And it would be correct, as long as it is consistent - right?
Both are "correct", but (Info, Error, Enabled) -> enabled -> sink.Enabled will cause less pain for downstream users.
There was a problem hiding this comment.
But then we are left with this weird document that Enabled() needs one more frame. I hate it. If it's already buggy, how bad is it really to just fix the bug?
|
Closing in favor of #218 |
klog does stack unwinding in
LogSink.Enabledto implement per-source code verbosity thresholds (-vmodule). This worked forlogger.Infoandlogger.Errorbecause the code was written such that it matches how logr is implemented (Logger.Info -> Logger.Enabled -> LogSink.Enabled).It did not work for direct calls (
if logger.Enabled) because then the call chain isLogger.Enabled -> LogSink.Enabled. That callchain is less common, so to fix this problem the callchains get arranges so that all calls go through one additional intermediate level.This is unnecessary extra work, but it is necessary to avoid breaking the more common normal logging calls with klog and -vmodule.
Fixes: #215