StatusLogger Unrecognized format specifier [msg]

[adamfarley]

Summary

A logging error in log4j appears to fail half of the system test targets in seconds.

Details

According to TRSS, one of the failed test targets (UtilLoadTest_5m_0) last passed on the 22nd of January, and started failing on the 6th of February.

So I've identified a list of commits in the systemtest and stf repositories for that period:

• Replace SecurityManager use with Java agent
• Added Visual Studio 2022 vcvarsall.bat path
• Exclude Mauve tests that use SecurityManager for JDK24
• Update jdk-25+ openjdk.test.debugging to use asm.jar

Example

https://ci.adoptium.net/job/Test_openjdk11_hs_extended.system_x86-64_linux/952/console

22:26:22  STF 22:26:22.812 - Monitoring processes: ULT
22:26:23  ULT stderr ERROR StatusLogger Unrecognized format specifier [msg]
22:26:23  ULT stderr ERROR StatusLogger Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
22:26:23  ULT 2025-02-26 22:26:23,770 main ERROR Unrecognized format specifier [msg]
22:26:23  ULT 2025-02-26 22:26:23,777 main ERROR Unrecognized conversion specifier [msg] starting at position 23 in conversion pattern.
22:26:24  ULT stderr Exception in thread "main" java.lang.LinkageError: loader 'app' attempted duplicate class definition for org.apache.logging.log4j.core.impl.MutableLogEvent. (org.apache.logging.log4j.core.impl.MutableLogEvent is in unnamed module of loader 'app')
22:26:24  ULT stderr 	at java.base/java.lang.ClassLoader.defineClass1(Native Method)
22:26:24  ULT stderr 	at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1022)
22:26:24  ULT stderr 	at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)
22:26:24  ULT stderr 	at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:800)
22:26:24  ULT stderr 	at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:698)
22:26:24  ULT stderr 	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:621)
22:26:24  ULT stderr 	at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:579)
22:26:24  ULT stderr 	at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)
22:26:24  ULT stderr 	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:527)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.createInstance(ReusableLogEventFactory.java:109)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.getOrCreateMutableLogEvent(ReusableLogEventFactory.java:105)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.impl.ReusableLogEventFactory.createEvent(ReusableLogEventFactory.java:80)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:415)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
22:26:24  ULT stderr 	at org.apache.logging.log4j.core.Logger.log(Logger.java:161)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2017)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1983)
22:26:24  ULT stderr 	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1320)
22:26:24  ULT stderr 	at net.adoptopenjdk.loadTest.LoadTest.<init>(LoadTest.java:253)
22:26:24  ULT stderr 	at net.adoptopenjdk.loadTest.LoadTest.main(LoadTest.java:105)

[adamfarley]

Starting with the target command, the two main differences between pass and failure seem to be the java agent and the classpath changes, implimented here.

I've tried moving the asm jars after the log4j jars in the classpath, but the same error applies.

Will try moving the javatest agent.

If that doesn't work, will try removing both entirely.

Update: The arguments are not applied to the command line in order. The modified StfCoreExtension seems to affect that. Refactoring and rerunning. - Failed. JVM options must be added before the classpath.

Also, I'm told there's an aqa-tests issue for this. Will link this to that, and then close this.

[sophia-guo]

Dup of adoptium/aqa-tests#5966?