slf4j-jdk14 adapter: Logger.log's fqcn parameter ignored

[thomas-k-git]

Dear all, In the process of upgrading from slf4j1 to v2 of api and impl jars, we notice a difference in behavior, breaking our setup.

we have a complex setup with multiple adapters: jboss-logging into log4j2-to-slf4j into slf4j-jdk.

indirectly, org.slf4j.spi.LocationAwareLogger#log is called with the outmost logger class as fcqn parameter.

from my understanding the intention of the parameter is to indicate the boundary / entrypoint into the log framework and the next stackframe past this fcqn should be used as "calling class".

however in our setup, a middle layer of the log adapters is being set as java.util.logging.LogRecord#setSourceClassName and not the actual caller.

so with a callstack setup like this:

steArray = {StackTraceElement[131]@3780} 
 0 = {StackTraceElement@3781} "org.slf4j.jul.JDK14LoggerAdapter.fillCallerData(JDK14LoggerAdapter.java:182)"
 1 = {StackTraceElement@3782} "org.slf4j.jul.JDK14LoggerAdapter.innerNormalizedLoggingCallHandler(JDK14LoggerAdapter.java:155)"
 2 = {StackTraceElement@3783} "org.slf4j.jul.JDK14LoggerAdapter.log(JDK14LoggerAdapter.java:172)"
 3 = {StackTraceElement@3784} "org.apache.logging.slf4j.SLF4JLogger.logMessage(SLF4JLogger.java:245)"
 4 = {StackTraceElement@3785} "org.jboss.logging.Log4j2Logger.doLog(Log4j2Logger.java:54)"
 5 = {StackTraceElement@3786} "org.jboss.logging.Logger.infov(Logger.java:1034)"
 6 = {StackTraceElement@3787} "ACTUALCLASS"

we get 2024-08-14 14:22:14 INFO [org.apache.logging.slf4j.SLF4JLogger] message instead of 2024-08-14 14:22:14 INFO [ACTUALCLASS] message

even though org.jboss.logging.Logger is the fcqn calling class.

it seems that behavior changed between version 1 and 2 here

I would expect precendence of the callerFQCN parameter of the org.slf4j.jul.JDK14LoggerAdapter#fillCallerData when it is present in the stacktrace (and the other BARRIER classes practically ignored in that case).

is my understanding wrong? is this a bug?

involved jars:

• slf4j-jdk14-2.0.13.jar
• log4j-to-slf4j-2.20.0.jar
• jboss-logging-3.3.0.Final.jar

[ceki]

@thomas-k-git Can you please provide a test case reproducing the problem?

[thomas-k-git]

slf4j-fcqn-issue-repro.zip actual output when I run it:

ago 14, 2024 3:11:43 P. M. org.apache.logging.slf4j.SLF4JLogger logMessage INFORMACIÓN: this should be logged with org.example.Main, but isnt

[ceki]

Why is org.apache.logging.log4j:log4j-to-slf4j:2.20.0 included in the class path since you are not using log4j 2.0?

[thomas-k-git]

the reality for us here across multiple libraries in one complex application is that many log frameworks are used. in our app we have code that uses all 3: jboss, slf4j, log4j (list goes on..). imagine the log APIs of all being used / called

[ceki]

So there are 3 different indirections and you would like to preserve the caller path. By the way, this is probably a org.apache.logging.log4j:log4j-to-slf4j:2.20.0 issue but I might me wrong.

[thomas-k-git]

So there are 3 different indirections and you would like to preserve the caller path. correct.

probably a org.apache.logging.log4j:log4j-to-slf4j:2.20.0 issue I don't see how log4j-to-slf4j could have use the org.slf4j.spi.LocationAwareLogger#log API differently. The intention is to use the fqcn to find the log framework border, no?

Not sure what the exact contract/agreement of the method is, but how else could we implement getting the correct caller in such complex call stacks except using the parameter in this way?

[thomas-k-git]

a simpler, maybe more general reproducer, the problem also exists (i think because of the same reason / treatment of fqcn) when just using jboss -> slf4j bridge. here:

with this output: `15.35.40: Executing ':org.example.Main.main()'...

Task :compileJava Task :processResources NO-SOURCE Task :classes

Task :org.example.Main.main() ago 14, 2024 3:35:42 P. M. jdk.internal.reflect.DirectMethodHandleAccessor invoke INFORMACIÓN: this should be logged with org.example.Main, but isnt `

note the "jdk.internal.reflect.DirectMethodHandleAccessor invoke"

slf4j-fcqn-issue-repro2-direct.zip

[ppkarwasz]

The problem is here:

https://github.com/qos-ch/slf4j/blob/4fa92fc007be215136cc12915e1f1d29192bb06e/slf4j-jdk14/src/main/java/org/slf4j/jul/JDK14LoggerAdapter.java#L219-L230

This method is called to decide if candidateClassName is the entry point of the logging system. It is called in two different situations:

1. When LocationAwareLogger is called. In this case callerFQCN matches the parameter passed by JBoss Logging and the BARRIER_CLASSES loop should be skipped.
2. When any other Logger or LoggingEventBuilder method is called. In this case the callerFQCN has a fixed value of org.slf4j.jul.JDK14LoggerAdapter and the loop is necessary.

[thomas-k-git]

@ceki what do you think? is there consensus that this should be changed?

[ceki]

Created https://jira.qos.ch/browse/SLF4J-604 to track this issue