OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other #18556

pshipton · 2023-12-04T16:38:50Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/103
jdk_lang_1
java/lang/invoke/lambda/LogGeneratedClassesTest.java

21:43:31  Timeout refired 960 times
21:43:31  Timeout information:
21:43:31  Running jcmd on process 3231992
21:43:31  Dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/aqa-tests/TKG/output_17014839509011/jdk_lang_1/work/scratch/0/core.20231201.214315.3231992.0001.dmp
21:43:31  Dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/aqa-tests/TKG/output_17014839509011/jdk_lang_1/work/scratch/0/javacore.20231201.214328.3231992.0002.txt
21:43:31  Running jstack on process 3231992
21:43:31  2023-12-01T21:43:28.981766665
21:43:31  Virtual machine: 3231992 JVM information:
21:43:31  JRE 11 Linux s390x-64-Bit 20231201_685 (JIT enabled, AOT enabled)
21:43:31  OpenJ9   - 244201c2b45
21:43:31  OMR      - 69bd2849661
21:43:31  JCL      - 72e4c5d71e3 based on jdk-11.0.22+5
21:43:31  
21:43:31  "main" prio=5 Id=1 WAITING
21:43:31  	at [email protected]/java.lang.Object.waitImpl(Native Method)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:251)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:219)
21:43:31  	at [email protected]/java.lang.Thread.join(Thread.java:766)
21:43:31  	at [email protected]/java.lang.Thread.join(Thread.java:721)
21:43:31  	at app//com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:198)
21:43:31  	at app//com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:306)
21:43:31  	at app//com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:233)
21:43:31  	at app//com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:70)
21:43:31  
21:43:31  "JIT Compilation Thread-000" prio=10 Id=3 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-001 Suspended" prio=10 Id=4 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-002 Suspended" prio=10 Id=5 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-003 Suspended" prio=10 Id=6 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-004 Suspended" prio=10 Id=7 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-005 Suspended" prio=10 Id=8 RUNNABLE
21:43:31  
21:43:31  "JIT Compilation Thread-006 Suspended" prio=10 Id=9 RUNNABLE
21:43:31  
21:43:31  "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=10 RUNNABLE
21:43:31  
21:43:31  "JIT-SamplerThread" prio=10 Id=11 TIMED_WAITING
21:43:31  
21:43:31  "IProfiler" prio=5 Id=12 RUNNABLE
21:43:31  
21:43:31  "Common-Cleaner" prio=8 Id=2 TIMED_WAITING
21:43:31  	at [email protected]/java.lang.Object.waitImpl(Native Method)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:251)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:219)
21:43:31  	at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
21:43:31  	at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:148)
21:43:31  	at [email protected]/java.lang.Thread.run(Thread.java:839)
21:43:31  	at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:161)
21:43:31  
21:43:31  "Concurrent Mark Helper" prio=1 Id=13 RUNNABLE
21:43:31  
21:43:31  "GC Worker" prio=5 Id=14 RUNNABLE
21:43:31  
21:43:31  "GC Worker" prio=5 Id=15 RUNNABLE
21:43:31  
21:43:31  "GC Worker" prio=5 Id=16 RUNNABLE
21:43:31  
21:43:31  "Finalizer thread" prio=5 Id=17 RUNNABLE
21:43:31  
21:43:31  "Attach API wait loop" prio=10 Id=20 RUNNABLE
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
21:43:31  
21:43:31  "pool-1-thread-1" prio=5 Id=21 TIMED_WAITING
21:43:31  	at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
21:43:31  	at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
21:43:31  	at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123)
21:43:31  	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
21:43:31  	at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
21:43:31  	at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
21:43:31  	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
21:43:31  	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
21:43:31  	at [email protected]/java.lang.Thread.run(Thread.java:839)
21:43:31  
21:43:31  "ClassByNameCache Reaper" prio=5 Id=43 WAITING
21:43:31  	at [email protected]/java.lang.Object.waitImpl(Native Method)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:251)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:219)
21:43:31  	at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
21:43:31  	at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:109)
21:43:31  	at [email protected]/java.io.ClassByNameCache$Reaper.run(ClassByNameCache.java:232)
21:43:31  	at [email protected]/java.lang.Thread.run(Thread.java:839)
21:43:31  
21:43:31  "process reaper (pid 3237752)" prio=10 Id=139 RUNNABLE
21:43:31  	at [email protected]/java.lang.ProcessHandleImpl.waitForProcessExit0(Native Method)
21:43:31  	at [email protected]/java.lang.ProcessHandleImpl$1.run(ProcessHandleImpl.java:141)
21:43:31  	at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
21:43:31  	at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
21:43:31  	at [email protected]/java.lang.Thread.run(Thread.java:839)
21:43:31  
21:43:31  "AgentVMThread" prio=5 Id=311 RUNNABLE
21:43:31  	at [email protected]/java.io.FileInputStream.readBytes(Native Method)
21:43:31  	at [email protected]/java.io.FileInputStream.read(FileInputStream.java:279)
21:43:31  	at [email protected]/java.io.BufferedInputStream.read1(BufferedInputStream.java:290)
21:43:31  	at [email protected]/java.io.BufferedInputStream.read(BufferedInputStream.java:351)
21:43:31  	- locked java.lang.ProcessImpl$ProcessPipeInputStream@18c36758
21:43:31  	at [email protected]/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
21:43:31  	at [email protected]/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
21:43:31  	at [email protected]/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
21:43:31  	- locked java.io.InputStreamReader@a716529
21:43:31  	at [email protected]/java.io.InputStreamReader.read(InputStreamReader.java:181)
21:43:31  	at [email protected]/java.io.BufferedReader.fill(BufferedReader.java:161)
21:43:31  	at [email protected]/java.io.BufferedReader.readLine(BufferedReader.java:326)
21:43:31  	- locked java.io.InputStreamReader@a716529
21:43:31  	at [email protected]/java.io.BufferedReader.readLine(BufferedReader.java:392)
21:43:31  	at LUtils.doExec(LUtils.java:111)
21:43:31  	at LUtils.doExec(LUtils.java:83)
21:43:31  	at LogGeneratedClassesTest.testDumpDirNotExist(LogGeneratedClassesTest.java:142)
21:43:31  	at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
21:43:31  	at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
21:43:31  	at [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:43:31  	at [email protected]/java.lang.reflect.Method.invoke(Method.java:572)
21:43:31  	at app//org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
21:43:31  	at app//org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
21:43:31  	at app//org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
21:43:31  	at app//org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
21:43:31  	at app//org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
21:43:31  	at app//org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
21:43:31  	at app//org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
21:43:31  	at app//org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
21:43:31  	at [email protected]/java.util.ArrayList.forEach(ArrayList.java:1541)
21:43:31  	at app//org.testng.TestRunner.privateRun(TestRunner.java:764)
21:43:31  	at app//org.testng.TestRunner.run(TestRunner.java:585)
21:43:31  	at app//org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
21:43:31  	at app//org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
21:43:31  	at app//org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
21:43:31  	at app//org.testng.SuiteRunner.run(SuiteRunner.java:286)
21:43:31  	at app//org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
21:43:31  	at app//org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
21:43:31  	at app//org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
21:43:31  	at app//org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
21:43:31  	at app//org.testng.TestNG.runSuites(TestNG.java:1069)
21:43:31  	at app//org.testng.TestNG.run(TestNG.java:1037)
21:43:31  	at app//com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
21:43:31  	at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
21:43:31  	at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
21:43:31  	at [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:43:31  	at [email protected]/java.lang.reflect.Method.invoke(Method.java:572)
21:43:31  	at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
21:43:31  	at [email protected]/java.lang.Thread.run(Thread.java:839)
21:43:31  
21:43:31  "file lock watchdog" prio=10 Id=313 TIMED_WAITING
21:43:31  	at [email protected]/java.lang.Object.waitImpl(Native Method)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:251)
21:43:31  	at [email protected]/java.lang.Object.wait(Object.java:219)
21:43:31  	at [email protected]/java.util.TimerThread.mainLoop(Timer.java:592)
21:43:31  	at [email protected]/java.util.TimerThread.run(Timer.java:533)
21:43:31  
21:43:31  "Attachment portNumber: 36609" prio=10 Id=315 RUNNABLE
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
21:43:31  	at [email protected]/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
21:43:31  
21:43:31  
21:43:31  --- Timeout information end.

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

pshipton · 2023-12-04T16:42:38Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/108/
jdk_lang_0
java/lang/invoke/lambda/LogGeneratedClassesTest.java

21:56:30  Unable to visit NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES
21:56:30  Unable to visit DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: DUMP_LAMBDA_PROXY_CLASS_FILES
21:56:30  java.lang.Exception: failures: 1
21:56:30  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:104)
21:56:30  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
21:56:30  	at java.base/java.lang.reflect.Method.invoke(Method.java:586)
21:56:30  	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
21:56:30  	at java.base/java.lang.Thread.run(Thread.java:1595)
21:56:30  
21:56:30  JavaTest Message: Test threw exception: java.lang.Exception
21:56:30  JavaTest Message: shutting down test
21:56:30  
21:56:30  STDOUT:
21:56:30  config LogGeneratedClassesTest.setup(): success
21:56:30  test LogGeneratedClassesTest.testDumpDirIsFile(): failure
21:56:30  java.lang.AssertionError: only show error once expected [1] but found [2]
21:56:30  	at org.testng.Assert.fail(Assert.java:99)
21:56:30  	at org.testng.Assert.failNotEquals(Assert.java:1037)
21:56:30  	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
21:56:30  	at org.testng.Assert.assertEquals(Assert.java:122)
21:56:30  	at org.testng.Assert.assertEquals(Assert.java:797)
21:56:30  	at LogGeneratedClassesTest.testDumpDirIsFile(LogGeneratedClassesTest.java:177)

