Skip to content

Reimplement contextLog to populate MDC even when disabled #907

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

Conversation

bcarter97
Copy link

My attempt at solving #868.

  • Populate the MDC even if isEnabled resolves in false
    • This is tested by implementing a TestLogger that will update some state with the current MDC value every time the <level>isEnabled is checked, to assert it is updated even if the check resolves to false
  • Changed the error handling to be more functional
    • not sure if this will impact performance? It will result in a few more flatMaps.

@danicheg
Copy link
Member

danicheg commented Apr 5, 2025

@morgen-peschke Would you mind reviewing this PR?

move state to local logger
@morgen-peschke
Copy link
Contributor

not sure if this will impact performance? It will result in a few more flatMaps.

Took a minute to confirm my suspicion here, but the concern isn't the performance, it's that the MDC is a thread-local construct and multiple fibers can share the same thread. Manipulating the MD needs to be done within a single Sync[F].delay block to prevent multiple loggers from clobbering the MDC.

Something like this would be trouble:

  1. Logger A clears the MDC and yields
  2. Logger B clears the MDC and yields
  3. Logger A populates the MDC and yields
  4. Logger B populates the MDC and yields
  5. Logger A logs a message with the combined context and yields
  6. Logger A resets the MDC and yields
  7. Logger B logs a message without it's context and yields
  8. Logger B resets the MDC and yields

@bcarter97
Copy link
Author

not sure if this will impact performance? It will result in a few more flatMaps.

Took a minute to confirm my suspicion here, but the concern isn't the performance, it's that the MDC is a thread-local construct and multiple fibers can share the same thread. Manipulating the MD needs to be done within a single Sync[F].delay block to prevent multiple loggers from clobbering the MDC.

Something like this would be trouble:

1. Logger A clears the `MDC` and yields

2. Logger B clears the `MDC` and yields

3. Logger A populates the `MDC` and yields

4. Logger B populates the `MDC` and yields

5. Logger A logs a message with the combined context and yields

6. Logger A resets the `MDC` and yields

7. Logger B logs a message without it's context and yields

8. Logger B resets the `MDC` and yields

Riight I see, that makes sense. I am now a bit unsure how to implement this in one effect, as I think we need:

  1. Set MDC
  2. Do log
  3. backup MDC

This worked before because isEnabled was done as step one. But to properly set the MDC before the log is called (which is needed for TurboFilters to work) it has to be second. Do you have any ideas on how this could work? I will continue to have a look into this as well.

@armanbilge
Copy link
Member

Do you have any ideas on how this could work? I will continue to have a look into this as well.

@bcarter97 here's a possible idea you can explore. In Cats Effect v3.6.0, we introduced the ability to create a ThreadLocal "view" that is backed by an IOLocal. This guarantees that the ThreadLocal behaves consistently across flatMaps even as Fibers move between threads.

https://github.com/typelevel/cats-effect/blob/553fdbbe62349a0d059213ed7af099db2cd98af4/core/jvm/src/main/scala/cats/effect/IOLocalPlatform.scala#L23-L29

The part I'm less sure about, that you should explore, is if it's possible to make a custom MDC implementation that is based on the IOLocal-backed ThreadLocal. We were able to do this in otel4s.

@morgen-peschke
Copy link
Contributor

morgen-peschke commented Apr 10, 2025

I think that, with a bit of restructuring, we can get there without major structural changes outside of Sl4jLoggerInternal.

I was poking at it and ended up with #910, and it looks like it might do what you need.

@bcarter97
Copy link
Author

I think that, with a bit of restructuring, we can get there without major structural changes outside of Sl4jLoggerInternal.

I was poking at it and ended up with #910, and it looks like it might do what you need.

Yeah I was doing some digging and I don't think it will be possible with only 1 effect without exposing the logger's isEnabled check.

@armanbilge I had a look at how this could be done with IOLocal - slf4j exposes an SPI for MDCAdapter. I've looked at how Otel4s does this with IOLocalContextStorage, but I can't say I'm very confident I'd be able to replicate something similar.

I think I'll close this PR in favour of #910, as the implementation is flawed.

@bcarter97 bcarter97 closed this Apr 12, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants