When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. #3282

Tonys-L · 2024-12-06T12:37:37Z

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.

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) {

            }
        }
    }
}

The text was updated successfully, but these errors were encountered:

vy · 2024-12-06T13:23:15Z

2.25.0 will deprecate ThrowableProxy – see the staged release notes 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.)

@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.

ppkarwasz · 2024-12-06T14:47:36Z

@Tonys-L,

I can reproduce the issue with a simple:

for (int i = 0; ; i++) {
    try {
        Class.forName(Main.class.getName() + i);
    } catch (ClassNotFoundException e) {
        // ignore
    }
}

This has apparently been reported as 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 to an explicit %ex pattern? E.g.:

<PatternLayout pattern="%d [%t] %p %c{.} - %m%n%ex"/>

garydgregory · 2024-12-06T14:50:37Z

Nice reproducer @ppkarwasz !

Tonys-L · 2024-12-06T16:24:41Z

@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.

Tonys-L · 2024-12-06T16:25:36Z

@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.

ppkarwasz · 2024-12-06T20:56:40Z

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.
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.

Tonys-L · 2024-12-09T03:22:18Z

@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.

vy · 2024-12-09T19:28:53Z

@ppkarwasz, shall we document this unexpected behavior of %xEx and JDK-8037342 encourage users to prefer %ex instead?

ppkarwasz · 2024-12-09T20:07:03Z

shall we document this unexpected behavior of %xEx and 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.

alan0428a · 2024-12-10T10:27:28Z

@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?

ppkarwasz · 2024-12-10T10:42:15Z

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.

github-actions bot added the waiting-for-maintainer label Dec 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. #3282

When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. #3282

Tonys-L commented Dec 6, 2024

vy commented Dec 6, 2024

ppkarwasz commented Dec 6, 2024

garydgregory commented Dec 6, 2024

Tonys-L commented Dec 6, 2024

Tonys-L commented Dec 6, 2024

ppkarwasz commented Dec 6, 2024

Tonys-L commented Dec 9, 2024

vy commented Dec 9, 2024

ppkarwasz commented Dec 9, 2024

alan0428a commented Dec 10, 2024

ppkarwasz commented Dec 10, 2024

When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. #3282

When logging exceptions, the exception stack traces include dynamically generated class names, which leads to a memory leak. #3282

Comments

Tonys-L commented Dec 6, 2024

Description

Configuration

Logs

Reproduction

vy commented Dec 6, 2024

ppkarwasz commented Dec 6, 2024

garydgregory commented Dec 6, 2024

Tonys-L commented Dec 6, 2024

Tonys-L commented Dec 6, 2024

ppkarwasz commented Dec 6, 2024

Tonys-L commented Dec 9, 2024

vy commented Dec 9, 2024

ppkarwasz commented Dec 9, 2024

alan0428a commented Dec 10, 2024

ppkarwasz commented Dec 10, 2024