pshipton · 2023-12-09T21:41:20Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/108 - timeout

pshipton · 2023-12-12T17:47:13Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_1/52/
jdk_lang_1
java/lang/invoke/lambda/LogGeneratedClassesTest.java

07:34:12  Unable to visit NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES
07:34:12  Unable to visit DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: DUMP_LAMBDA_PROXY_CLASS_FILES
07:34:12  java.lang.Exception: failures: 1
07:34:12  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:104)
07:34:12  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
07:34:12  	at java.base/java.lang.reflect.Method.invoke(Method.java:586)
07:34:12  	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
07:34:12  	at java.base/java.lang.Thread.run(Thread.java:1595)
07:34:12  
07:34:12  JavaTest Message: Test threw exception: java.lang.Exception
07:34:12  JavaTest Message: shutting down test
07:34:12  
07:34:12  STDOUT:
07:34:12  config LogGeneratedClassesTest.setup(): success
07:34:12  test LogGeneratedClassesTest.testDumpDirIsFile(): failure
07:34:12  java.lang.AssertionError: only show error once expected [1] but found [2]
07:34:12  	at org.testng.Assert.fail(Assert.java:99)
07:34:12  	at org.testng.Assert.failNotEquals(Assert.java:1037)
07:34:12  	at org.testng.Assert.assertEqualsImpl(Assert.java:140)
07:34:12  	at org.testng.Assert.assertEquals(Assert.java:122)
07:34:12  	at org.testng.Assert.assertEquals(Assert.java:797)
07:34:12  	at LogGeneratedClassesTest.testDumpDirIsFile(LogGeneratedClassesTest.java:177)

