search

apache / logging-log4j2

Apache Log4j 2 is a versatile, feature-rich, efficient logging API and backend for Java.
https://logging.apache.org/log4j/2.x/
Apache License 2.0
3.35k stars 1.59k forks source link

JFR logs NoSuchMethodError when application is closed #2951

Closed Karonazaba closed 14 hours ago

Karonazaba commented 5 days ago

When the application is closed, the log does not record Error or Exception, but there is an exception about the log4j thread in the JFR file. I suspect it is related to class unloading. It seems to only appear when the application is closed. The following are some exception stacks and JFR screenshots.

Screenshot 2024-09-14 at 10 19 22 Screenshot 2024-09-14 at 10 19 56 
java.lang.Error.<init>(java.lang.String)
java.lang.LinkageError.<init>(java.lang.String)
java.lang.IncompatibleClassChangeError.<init>(java.lang.String)
java.lang.NoSuchMethodError.<init>(java.lang.String)
java.lang.invoke.MethodHandleNatives.resolve(java.lang.invoke.MemberName, java.lang.Class, int, boolean)
java.lang.invoke.MemberName$Factory.resolve(byte, java.lang.invoke.MemberName, java.lang.Class, int, boolean)
java.lang.invoke.MemberName$Factory.resolveOrNull(byte, java.lang.invoke.MemberName, java.lang.Class, int)
java.lang.invoke.InvokerBytecodeGenerator.resolveFrom(java.lang.String, java.lang.invoke.MethodType, java.lang.Class)
java.lang.invoke.InvokerBytecodeGenerator.lookupPregenerated(java.lang.invoke.LambdaForm, java.lang.invoke.MethodType)
java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(java.lang.invoke.LambdaForm, java.lang.invoke.MethodType)
java.lang.invoke.LambdaForm.compileToBytecode()
java.lang.invoke.DirectMethodHandle.makePreparedLambdaForm(java.lang.invoke.MethodType, int)
java.lang.invoke.DirectMethodHandle.preparedLambdaForm(java.lang.invoke.MethodType, int)
java.lang.invoke.DirectMethodHandle.preparedLambdaForm(java.lang.invoke.MemberName, boolean)
java.lang.invoke.DirectMethodHandle.preparedLambdaForm(java.lang.invoke.MemberName)
java.lang.invoke.DirectMethodHandle.make(byte, java.lang.Class, java.lang.invoke.MemberName, java.lang.Class)
java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(byte, java.lang.Class, java.lang.invoke.MemberName, boolean, boolean, java.lang.invoke.MethodHandles$Lookup)
java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(byte, java.lang.Class, java.lang.invoke.MemberName, java.lang.invoke.MethodHandles$Lookup)
java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(byte, java.lang.Class, java.lang.invoke.MemberName)
java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(byte, java.lang.Class, java.lang.String, java.lang.Object)
java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(java.lang.Class, int, java.lang.Class, java.lang.String, java.lang.Object)
java.lang.SecurityManager.addNonExportedPackages(java.lang.ModuleLayer)
java.lang.SecurityManager.<clinit>()
org.apache.logging.log4j.util.PrivateSecurityManagerStackTraceUtil.<clinit>()
org.apache.logging.log4j.util.StackLocator.getCurrentStackTrace()
org.apache.logging.log4j.util.StackLocatorUtil.getCurrentStackTrace()
org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(java.lang.Throwable, java.util.Set)
org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(java.lang.Throwable)
org.apache.logging.log4j.core.async.RingBufferLogEvent.getThrownProxy()
org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(org.apache.logging.log4j.core.LogEvent, java.lang.StringBuilder)
org.springframework.boot.logging.log4j2.ExtendedWhitespaceThrowablePatternConverter.format(org.apache.logging.log4j.core.LogEvent, java.lang.StringBuilder)
org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(org.apache.logging.log4j.core.LogEvent, java.lang.StringBuilder)
org.apache.logging.log4j.core.layout.PatternLayout.toText(org.apache.logging.log4j.core.layout.AbstractStringLayout$Serializer2, org.apache.logging.log4j.core.LogEvent, java.lang.StringBuilder)
org.apache.logging.log4j.core.layout.PatternLayout.encode(org.apache.logging.log4j.core.LogEvent, org.apache.logging.log4j.core.layout.ByteBufferDestination)
org.apache.logging.log4j.core.layout.PatternLayout.encode(java.lang.Object, org.apache.logging.log4j.core.layout.ByteBufferDestination)
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.AppenderControl.callAppender0(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.AppenderControl.callAppender(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(org.apache.logging.log4j.core.LogEvent, org.apache.logging.log4j.core.config.LoggerConfig$LoggerConfigPredicate)
org.apache.logging.log4j.core.config.LoggerConfig.log(org.apache.logging.log4j.core.LogEvent, org.apache.logging.log4j.core.config.LoggerConfig$LoggerConfigPredicate)
org.apache.logging.log4j.core.config.LoggerConfig.log(org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(org.apache.logging.log4j.util.Supplier, org.apache.logging.log4j.core.LogEvent)
org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(org.apache.logging.log4j.core.async.RingBufferLogEvent)
org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(boolean)
org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(org.apache.logging.log4j.core.async.RingBufferLogEvent, long, boolean)
org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(java.lang.Object, long, boolean)
com.lmax.disruptor.BatchEventProcessor.processEvents()
com.lmax.disruptor.BatchEventProcessor.run()
java.lang.Thread.run()
ppkarwasz commented 5 days ago

@Karonazaba,

Thank You for reporting this issue. What version of the JRE and Log4j are you using?

Karonazaba commented 5 days ago

@ppkarwasz Thanks for reply.

The log4j version:2.21.1

the JDK version: java version "17.0.10.0.101" 2024-04-12 LTS Java Runtime Environment Zing24.02.100.0+5 (build 17.0.10.0.101+3-LTS) Zing 64-Bit Tiered VM Zing24.02.100.0+5 (build 17.0.10.0.101-zing_24.02.100.0-b5-product-linux-X86_64, mixed mode)

ppkarwasz commented 2 days ago

@Karonazaba,

It seems to only appear when the application is closed.

Would does it mean exactly? Does it mean it happens after a System.exit() call? Or are you running in a multi-application environment?

I tried to reproduce it using:

try {
    System.exit(0);
} finally {
    try {
        new SecurityManager() {};
    } catch (Exception e) {
        e.printStackTrace();
    }
}

using Temurin 17 and Zulu 17, but it doesn't happen.

Since we don't have access to Zing, can you try if the problem occurs with the latest version of the VM?

Karonazaba commented 2 days ago

@ppkarwasz I mean to kill an application(SpringBoot). Every time the service stops, the JFR file will record this exception. I tried to use arthas to view the call chain. It seems that every time the application stops, the constructor of ThrowableProxy is called. I am not sure if this is normal. I also confirmed that only this one application is tracked on the server and no others exist. Maybe I should write a springboot application

vy commented 2 days ago

@Karonazaba, would you mind providing us a minimal (i.e., a Main.java, pom.xml, and log4j2.xml) reproduction that we can trigger the failure on our side using publicly accessible tools & libraries, please?

ppkarwasz commented 1 day ago

This seems some sort of logic in the JDK that uses Error throwing to control the flow of the code. In any simple application I can find entries like this:

piotr@migi:~/workspace/sandbox$ jfr print --events jdk.JavaErrorThrow --stack-depth 50 myrecording.jfr 
jdk.JavaErrorThrow {
  startTime = 06:27:58.650
  message = "'long java.lang.invoke.DirectMethodHandle$Holder.invokeStatic(java.lang.Object, java.lang.Object)'"
  thrownClass = java.lang.NoSuchMethodError (classLoader = bootstrap)
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    java.lang.Error.<init>(String) line: 72
    java.lang.LinkageError.<init>(String) line: 55
    java.lang.IncompatibleClassChangeError.<init>(String) line: 54
    java.lang.NoSuchMethodError.<init>(String) line: 57
    java.lang.invoke.MethodHandleNatives.resolve(MemberName, Class, int, boolean)
    java.lang.invoke.MemberName$Factory.resolve(byte, MemberName, Class, int, boolean) line: 1085
    java.lang.invoke.MemberName$Factory.resolveOrNull(byte, MemberName, Class, int) line: 1129
    java.lang.invoke.InvokerBytecodeGenerator.resolveFrom(String, MethodType, Class) line: 687
    java.lang.invoke.InvokerBytecodeGenerator.lookupPregenerated(LambdaForm, MethodType) line: 739
    java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(LambdaForm, MethodType) line: 748
    java.lang.invoke.LambdaForm.compileToBytecode() line: 854
    java.lang.invoke.DirectMethodHandle.makePreparedLambdaForm(MethodType, int) line: 305
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MethodType, int) line: 233
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MemberName, boolean) line: 218
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MemberName) line: 227
    java.lang.invoke.DirectMethodHandle.make(byte, Class, MemberName, Class) line: 108
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(byte, Class, MemberName, boolean, boolean, MethodHandles$Lookup) line: 4004
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(byte, Class, MemberName, MethodHandles$Lookup) line: 3960
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(byte, Class, MemberName) line: 4204
    java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(byte, Class, String, Object) line: 4152
    java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(Class, int, Class, String, Object) line: 615
    jdk.internal.platform.cgroupv2.CgroupV2Subsystem.getLongVal(String, long) line: 56
    jdk.internal.platform.cgroupv2.CgroupV2Subsystem.getLongVal(String) line: 63
    jdk.internal.platform.cgroupv2.CgroupV2Subsystem.getCpuShares() line: 156
    jdk.internal.platform.CgroupMetrics.getCpuShares() line: 75
    jdk.jfr.internal.instrument.JDKEvents.emitContainerConfiguration() line: 196
    jdk.jfr.internal.RequestEngine$RequestHook.execute() line: 68
    jdk.jfr.internal.RequestEngine.doChunk(Predicate) line: 186
    jdk.jfr.internal.RequestEngine.doChunkBegin() line: 179
    jdk.jfr.internal.PlatformRecorder.start(PlatformRecording) line: 294
    jdk.jfr.internal.PlatformRecording.start() line: 123
    jdk.jfr.Recording.start() line: 184
    jdk.jfr.internal.dcmd.DCmdStart.execute(ArgumentParser) line: 197
    jdk.jfr.internal.dcmd.AbstractDCmd.execute(String, String, char) line: 88
  ]
}

