log4cats icon indicating copy to clipboard operation
log4cats copied to clipboard

Unable to use turbo filters dependent on MDC

Open r-glyde opened this issue 1 year ago • 3 comments

We're trying to use logback turbofilters to alter which logs are output based on values in the MDC but this doesn't seem to work properly with log4cats and the slf4j logger implementation. When outputting the MDC as part of the log I can see it includes the correct value but the correct filtering doesn't get applied when trying to output logs below the global log level (e.g. log at DEBUG, set global level to INFO but force ALLOW in the filter). This is with both the MDCFilter and the DynamicThresholdFilter.

This appears to be because in Slf4jLoggerInternal, whenever a logging method is called there is a check of the corresponding is$levelEnabled value which doesn't include updating the MDC in the versions where a context is passed in (e.g. for debug here).

I can't think of a reason we wouldn't want these filters to work (happy to be corrected) so was thinking that in contextLog the MDC should be updated prior to the isEnabled check? Alternative could be to not run the is$levelEnabled checks prior to each log and leave to the user but probably nice that that safety of avoiding running anything expensive if it won't be logged is built in? I've tried these locally (roughly) and they both seem to work as expected. Happy to look at raising a PR for either of these if it makes sense.

Semi-related - in some projects, we're using a custom self aware logger implementation that wraps an underlying logger where the overridden is$levelEnabled methods match what would be enabled in the turbo filter but this is then not used in the end because the check is done within Slf4jLoggerInternal using it's own implementation. I'm not sure if there is anything we can do to avoid this (without some more significant changes to how the logging is implemented) but ends up being a bit confusing that we have two implementations of the method and ours isn't the actual one being used when the check is done?

r-glyde avatar Oct 27 '24 17:10 r-glyde

@rossabaker @danicheg this would be really useful for us, are you ok with this being raised as a PR to discuss?

bcarter97 avatar Jan 28 '25 13:01 bcarter97

We certainly do not block anyone from opening wish PRs, as long as they comply with the license!

danicheg avatar Jan 31 '25 08:01 danicheg

Thanks @danicheg. Will try to look at sorting out sometime soon. Would it make sense to get #850 reviewed and merged first as it's touching a lot of similar code and setting up all the tests that we'll probably have to use/extend for this as well?

r-glyde avatar Jan 31 '25 10:01 r-glyde

@danicheg I have given this a go in #907, if you wouldn't mind reviewing

bcarter97 avatar Apr 05 '25 12:04 bcarter97

This is now available in v2.7.1

morgen-peschke avatar May 26 '25 18:05 morgen-peschke

Thanks for sorting out @morgen-peschke and @bcarter97

r-glyde avatar Jun 09 '25 12:06 r-glyde