pshipton · 2023-12-14T13:32:05Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/111

pshipton · 2024-01-04T21:51:24Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/125 - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_0/134 - only show error once expected [1] but found [2]

pshipton · 2024-01-08T00:46:49Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_OMR_testList_1/66 - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_s390x_linux_OMR_testList_1/65 - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_0/59 - only show error once expected [1] but found [2]

pshipton · 2024-01-08T13:19:24Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/132/ - only show error once expected [1] but found [2]

pshipton · 2024-01-09T19:46:06Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_OMR_testList_1/72/ - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_1/38/ - timeout

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/136/ - only show error once expected [1] but found [2]

pshipton · 2024-01-10T14:58:49Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/129/ - timeout

pshipton · 2024-01-15T17:25:41Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/137/ - expected [1] but found [2]

This type of failure may be due to the following

20:22:06  Unable to visit NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: NotExist/DUMP_LAMBDA_PROXY_CLASS_FILES
20:22:06  Unable to visit DUMP_LAMBDA_PROXY_CLASS_FILES: java.nio.file.NoSuchFileException: DUMP_LAMBDA_PROXY_CLASS_FILES

pshipton · 2024-01-18T14:16:09Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_s390x_linux_OMR_testList_1/69/ - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_s390x_linux_OMR_testList_0/70 - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_linux_OMR_testList_1/41 x 2 - timeout

