You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Tonys-L (via GitHub)" <gi...@apache.org> on 2024/12/06 12:37:40 UTC
[I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Tonys-L opened a new issue, #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282
## Description
When using the Nashorn JavaScript engine, if an exception is thrown internally within the JavaScript code and this exception is logged using a logger, it results in a memory leak. Tracing the log4j source code reveals that log4j uses `ThrowableProxy` when handling exception parameters. `ThrowableProxy` calls `loadClass`. Because Nashorn dynamically generates some classes, the exception stack trace includes dynamically generated class names, which are not cached. This causes loadClass to add these class names to the `parallelLockMap` inside the ClassLoader, leading to a memory leak.
## Configuration
**Version:** 2.24.1
**Operating system:** Windows10
**JDK:** 1.8.0_331
## Logs
Below are some log fragments. Note the class names in the exception stack trace that follow the pattern `jdk.nashorn.internal.scripts.Script$Recompilation$19663$15$^eval_.test.` The numbers following Recompilation$ are incrementing.
```
a 2024-12-06 20:11:38,104 [main] ERROR c.l.t.l.TestJsEngine - Script execution exception
javax.script.ScriptException: Error: error in <eval> at line number 1 at column number 16
at jdk.nashorn.api.scripting.NashornScriptEngine.throwAsScriptException(NashornScriptEngine.java:470) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeImpl(NashornScriptEngine.java:392) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeFunction(NashornScriptEngine.java:190) ~[nashorn.jar:?]
at com.lt.test.log4j.TestJsEngine.main(TestJsEngine.java:33) [classes/:?]
Caused by: jdk.nashorn.internal.runtime.ECMAException: Error: error
at jdk.nashorn.internal.objects.NativeError.initException(NativeError.java:137) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:102) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:106) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:110) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.constructor(NativeError.java:129) ~[nashorn.jar:?]
at jdk.nashorn.internal.scripts.Script$Recompilation$19663$15$\^eval\_.test(<eval>:1) ~[?:?]
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.ScriptObjectMirror.callMember(ScriptObjectMirror.java:199) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeImpl(NashornScriptEngine.java:386) ~[nashorn.jar:?]
... 2 more
aaaaa 2024-12-06 20:11:40,699 [main] ERROR c.l.t.l.TestJsEngine - Script execution exception
javax.script.ScriptException: Error: error in <eval> at line number 1 at column number 16
at jdk.nashorn.api.scripting.NashornScriptEngine.throwAsScriptException(NashornScriptEngine.java:470) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeImpl(NashornScriptEngine.java:392) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeFunction(NashornScriptEngine.java:190) ~[nashorn.jar:?]
at com.lt.test.log4j.TestJsEngine.main(TestJsEngine.java:33) [classes/:?]
Caused by: jdk.nashorn.internal.runtime.ECMAException: Error: error
at jdk.nashorn.internal.objects.NativeError.initException(NativeError.java:137) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:102) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:106) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.<init>(NativeError.java:110) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeError.constructor(NativeError.java:129) ~[nashorn.jar:?]
at jdk.nashorn.internal.scripts.Script$Recompilation$19665$15$\^eval\_.test(<eval>:1) ~[?:?]
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.ScriptObjectMirror.callMember(ScriptObjectMirror.java:199) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.invokeImpl(NashornScriptEngine.java:386) ~[nashorn.jar:?]
... 2 more
*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message can't create byte arrau at JPLISAgent.c line: 813
Exception in thread "main" java.lang.InternalError: BMH.reinvoke=Lambda(a0:L/SpeciesData<LIL>,a1:L)=>{
t2:L=BoundMethodHandle$Species_LIL.argL2(a0:L);
t3:I=BoundMethodHandle$Species_LIL.argI1(a0:L);
t4:L=BoundMethodHandle$Species_LIL.argL0(a0:L);
t5:L=MethodHandle.invokeBasic(t4:L,t2:L,a1:L,t3:I);t5:L}
at java.lang.invoke.MethodHandleStatics.newInternalError(MethodHandleStatics.java:127)
at java.lang.invoke.LambdaForm.compileToBytecode(LambdaForm.java:660)
at java.lang.invoke.LambdaForm.prepare(LambdaForm.java:635)
at java.lang.invoke.MethodHandle.<init>(MethodHandle.java:461)
at java.lang.invoke.BoundMethodHandle.<init>(BoundMethodHandle.java:58)
at java.lang.invoke.BoundMethodHandle$Species_LIL.<init>(Species_LIL)
at java.lang.invoke.BoundMethodHandle$Species_LIL.make(Species_LIL)
at java.lang.invoke.BoundMethodHandle$Species_LI.copyWithExtendL(Species_LI)
at java.lang.invoke.LambdaFormEditor.bindArgumentL(LambdaFormEditor.java:404)
at java.lang.invoke.BoundMethodHandle.bindArgumentL(BoundMethodHandle.java:99)
at java.lang.invoke.MethodHandles.insertArguments(MethodHandles.java:2379)
at jdk.internal.dynalink.ChainedCallSite.makePruneAndInvokeMethod(ChainedCallSite.java:226)
at jdk.internal.dynalink.ChainedCallSite.relinkInternal(ChainedCallSite.java:184)
at jdk.internal.dynalink.ChainedCallSite.relink(ChainedCallSite.java:149)
at jdk.nashorn.internal.runtime.linker.LinkerCallSite.relink(LinkerCallSite.java:142)
at jdk.internal.dynalink.DynamicLinker.relink(DynamicLinker.java:285)
at jdk.nashorn.internal.scripts.Script$19666$\^eval\_.:program(<eval>:1)
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637)
at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494)
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393)
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:449)
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:406)
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:402)
at jdk.nashorn.api.scripting.NashornScriptEngine.eval(NashornScriptEngine.java:155)
at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
at com.lt.test.log4j.TestJsEngine.main(TestJsEngine.java:27)
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
at jdk.internal.org.objectweb.asm.ClassWriter.newUTF8(ClassWriter.java:1122)
at jdk.internal.org.objectweb.asm.ClassWriter.newNameTypeItem(ClassWriter.java:1591)
at jdk.internal.org.objectweb.asm.ClassWriter.newNameType(ClassWriter.java:1574)
at jdk.internal.org.objectweb.asm.ClassWriter.newMethodItem(ClassWriter.java:1436)
at jdk.internal.org.objectweb.asm.MethodWriter.visitMethodInsn(MethodWriter.java:917)
at java.lang.invoke.InvokerBytecodeGenerator.emitStaticInvoke(InvokerBytecodeGenerator.java:867)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCodeBytes(InvokerBytecodeGenerator.java:715)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(InvokerBytecodeGenerator.java:618)
at java.lang.invoke.LambdaForm.compileToBytecode(LambdaForm.java:654)
at java.lang.invoke.LambdaForm.prepare(LambdaForm.java:635)
at java.lang.invoke.MethodHandle.<init>(MethodHandle.java:461)
at java.lang.invoke.BoundMethodHandle.<init>(BoundMethodHandle.java:58)
at java.lang.invoke.BoundMethodHandle$Species_LIL.<init>(Species_LIL)
at java.lang.invoke.BoundMethodHandle$Species_LIL.make(Species_LIL)
at java.lang.invoke.LambdaForm$DMH/221634215.invokeStatic_L3IL_L(LambdaForm$DMH)
at java.lang.invoke.BoundMethodHandle$Species_LI.copyWithExtendL(Species_LI)
at java.lang.invoke.LambdaFormEditor.bindArgumentL(LambdaFormEditor.java:404)
at java.lang.invoke.BoundMethodHandle.bindArgumentL(BoundMethodHandle.java:99)
at java.lang.invoke.MethodHandles.insertArguments(MethodHandles.java:2379)
at jdk.internal.dynalink.ChainedCallSite.makePruneAndInvokeMethod(ChainedCallSite.java:226)
at jdk.internal.dynalink.ChainedCallSite.relinkInternal(ChainedCallSite.java:184)
at jdk.internal.dynalink.ChainedCallSite.relink(ChainedCallSite.java:149)
at jdk.nashorn.internal.runtime.linker.LinkerCallSite.relink(LinkerCallSite.java:142)
at jdk.internal.dynalink.DynamicLinker.relink(DynamicLinker.java:285)
at java.lang.invoke.LambdaForm$DMH/1976870338.invokeSpecial_LLIL_L(LambdaForm$DMH)
at java.lang.invoke.LambdaForm$BMH/645206471.reinvoke(LambdaForm$BMH)
at java.lang.invoke.LambdaForm$MH/480903748.exactInvoker(LambdaForm$MH)
at java.lang.invoke.LambdaForm$MH/756400524.linkToCallSite(LambdaForm$MH)
at jdk.nashorn.internal.scripts.Script$19666$\^eval\_.:program(<eval>:1)
at java.lang.invoke.LambdaForm$DMH/664223387.invokeStatic_LL_L(LambdaForm$DMH)
at java.lang.invoke.LambdaForm$MH/1278254413.invokeExact_MT(LambdaForm$MH)
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637)
```
## Reproduction
Below is my test case, with memory settings configured as -Xms10m -Xmx10m. The program runs for 2 minutes and 24 seconds before an OutOfMemoryError (OOM) occurs.
```java
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import javax.script.Invocable;
import javax.script.ScriptEngine;
import javax.script.ScriptEngineManager;
import javax.script.ScriptException;
public class TestJsEngine {
private static final Logger LOGGER = LoggerFactory.getLogger(TestJsEngine.class);
public static void main(String[] args) {
//Set the class cache size to 0
System.setProperty("nashorn.option.class.cache.size", "0");
ScriptEngineManager engineManager = new ScriptEngineManager();
ScriptEngine engine = engineManager.getEngineByName("javascript");
String content = "function test(){" +
"throw new Error('error'); " +
"}";
while (true) {
try {
engine.eval(content);
} catch (ScriptException e) {
LOGGER.error("eval script exception", e);
}
Invocable in = (Invocable) engine;
try {
in.invokeFunction("test");
} catch (ScriptException e) {
LOGGER.error("Script execution exception", e);
} catch (NoSuchMethodException e) {
}
}
}
}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2523413394
@Tonys-L,
I can reproduce the issue with a simple:
```java
for (int i = 0; ; i++) {
try {
Class.forName(Main.class.getName() + i);
} catch (ClassNotFoundException e) {
// ignore
}
}
```
This has apparently been reported as [JDK-8037342](https://bugs.openjdk.org/browse/JDK-8037342), but has been classified as `wontfix`.
I am not sure there is anything we can do to workaround this JDK bug: if you want packaging information in your stack traces (the trailing `~[nashorn.jar:?]`), we need to access all the classes in the stack trace of the exception. Might I suggest you switch from the (implicit) [`%xEx` pattern](https://logging.apache.org/log4j/3.x/manual/pattern-layout.html#converter-exception-extended) to an explicit [`%ex` pattern](https://logging.apache.org/log4j/3.x/manual/pattern-layout.html#converter-exception)? E.g.:
```xml
<PatternLayout pattern="%d [%t] %p %c{.} - %m%n%ex"/>
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2529335265
> shall we document this unexpected behavior of `%xEx` and [JDK-8037342](https://bugs.openjdk.org/browse/JDK-8037342) encourage users to prefer `%ex` instead?
Sure, let us document it in the `2.25.0` release. Users don't need to be encouraged, because the default behavior will change, but if somebody wants to go back to `%xEx` and uses scripting (or other generated classes like JSP), he should consider it.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "vy (via GitHub)" <gi...@apache.org>.
vy commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2523249374
`2.25.0` will deprecate `ThrowableProxy` – see [the staged release notes](https://logging.staged.apache.org/log4j/2.x/release-notes.html) for `2.x.x`. Though incorporated changes might not be addressing this particular corner case, since a `loadClass()` is still needed/used while populating the stack trace. @Tonys-L, can you reproduce the issue using the most recent `2.25.0-SNAPSHOT`? (See [Using snapshots](https://logging.staged.apache.org/log4j/2.x/manual/installation.html#snapshots).)
@alan0428a, do you have time to look at this issue? Maybe we should start with writing a test, ideally that doesn't require an OOM.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "alan0428a (via GitHub)" <gi...@apache.org>.
alan0428a commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2531142418
@ppkarwasz @vy
Maybe I am dumb, AFAIK, the loadclass happens in creating context phase, but `ignoredPackages` is used in rendering phase. And this OOM happens in creating context phase, so `ignoredPackages` won't help?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "garydgregory (via GitHub)" <gi...@apache.org>.
garydgregory commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2523419631
Nice reproducer @ppkarwasz !
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "Tonys-L (via GitHub)" <gi...@apache.org>.
Tonys-L commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2523675838
@ppkarwasz This is a rather hidden problem. We didn't realize that we should pay attention to this point when using Log4j to output exception information until we located the cause of the problem. Of course, it's a low-probability event and only occurs when used in combination with certain special libraries. However, once it occurs, it's still quite difficult to troubleshoot this problem. It took two months from the startup of our system to the occurrence of Out Of Memory (OOM). The loadClass method is called internally within Log4j. I wonder if there should be some mechanism that can monitor and alert users when too many different classes have been loaded, making this problem easier to expose.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "vy (via GitHub)" <gi...@apache.org>.
vy commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2529194672
@ppkarwasz, shall we document this unexpected behavior of `%xEx` and [JDK-8037342](https://bugs.openjdk.org/browse/JDK-8037342) encourage users to prefer `%ex` instead?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2531191612
> Maybe I am dumb, AFAIK, the loadclass happens in creating context phase, but `ignoredPackages` is used in rendering phase. And this OOM happens in creating context phase, so `ignoredPackages` won't help?
Yes, currently `ignoredPackages` does not help. But the algorithm could be modified so that at least `Class.forName` is skipped for ignored packages. The question is, whether this is worth the effort.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "Tonys-L (via GitHub)" <gi...@apache.org>.
Tonys-L commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2526739069
@ppkarwasz ,
Thank you. The solutions you proposed indeed work very well to resolve my issues.
Currently, it seems there isn't a perfect solution to prevent this problem in advance; we can only address it after the issue is discovered.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "Tonys-L (via GitHub)" <gi...@apache.org>.
Tonys-L commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2523673886
@vy Sorry, I can't find the version 2.25.0-SNAPSHOT in the Maven repository. It seems that this version has not been released to the Maven repository yet.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3282:
URL: https://github.com/apache/logging-log4j2/issues/3282#issuecomment-2524161891
> The loadClass method is called internally within Log4j. I wonder if there should be some mechanism that can monitor and alert users when too many different classes have been loaded, making this problem easier to expose.
As mentioned by @vy, in `2.25.0` the `ThrowableProxy` class will no longer be used. The code that determines the additional packaging information for each class is now in [`ThrowableExtendedStackTraceRenderer`](https://github.com/apache/logging-log4j2/blob/2.x/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/ThrowableExtendedStackTraceRenderer.java).
We could probably:
- enhance it to skip the generation of packaging information for classes in the `ignoredPackages` option.
- you could then specify `%xEx(filters=jdk.nashorn.internal.scripts)` to ignore the packaging information of the classes generated by Nashorn.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org