Logging MDC tags no longer work with logback-classic 1.4.x

[scheleaap]

After upgrading logback-classic from 1.2.11 to 1.4.x, tags set in the Kamon context are no longer included in log messages.

(This problem is similar to #1225, but different: #1225 is about upgrading Kamon, this issue is about upgrading logback-classic.)

At our company, we write log messages in JSON format and add information to the messages through the MDC through Kamon.
We use the latest version of Kamon (2.5.12) with logback-classic and logstash-logback-encoder.

Expected behavior

For example, we add the tag application-startup-marker to a log message when the application is starting up:

object Application extends App with StrictLogging {
  Kamon.init()
  Kamon.runWithContextTag("application-startup-marker", value = true)(logger.info("Application starting..."))
}

For Kamon 2.5.12 + logback-classic 1.2.11, the log message looks as follows:

{"@timestamp":"2022-12-08T10:06:14.701Z","level":"INFO","level_value":20000,"message":"Application starting...",
"logger_name":"foo.Application$","thread_name":"main","caller_class_name":"foo.Application$","caller_method_name":"$anonfun$new$1",
"caller_file_name":"Application.scala","caller_line_number":8,"application-startup-marker":"true"}
                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Actual behavior

However, when we upgrade logback-classic to 1.4.5, the tag suddenly disappears:

{"@timestamp":"2022-12-08T10:07:18.417Z","level":"INFO","level_value":20000,"message":"Application starting...",
"logger_name":"foo.Application$","thread_name":"main","caller_class_name":"foo.Application$","caller_method_name":"$anonfun$new$1",
"caller_file_name":"Application.scala","caller_line_number":8}
                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Minimal example

I have created a minimal example here: https://github.com/scheleaap/kamon-issue. Run with sbt run.

If you change the line

      "ch.qos.logback" % "logback-classic" % "1.4.5",

to

      "ch.qos.logback" % "logback-classic" % "1.2.11",

in build.sbt, you will see the tag reappears.

Conclusion

TBH, we are not sure if this is a problem in Kamon or logback-classic. Any insights you can provide would be valuable.

And thank you for your great help on #1225!

[ivantopo]

Hey @scheleaap 👋

I looked into this and the problem I found is that sometimes the Play instrumentation gets loaded before the logback instrumentation (see image below). When that happens, the Play instrumentation loads the logback classes before they get instrumented and nothing gets copied.

(you can get the same output adding -Dkanela.debug-mode=YES -Dkanela.log-level=DEBUG to your JVM options)

Running your reproducer several times should work every now and then, depending on the order the modules are loaded. You can workaround it with this setting:

kanela.modules.play-framework.order = 3

I'll be opening a PR with that same change, assuming that's the only thing we need to fix it 🙏

[scheleaap]

Hi @ivantopo, thank you for taking a look. I am getting consistent results when I run the example project.

When I add the setting you mentioned I can see that the Logback instrumentation gets loaded before the Play Framework instrumentation, but it does not bring the MDC tag back.

I have updated example project accordingly. Does the application log the MDC tag when you run it on your machine?

For reference, here's my log output:

...
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : The Module: Executor Service Capture on Submit Instrumentation is disabled 
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : The Module: Scala Future Chaining Instrumentation (Deprecated) is disabled 
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : Loading Logback Instrumentation  
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger :  ==> Loading kamon.instrumentation.logback.LogbackInstrumentation  
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : Retransformation Strategy activated for: Logback Instrumentation 
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : Periodic Resubmitter activated. 
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : Loading Play Framework Instrumentation  
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger :  ==> Loading kamon.instrumentation.play.PlayServerInstrumentation  
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger :  ==> Loading kamon.instrumentation.play.PlayClientInstrumentation  
[info] [Attach Listener] INFO 2022-12-14 17:15:13  Logger : Retransformation Strategy activated for: Play Framework Instrumentation 
...
[info] {"@timestamp":"2022-12-14T16:17:31.052Z","level":"INFO","level_value":20000,"message":"Application starting...","logger_name":"foo.Application$","thread_name":"main","caller_class_name":"foo.Application$","caller_method_name":"$anonfun$new$1","caller_file_name":"Application.scala","caller_line_number":8}
[success] Total time: 3 s, completed Dec 14, 2022, 5:17:31 PM

[ivantopo]

I see you are running this from SBT and that might be the issue. Even though you have the fork and javaAgents settings, the only way I was able to make it work when running with SBT was by adding our SBT plugin:

addSbtPlugin("io.kamon" % "sbt-kanela-runner" % "2.0.14")

My previous tests were directly from IntelliJ. You can see two runs here, before/after adding the plugin:

I think it is fair to assume that the ordering change fixes the issue 💪

[scheleaap]

We were able to get everything to work thanks to your suggestions @ivantopo. To summarize, in the end we had to make two changes:

1. Add kanela.modules.logback.order = 1 to our configuration to ensure that the Logback instrumentation is loaded as soon as possible.
2. Add the sbt-kanela-runner Sbt plugin (addSbtPlugin("io.kamon" % "sbt-kanela-runner" % "2.0.14"))

Thank you for your valuable support @ivantopo! 💯

I believe we can close this issue now.

[ivantopo]

Thanks for sharing your results @scheleaap. Have a great day!