pshipton · 2024-01-24T22:53:00Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_s390x_linux_OMR_testList_0/72/ - timeout

pshipton · 2024-01-26T05:00:51Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/137/ - timeout

It continues to occur, I don't think I need to keep logging all the failures.

tajila · 2024-01-30T14:01:43Z

@singh264 Please take a look at this

singh264 · 2024-02-02T20:26:03Z

I have been unable to reproduce the timout error in LogGeneratedClassesTest locally on a x86_64 Linux machine with jdk11, jdk17 and jdk21.

I was able to reproduce the intermittent assert error in LogGeneratedClassesTest.testDumpDirIsFile locally on a x86_64 Linux machine with jdk21: java.lang.AssertionError: only show error once expected [1] but found [2]. The test creates a file named DUMP_LAMBDA_PROXY_CLASS_FILES (instead of a directory) and checks for an error message DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory in the output of the java command in the test. The java command in the test runs TestLambda with -Djdk.invoke.LambdaMetafactory.dumpProxyClassFiles which results in a request to add the lambda proxy class files in a directory named DUMP_LAMBDA_PROXY_CLASS_FILES.

package com.example;
public class TestLambda {
    interface I {
        int foo();
    }   
    public static void main(String[] args) { 
        System.setSecurityManager(new SecurityManager()); <-----
        I lam = () -> 10;
        Runnable r = () -> {
            System.out.println("Runnable");
        };
        r.run();
        System.out.println("Finish");
    }
}

@Test
public void testDumpDirIsFile() throws IOException {
    Path testDir = Path.of("notDir");
    Path dumpFile = testDir.resolve(DUMP_LAMBDA_PROXY_CLASS_FILES);
    Files.createDirectory(testDir);
    Files.createFile(dumpFile); <-----
    assertTrue(Files.isRegularFile(dumpFile));
    TestResult tr = doExec(JAVA_CMD.getAbsolutePath(),
                           "-cp", "..",
                           "-Duser.dir=" + testDir.toAbsolutePath(),
                           "-Djava.security.manager=allow",
                           "-Djdk.invoke.LambdaMetafactory.dumpProxyClassFiles", <-----
                           "com.example.TestLambda"); <------
    assertEquals(tr.testOutput.stream()
                              .filter(s -> s.contains("DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory"))
                              .count(),
                 1, "only show error once");
    assertTrue(tr.exitValue != 0);
}

An output of the java command in the test (when it passes) indicates that the error message is generated in the main thread by ClassFileDumper.validateDumpDir during the initialization of SecurityManager.

Exception in thread "main" java.lang.BootstrapMethodError: java.lang.ExceptionInInitializerError
        at java.base/java.lang.SecurityManager.addNonExportedPackages(SecurityManager.java:1232)
        at java.base/java.lang.SecurityManager.<clinit>(SecurityManager.java:1223)
        at com.example.TestLambda.main(TestLambda.java:7)
Caused by: java.lang.ExceptionInInitializerError
        at java.base/java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:175)
        at java.base/java.lang.invoke.LambdaMetafactory.metafactory(LambdaMetafactory.java:331)
        at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:134)
        at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:316)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:274)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:264)
        at java.base/java.lang.invoke.MethodHandleResolver.resolveInvokeDynamic(MethodHandleResolver.java:195)
        ... 3 more
Caused by: java.lang.IllegalArgumentException: Path DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory <-----
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:169)
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:157)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
        at java.base/jdk.internal.util.ClassFileDumper.validateDumpDir(ClassFileDumper.java:157)
        at java.base/jdk.internal.util.ClassFileDumper.<init>(ClassFileDumper.java:87)
        at java.base/jdk.internal.util.ClassFileDumper.getInstance(ClassFileDumper.java:66)
        at java.base/java.lang.invoke.InnerClassLambdaMetafactory.<clinit>(InnerClassLambdaMetafactory.java:95)
        ... 9 more

