Logging MDC tags no longer work with logback-classic 1.4.x about kamon HOT 5 CLOSED

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 🙏

from kamon.

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

from kamon.

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 💪

from kamon.

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.

from kamon.

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

from kamon.