Logging framework uses MDC adapter provided by SubstituteServiceProvider even after initialization of CustomServiceProvider

[OmShinde1513]

Hi, I'm Using logback 1.5.16 logging framework and slf4j 2.0.16, when LogbackServiceProvider initialization is ongoing, slf4j provides SubstituteServiceProvider, In static block of MDC class, mdcAdapter is initialized with BasicMDCAdapter provided by SubstituteServiceProvider, and this is not replaced with MDCAdapter provided by LogbackServiceProvider after service providers initialization completed. Hence MDC key values are placed in this BasicMDCAdapter, But logback appenders get mdcPropertyMap from its own MDCAdapter so this map gets empty as all property values placed in map of BasicMDCAdapter. ex: // After custome service initialization completed. MDC.put(key,value) -> puts this in BasicMDCAdapter provided by SubstituteServiceProvider. loggerContext.getMDCAdapter() -> this adapter have empty PropertyMap, which is used by logback to set mdc properties to LoggingEvent.

After initialization of CustomServiceProvider MDCAdapter should be replaced with its MDCAdapter.

[OmShinde1513]

Hi @ceki, We are currently facing security issues with the older version of Logback, and as a result, we are in the process of upgrading both Logback and SLF4J, this security issues are critical for us. Could you please provide an update on when this issue will be resolved?

[viphadke]

@ceki Thanks for looking into the issue. The issue is a blocker for our release. Do you have any estimate on when the problem can be fixed and released?

[ceki]

@OmShinde1513 This issue is solved in commit 9349d64f95d0ee4e6ee0057e7376d15f1d15b37c

[skanikdale]

@ceki Thanks a lot for the quick turnaround. When will the next release be available which will contain this fix?

[OmShinde1513]

Hi @ceki Thanks for looking into issue, Since in current version of logback the LogbackServiceProvider not initializes MDCAdapter field in its constructor or on field declaration, due to this LoggerFactory#earlyBindMDCAdapter not able to initialize the MDC_ADAPTER. As a result, the MDC_ADAPTER provided by the SubstituteServiceProvider is used throughout the entire application and MDC's are not getting in logs. Is there will be new release of logback for this ?

[viphadke]

@ceki The fix is not working for use. Let me try to clarify @OmShinde1513 comment.

I think this might be very specific to our usage of logback and sl4j. We have a logback lifecycle listener where we use MDC. This retriggers another initialization of the service provider. I am attaching the source code here.

App.txt CustomLoggerContextListener.txt

logback.txt

Thanks for looking into this.

[ceki]

@viphadke Thank you for the helpful clarification.

[viphadke]

@ceki Do you have any ETA on a possible solution ?

[ceki]

Logback version 1.5.17 has been released a short time ago. See also https://logback.qos.ch/news.html#1.5.17

[TWiStErRob]

@ceki a quick heads-up on the "Note that these changes are transparent to existing logging backends which will continue to work as is." part of the release notes. The existing implementations of the SLF4JServiceProvider interface in the wild might not be compatible with SFL4J 2.0.17. Here's a trivial example:

class AndroidLoggerServiceProvider : SLF4JServiceProvider {
	private val requestedApiVersion: String = "2.0.13"
	override fun getRequestedApiVersion(): String = requestedApiVersion

	private lateinit var loggerFactory: ILoggerFactory
	override fun getLoggerFactory(): ILoggerFactory = loggerFactory

	private lateinit var markerFactory: IMarkerFactory
	override fun getMarkerFactory(): IMarkerFactory = markerFactory

	private lateinit var mdcAdapter: MDCAdapter
	override fun getMDCAdapter(): MDCAdapter = mdcAdapter

	override fun initialize() {
		loggerFactory = AndroidLoggerFactory()
		markerFactory = BasicMarkerFactory()
		mdcAdapter = NOPMDCAdapter()
	}
}

According to the original behavioral contract of "we'll only call getters after initialize()" (paraphrasing the javadoc "Initialize the logging back-end."), this is a valid implementation, yet combined with 2.0.17 it throws an exception:

Caused by: kotlin.UninitializedPropertyAccessException: lateinit property mdcAdapter has not been initialized
	at ....AndroidLoggerServiceProvider.getMDCAdapter(AndroidLoggerServiceProvider.kt:27)
	at org.slf4j.LoggerFactory.earlyBindMDCAdapter(LoggerFactory.java:227)
	at org.slf4j.LoggerFactory.bind(LoggerFactory.java:199)
	... 18 more

this is because of Kotlin's strictness and self-checking, but it's easy to imagine any third party implementation expecting an initialize() call first before get*(). Of course the fix is trivial, it just breaks the "non-major release" will "just work" expectations. I was definitely surprised to see this exception show up in my UI tests on a Renovate patch PR.

[agentgt]

@ceki I'm shocked this was a patch change and not a minor change. What is the point of initialize then.

https://github.com/jstachio/rainbowgum/issues/210

[agentgt]

Like @TWiStErRob pointed out with their Kotlin implementation I was safely checking for null as I use JSpecify/Checker.

@ceki

I now initialize the MDCAdapter and MarkerFactory in the service provider constructor (I suppose I could do a getter check null on volatile as well). I did the MarkerFactory in the advent something similar happens later.

However this begs the question are we going to have another patch change where you require initialization of the logging framework before initialize is called? Like am I going to find my implementation broken again with another patch release of slf4j?

https://github.com/jstachio/rainbowgum/blob/main/rainbowgum-slf4j/src/main/java/io/jstach/rainbowgum/slf4j/RainbowGumSLF4JServiceProvider.java

[agentgt]

@ceki We really should consider reverting this fix or some fix for the fix. I say this kindly that this fix hurts way more and only helps a very select few. Although I put the fix in my implementation today I think its unfair that this fix got in and breaks compliant implementations. At the bare minimum can we improve the Javadoc particularly initialize and getMDCAdapter?

Let me give the synopsis.

There is a fringe bug in an SLF4J implementation (Logback) of calling MDC before logging framework initialization. Neither Logback or the very small users facing this bug just did the work around and initialize logging framework before calling MDC storage methods.

The bug was fixed not in Logback but SLF4J a shared facade API with who knows how many implementations but for sure at least a dozen.

If you follow the spec of initialize and even older code the initialization was done entirely here. And it makes sense because of how SLF4J uses the Service Loader. It loads all the implementations to see if there are duplicates (e.g. calls the constructor) so yeah you might not want to call initialize on all of them hence I assumed was the reasoning for that method (e.g. the Service Loader does not do the initialization with the constructor. However there is away to check for multiple implementations without loading the class using the Stream API of the ServiceLoader).

So this fringe bug fix applied as a patch in SLF4J that again originates in an SLF4J implementation so far breaks two compliant implementations (@TWiStErRob 's and RainbowGum) on a patch upgrade of an API.

And there are problems with this in that the MDC implementation is just assumed to not need the rest of the logging framework. I admit my library does not (need the rest of the library) but I could easily see more complicated libraries that would check configuration of what type of data structure to use for storage of the threadlocal MDC or perhaps even use some sort of new ScopedValue based on config (coming in JDK 25 as an alternative to ThreadLocal) that is already set.