An output of the java command in the test (when it fails) indicates that the error message appears twice in two separate threads. In addition to the main thread, the error message is generated in the Attach API initializer thread during the initialization of InternalCRIUSupport.

Exception in thread "main" java.lang.BootstrapMethodError: java.lang.ExceptionInInitializerError
        at java.base/java.lang.SecurityManager.addNonExportedPackages(SecurityManager.java:1232)
Exception in thread "Attach API initializer" java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError: java.lang.invoke.InnerClassLambdaMetafactory (initialization failure)
        at java.base/openj9.internal.criu.InternalCRIUSupport.<clinit>(InternalCRIUSupport.java:215)
        at java.base/java.util.Timer.schedule(Timer.java:214)
        at java.base/openj9.internal.tools.attach.target.FileLock.lockFile(FileLock.java:100)
        at java.base/openj9.internal.tools.attach.target.CommonDirectory.obtainControllerLock(CommonDirectory.java:148)
        at java.base/openj9.internal.tools.attach.target.AttachHandler.createFiles(AttachHandler.java:190)
        at java.base/openj9.internal.tools.attach.target.AttachHandler.initialize(AttachHandler.java:296)
        at java.base/openj9.internal.tools.attach.target.AttachHandler.run(AttachHandler.java:229)
        at java.base/java.lang.SecurityManager.<clinit>(SecurityManager.java:1223)
        at com.example.TestLambda.main(TestLambda.java:7)
Caused by: java.lang.ExceptionInInitializerError                                                              
        at java.base/java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:175)
        at java.base/java.lang.invoke.LambdaMetafactory.metafactory(LambdaMetafactory.java:331)
        at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:134)
        at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:316)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:274)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:264)
        at java.base/java.lang.invoke.MethodHandleResolver.resolveInvokeDynamic(MethodHandleResolver.java:195)
        ... 3 more
Caused by: java.lang.IllegalArgumentException: Path DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory <-----
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:169)
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:157)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
        at java.base/jdk.internal.util.ClassFileDumper.validateDumpDir(ClassFileDumper.java:157)
        at java.base/jdk.internal.util.ClassFileDumper.<init>(ClassFileDumper.java:87)
        at java.base/jdk.internal.util.ClassFileDumper.getInstance(ClassFileDumper.java:66)
        at java.base/java.lang.invoke.InnerClassLambdaMetafactory.<clinit>(InnerClassLambdaMetafactory.java:95)
        ... 9 more
Caused by: java.lang.NoClassDefFoundError: java.lang.invoke.InnerClassLambdaMetafactory (initialization failure)
        at java.base/java.lang.J9VMInternals.initializationAlreadyFailed(J9VMInternals.java:146)
        at java.base/java.lang.invoke.LambdaMetafactory.metafactory(LambdaMetafactory.java:331)
        at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:134)
        at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:316)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:274)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:264)
        at java.base/java.lang.invoke.MethodHandleResolver.resolveInvokeDynamic(MethodHandleResolver.java:195)
        ... 7 more
Caused by: java.lang.ExceptionInInitializerError                                                               
        at java.base/java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:175)
        at java.base/java.lang.invoke.LambdaMetafactory.metafactory(LambdaMetafactory.java:331)
        at java.base/java.lang.invoke.BootstrapMethodInvoker.invoke(BootstrapMethodInvoker.java:134)
        at java.base/java.lang.invoke.CallSite.makeSite(CallSite.java:316)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:274)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:264)
        at java.base/java.lang.invoke.MethodHandleResolver.resolveInvokeDynamic(MethodHandleResolver.java:195)
        at java.base/java.lang.SecurityManager.addNonExportedPackages(SecurityManager.java:1232)
        at java.base/java.lang.SecurityManager.<clinit>(SecurityManager.java:1223)
        at com.example.TestLambda.main(TestLambda.java:7)
