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:

slf4j/slf4j-jdk14/src/main/java/org/slf4j/jul/JDK14LoggerAdapter.java

Lines 219 to 230 in 4fa92fc

	static String[] BARRIER_CLASSES = new String[] { SUPER_OF_SUPER, SUPER, SELF, SUBSTITUE, FLUENT };
	private boolean barrierMatch(String callerFQCN, String candidateClassName) {
	if (candidateClassName.equals(callerFQCN))
	return true;
	for (String barrierClassName : BARRIER_CLASSES) {
	if (barrierClassName.equals(candidateClassName)) {
	return true;
	}
	}
	return false;
	}

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

[thomas-k-git]

Hi all!
Any update on the issue? anything that I can do to assist? cheers and thx

[ceki]

@thomas-k-git Fixed in commit 69c333d

In JDK14LoggerAdapter, the logic searching for the stack trace line just before actual the caller was adapted to take into account an extra logging layer such as Jboss logging.

Other logging adapters/backends such as slf4j-relaod4j/reload4j and logback already had the correct behavior.

[ceki]

@ppkarwasz Please let me know if commit 69c333d works for you.

[ppkarwasz]

@ceki,

It works, but it looks a little bit over-engineered to me.
The callerBoundary can IMHO be precisely determined and barrierMatch can be reduced to:

 private boolean barrierMatch(String callerFQCN, String candidateClassName) { 
     return candidateClassName.equals(callerFQCN)); 
 }

The callerBoundary depends on the type of API used:

1. For the classic API, the boundary is AbstractLogger (not JDK14LoggerAdapter as the current code sets). All the trace, debug, etc. methods are defined in AbstractLogger: LegacyAbstractLogger and JDK14LoggerAdapter will never be the caller boundary.
2. For the fluent API, it is up to the LoggingEventBuilder to set the correct boundary and DefaultLoggingEventBuilder does it correctly.
3. For the LoggingEventAware API the caller should set the caller boundary and JDK14LoggerAdapter should use it (currently it does not use that information).
4. For the SubstituteLogger, I believe that it is up to the SubstituteLogger to set itself as caller boundary, not up to the SLF4J implementations to be aware of SubstituteLogger.

I can probably make a PR that simplifies the location logic by the end of the week.

[thomas-k-git]

Is there a pre-release build somewhere to test?
had troubles setting up / running maven locally on the repo :/
does it fix both reproducers attached here https://github.com/user-attachments/files/16613965/slf4j-fcqn-issue-repro2-direct.zip and further up?

[ceki]

@thomas-k-git It should be very easy to build slf4j. JDK 11 and Maven should be enough to build. What is failing?

[thomas-k-git]

Ah ok, works now with mvn install. mvn compile didn't work at first. for info, error was:

INFO] Changes detected - recompiling the module!
[INFO] Compiling 1 source file to /mnt/data/workspaces/slf4j/slf4j-simple/target/classes/META-INF/versions/9
...
[INFO] -------------------------------------------------------------
[ERROR] COMPILATION ERROR :
[INFO] -------------------------------------------------------------
[ERROR] /mnt/data/workspaces/slf4j/slf4j-simple/src/main/java9/module-info.java:[2,15] module not found: org.slf4j
...
[INFO] SLF4J Simple Provider .............................. FAILURE [ 0.327 s]
...
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.10.1:compile (module-compile) on project > slf4j-simple: Compilation failure
[ERROR] /mnt/data/workspaces/slf4j/slf4j-simple/src/main/java9/module-info.java:[2,15] module not found: org.slf4j

[thomas-k-git]

Just did local tests with the current master with the suggested fix: Fixes both reproducers and our actual prodution setup, which has a bit more stuff added on top!

@ppkarwasz I also tested the changes on your branch. Same: fixes both reproducers and our location production setup.

[thomas-k-git]

Hi all! do we have a decision regarding which approach we want to use, the one here or in #439 ?