typelevel / log4cats

Logging Tools For Interaction with cats-effect
https://typelevel.org/log4cats/
Apache License 2.0
400 stars 73 forks source link

Are values in the MDC intended to be include in the context logged by Slf4jLogger? #851

Open morgen-peschke opened 2 months ago

morgen-peschke commented 2 months ago

While adding tests to Slf4jLogger in #850 I noticed that, every now and again, the tests would fail because extra values would be captured as context.

Looking at the failure, it's the value set in the "Slf4jLoggerInternal resets after logging" test. I didn't see in the docs if this was intended behavior or not, and I could see arguments for either behavior, so I figured it's worth asking about and documenting.

munit.ComparisonFailException: /Users/morgen/learning/log4cats/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala:256
255:      slf4jLogger.error("error(msg)").assert >>
256:      IO(testLogger.logs().asScala.toList).assertEquals(
257:        List(
values are not the same
=> Obtained
List(
  DeferredStructuredLogMessage(LogLevel.Trace,Map(foo -> yellow),None,trace(msg)),
  DeferredStructuredLogMessage(LogLevel.Debug,Map(foo -> yellow),None,debug(msg)),
  DeferredStructuredLogMessage(LogLevel.Info,Map(foo -> yellow),None,info(msg)),
  DeferredStructuredLogMessage(LogLevel.Warn,Map(foo -> yellow),None,warn(msg)),
  DeferredStructuredLogMessage(LogLevel.Error,Map(foo -> yellow),None,error(msg))
)
=> Diff (- obtained, + expected)
 List(
-  DeferredStructuredLogMessage(LogLevel.Trace,Map(foo -> yellow),None,trace(msg)),
-  DeferredStructuredLogMessage(LogLevel.Debug,Map(foo -> yellow),None,debug(msg)),
-  DeferredStructuredLogMessage(LogLevel.Info,Map(foo -> yellow),None,info(msg)),
-  DeferredStructuredLogMessage(LogLevel.Warn,Map(foo -> yellow),None,warn(msg)),
-  DeferredStructuredLogMessage(LogLevel.Error,Map(foo -> yellow),None,error(msg))
+  DeferredStructuredLogMessage(LogLevel.Trace,Map(),None,trace(msg)),
+  DeferredStructuredLogMessage(LogLevel.Debug,Map(),None,debug(msg)),
+  DeferredStructuredLogMessage(LogLevel.Info,Map(),None,info(msg)),
+  DeferredStructuredLogMessage(LogLevel.Warn,Map(),None,warn(msg)),
+  DeferredStructuredLogMessage(LogLevel.Error,Map(),None,error(msg))
 )
rossabaker commented 2 months ago

Is it because it's based on thread local storage? Is that test supposed to run on the "dirty stuff" I kneejerkily tried to remove in #852, to quarantine it from polluting any other test?

rossabaker commented 2 months ago

I don't have time at the moment to dig deep into the intent, but I'd start exploring the git history hereabouts?

morgen-peschke commented 2 months ago

There isn't much, unfortunately, just that it shouldn't be blocking, and that there was a bug a while back that would clear the MDC before logging happened.

I can fix the test pretty easily by clearing the MDC before each test, but I didn't want to do that if this is actually a bug 🤷🏻

I could fix it in the test, and we can leave this issue open until someone remembers what the intended behavior is (because I can definitely see good arguments for either behavior)

morgen-peschke commented 2 months ago

Talked with @ChristopherDavenport , and he indicated the intent was to only include the information in the context.

If there are no objections, I can adjust the current implementation to align with this.