Caused by: java.lang.IllegalArgumentException: Path DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory <-----
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:169)
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:157)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
        at java.base/jdk.internal.util.ClassFileDumper.validateDumpDir(ClassFileDumper.java:157)
        at java.base/jdk.internal.util.ClassFileDumper.<init>(ClassFileDumper.java:87)
        at java.base/jdk.internal.util.ClassFileDumper.getInstance(ClassFileDumper.java:66)
        at java.base/java.lang.invoke.InnerClassLambdaMetafactory.<clinit>(InnerClassLambdaMetafactory.java:95)
        ... 9 more

singh264 · 2024-02-05T15:55:31Z

@tajila given the intermittent assert error in LogGeneratedClassesTest.testDumpDirIsFile, where the error message appears twice in two separate threads (main thread and Attach API initializer), and considering that the test does not seem to enable criu support with -XX:+EnableCRIUSupport, export criu modules with --add-exports java.base/openj9.internal.criu=ALL-UNNAMED, or use any criu features like InternalCRIUSupport, I would like to understand:

How could criu features be initialized by the Attach API initializer thread during the test?
Would the expected behaviour be that no criu features are initialized during the test?

tajila · 2024-02-05T16:29:58Z

How could criu features be initialized by the Attach API initializer thread during the test?

I think thats the key. Why does the application require InternalCRIUSupport. My guess is that it is using some crypto/security APIs. We have a certain set we allow when CRIu is enabled. So its probably checking if criu is enabled. You'd need to find which API is requesting that check.

singh264 · 2024-02-07T17:25:27Z

Why does the application require InternalCRIUSupport. My guess is that it is using some crypto/security APIs. We have a certain set we allow when CRIu is enabled. So its probably checking if criu is enabled.

@tajila requesting your input on the preferred approach to resolve the intermittent assert error in the test LogGeneratedClassesTest.testDumpDirIsFile.

The intermittent assert error in the test java.lang.AssertionError: only show error once expected [1] but found [2] occurs when the test creates a file named DUMP_LAMBDA_PROXY_CLASS_FILES (instead of a directory), runs TestLambda in a java command with -Djdk.invoke.LambdaMetafactory.dumpProxyClassFiles, and finds two instances of the error message DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory in the output of the java command.

package com.example;
public class TestLambda {
    interface I {
        int foo();
    }   
    public static void main(String[] args) { 
        System.setSecurityManager(new SecurityManager()); <-----
        I lam = () -> 10;
        Runnable r = () -> {
            System.out.println("Runnable");
        };
        r.run();
        System.out.println("Finish");
    }
}

The first instance of the error message in the main thread is expected and occurs during the initialization of SecurityManager, which includes lambda expressions.

The second instance of the error message in the Attach API initializer thread is intermittent and occurs during the initialization of InternalCRIUSupport, which includes a lambda expression. The reference to InternalCRIUSupport is in System.setSecurityManager.

openj9/jcl/src/java.base/share/classes/java/lang/System.java