jdk.JavaErrorThrow {
  startTime = 06:27:58.661
  message = "'void java.lang.invoke.DirectMethodHandle$Holder.invokeStatic(java.lang.Object, java.lang.Object, java.lang.Object, java.lang.Object)'"
  thrownClass = java.lang.NoSuchMethodError (classLoader = bootstrap)
  eventThread = "main" (javaThreadId = 1)
  stackTrace = [
    java.lang.Error.<init>(String) line: 72
    java.lang.LinkageError.<init>(String) line: 55
    java.lang.IncompatibleClassChangeError.<init>(String) line: 54
    java.lang.NoSuchMethodError.<init>(String) line: 57
    java.lang.invoke.MethodHandleNatives.resolve(MemberName, Class, int, boolean)
    java.lang.invoke.MemberName$Factory.resolve(byte, MemberName, Class, int, boolean) line: 1085
    java.lang.invoke.MemberName$Factory.resolveOrNull(byte, MemberName, Class, int) line: 1129
    java.lang.invoke.InvokerBytecodeGenerator.resolveFrom(String, MethodType, Class) line: 687
    java.lang.invoke.InvokerBytecodeGenerator.lookupPregenerated(LambdaForm, MethodType) line: 739
    java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(LambdaForm, MethodType) line: 748
    java.lang.invoke.LambdaForm.compileToBytecode() line: 854
    java.lang.invoke.DirectMethodHandle.makePreparedLambdaForm(MethodType, int) line: 305
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MethodType, int) line: 233
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MemberName, boolean) line: 218
    java.lang.invoke.DirectMethodHandle.preparedLambdaForm(MemberName) line: 227
    java.lang.invoke.DirectMethodHandle.make(byte, Class, MemberName, Class) line: 108
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(byte, Class, MemberName, boolean, boolean, MethodHandles$Lookup) line: 4004
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(byte, Class, MemberName, MethodHandles$Lookup) line: 3960
    java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(byte, Class, MemberName) line: 4204
    java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(byte, Class, String, Object) line: 4152
    java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(Class, int, Class, String, Object) line: 615
    org.apache.logging.log4j.status.StatusLogger$PropertiesUtilsDouble.normalizeProperties(Properties[]) line: 448
    org.apache.logging.log4j.status.StatusLogger$PropertiesUtilsDouble.readAllAvailableProperties() line: 409
    org.apache.logging.log4j.status.StatusLogger$Config.<init>() line: 264
    org.apache.logging.log4j.status.StatusLogger$Config.<clinit>() line: 219
    org.apache.logging.log4j.status.StatusLogger.<init>() line: 533
    org.apache.logging.log4j.status.StatusLogger$InstanceHolder.<clinit>() line: 506
    org.apache.logging.log4j.status.StatusLogger.getLogger() line: 565
    org.apache.logging.log4j.LogManager.<clinit>() line: 56
    eu.copernik.sandbox.Main.<clinit>() line: 8
  ]
}

...
}

They all refer to this snippet of JDK logic that catches exceptions as part of the normal control flow. I don't believe this is related to Log4j, it is probably some implementation detail that you can ask on the OpenJDK mailing list.

Karonazaba commented 14 hours ago

@ppkarwasz thanks, got it