Lines 1237 to 1247 in 01d6c8e

    
           /*[IF JAVA_SPEC_VERSION >= 17]*/ 
        
           @Deprecated(since="17", forRemoval=true) 
        
           @CallerSensitive 
        
           /*[ENDIF] JAVA_SPEC_VERSION >= 17 */ 
        
           public static void setSecurityManager(final SecurityManager s) { 
        
           /*[IF CRIU_SUPPORT]*/ 
        
           	if (openj9.internal.criu.InternalCRIUSupport.isCRIUSupportEnabled()) { 
        
           		/*[MSG "K0B02", "Enabling a SecurityManager currently unsupported when -XX:+EnableCRIUSupport is specified"]*/ 
        
           		throw new UnsupportedOperationException(Msg.getString("K0B02")); //$NON-NLS-1$ 
        
           	} 
        
           /*[ENDIF] CRIU_SUPPORT */

The error message in the Attach API initializer thread can be avoided with the following apporaches:

Refactor the static block in InternalCRIUSupport to remove use of lambda expression singh264@37e4dce.
Disable CRIU_SUPPORT by default singh264/openj9-openjdk-jdk21@630bd8a.

tajila · 2024-02-08T02:50:24Z

After taking a second look:

Exception in thread "Attach API initializer" java.lang.BootstrapMethodError: java.lang.NoClassDefFoundError: java.lang.invoke.InnerClassLambdaMetafactory (initialization failure)
        at java.base/openj9.internal.criu.InternalCRIUSupport.<clinit>(InternalCRIUSupport.java:215)
        at java.base/java.util.Timer.schedule(Timer.java:214)

The following is interesting because InternalCRIUSupport is in java.base so it should be there all the time regardless of the following

test does not seem to enable criu support with -XX:+EnableCRIUSupport, export criu modules with --add-exports java.base/openj9.internal.criu=ALL-UNNAMED

Do you know what causes the init failure exactly? is it a missing class

eclipse-openj9/openj9#18556 Signed-off-by: Peter Shipton <[email protected]>

pshipton · 2024-02-08T14:05:53Z

Created adoptium/aqa-tests#5047 to exclude the test since it fails too often in the builds.

eclipse-openj9/openj9#18556 Signed-off-by: Peter Shipton <[email protected]>

singh264 · 2024-02-08T15:51:41Z

Do you know what causes the init failure exactly? is it a missing class

The init failure is caused by the absence of ClassFileDumper which is requested during the initialization of InnerClassLambdaMetafactory to add the lambda class files in a directory named DUMP_LAMBDA_PROXY_CLASS_FILES. The error message DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory seems to appear in the main thread before the Attach API initializer thread.

Caused by: java.lang.IllegalArgumentException: Path DUMP_LAMBDA_PROXY_CLASS_FILES is not a directory
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:169)
        at java.base/jdk.internal.util.ClassFileDumper$2.run(ClassFileDumper.java:157)
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:692)
        at java.base/jdk.internal.util.ClassFileDumper.validateDumpDir(ClassFileDumper.java:157)
        at java.base/jdk.internal.util.ClassFileDumper.<init>(ClassFileDumper.java:87) <-----
        at java.base/jdk.internal.util.ClassFileDumper.getInstance(ClassFileDumper.java:66)
        at java.base/java.lang.invoke.InnerClassLambdaMetafactory.<clinit>(InnerClassLambdaMetafactory.java:95) <-----
        ... 9 more

Depends-on: eclipse-openj9/openj9#18968 Issue: eclipse-openj9/openj9#18556 Signed-off-by: Amarpreet Singh <[email protected]>

Fix intermittent LogGeneratedClassesTest failures by removing use of lambda expression in static block of InternalCRIUSupport, which avoids the unexpected creation of lambda class files for InternalCRIUSupport during the test. Issue: eclipse-openj9#18556 Signed-off-by: Amarpreet Singh <[email protected]>

Depends-on: eclipse-openj9/openj9#18968 Issue: eclipse-openj9/openj9#18556 Signed-off-by: Amarpreet Singh <[email protected]>

pshipton · 2024-02-23T20:53:15Z

I assume this can be closed now.

pshipton added the test failure label Dec 4, 2023

hzongaro mentioned this issue Dec 5, 2023

Fix string literal conversion warnings in env #18467

Merged

pshipton added this to the Release 0.44 (Java 8, 11, 17, 21) Apr refresh milestone Dec 12, 2023

pshipton added the comp:vm label Jan 4, 2024

cjjdespres mentioned this issue Jan 9, 2024

Internal JITServer test failures #14538

Open

pshipton added the blocker label Jan 9, 2024

babsingh mentioned this issue Jan 10, 2024

Fix erroneously large section size in ROM walk #18585

Merged

pshipton changed the title ~~OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout~~ OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other Jan 15, 2024

pshipton added the test excluded label Feb 8, 2024

pshipton added a commit to pshipton/openjdk-tests that referenced this issue Feb 8, 2024

Exclude LogGeneratedClassesTest on OpenJ9 for jdk11+

a2c7657

eclipse-openj9/openj9#18556 Signed-off-by: Peter Shipton <[email protected]>

pshipton mentioned this issue Feb 8, 2024

Exclude LogGeneratedClassesTest on OpenJ9 for jdk11+ adoptium/aqa-tests#5047

Merged

LongyuZhang pushed a commit to adoptium/aqa-tests that referenced this issue Feb 8, 2024

Exclude LogGeneratedClassesTest on OpenJ9 for jdk11+ (#5047)

7f68522

eclipse-openj9/openj9#18556 Signed-off-by: Peter Shipton <[email protected]>

singh264 mentioned this issue Feb 16, 2024

Fix intermittent LogGeneratedClassesTest failures #18968

Merged

singh264 added a commit to singh264/aqa-tests that referenced this issue Feb 16, 2024

Include LogGeneratedClassesTest on openj9 for jdk11+

ecb3981

Depends-on: eclipse-openj9/openj9#18968 Issue: eclipse-openj9/openj9#18556 Signed-off-by: Amarpreet Singh <[email protected]>

singh264 mentioned this issue Feb 16, 2024

Include LogGeneratedClassesTest on openj9 for jdk11+ adoptium/aqa-tests#5080

Merged

singh264 mentioned this issue Feb 21, 2024

(0.44) Fix intermittent LogGeneratedClassesTest failures #18988

Merged

JasonFengJ9 pushed a commit to adoptium/aqa-tests that referenced this issue Feb 21, 2024

Include LogGeneratedClassesTest on openj9 for jdk11+ (#5080)

e512a5a

Depends-on: eclipse-openj9/openj9#18968 Issue: eclipse-openj9/openj9#18556 Signed-off-by: Amarpreet Singh <[email protected]>

pshipton removed the test excluded label Feb 23, 2024

pshipton closed this as completed Feb 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other #18556

OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other #18556

pshipton commented Dec 4, 2023

pshipton commented Dec 4, 2023 •

edited

Loading

pshipton commented Dec 9, 2023 •

edited

Loading

pshipton commented Dec 12, 2023

pshipton commented Dec 14, 2023

pshipton commented Jan 4, 2024 •

edited

Loading

pshipton commented Jan 8, 2024 •

edited

Loading

pshipton commented Jan 8, 2024

pshipton commented Jan 9, 2024 •

edited

Loading

pshipton commented Jan 10, 2024

pshipton commented Jan 15, 2024

pshipton commented Jan 18, 2024 •

edited

Loading

pshipton commented Jan 24, 2024

pshipton commented Jan 26, 2024

tajila commented Jan 30, 2024

singh264 commented Feb 2, 2024

singh264 commented Feb 5, 2024

tajila commented Feb 5, 2024

singh264 commented Feb 7, 2024

tajila commented Feb 8, 2024

pshipton commented Feb 8, 2024

singh264 commented Feb 8, 2024

pshipton commented Feb 23, 2024

OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other #18556

OpenJDK java/lang/invoke/lambda/LogGeneratedClassesTest timeout or other #18556

Comments

pshipton commented Dec 4, 2023

pshipton commented Dec 4, 2023 • edited Loading

pshipton commented Dec 9, 2023 • edited Loading

pshipton commented Dec 12, 2023

pshipton commented Dec 14, 2023

pshipton commented Jan 4, 2024 • edited Loading

pshipton commented Jan 8, 2024 • edited Loading

pshipton commented Jan 8, 2024

pshipton commented Jan 9, 2024 • edited Loading

pshipton commented Jan 10, 2024

pshipton commented Jan 15, 2024

pshipton commented Jan 18, 2024 • edited Loading

pshipton commented Jan 24, 2024

pshipton commented Jan 26, 2024

tajila commented Jan 30, 2024

singh264 commented Feb 2, 2024

singh264 commented Feb 5, 2024

tajila commented Feb 5, 2024

singh264 commented Feb 7, 2024

tajila commented Feb 8, 2024

pshipton commented Feb 8, 2024

singh264 commented Feb 8, 2024

pshipton commented Feb 23, 2024

pshipton commented Dec 4, 2023 •

edited

Loading

pshipton commented Dec 9, 2023 •

edited

Loading

pshipton commented Jan 4, 2024 •

edited

Loading

pshipton commented Jan 8, 2024 •

edited

Loading

pshipton commented Jan 9, 2024 •

edited

Loading

pshipton commented Jan 18, 2024 •

edited

Loading