Bug ID: JDK-8289079 java/lang/Thread/jni/AttachCurrentThread/AttachTest.java#id1 failed with "RuntimeException: Test failed"

JDK-8289079 : java/lang/Thread/jni/AttachCurrentThread/AttachTest.java#id1 failed with "RuntimeException: Test failed"

Type: Bug
Component: core-libs
Sub-Component: java.lang
Affected Version: 19

Priority: P4
Status: Resolved
Resolution: Fixed
OS: linux
CPU: x86_64

Submitted: 2022-06-23
Updated: 2022-07-27
Resolved: 2022-06-27

Versions (Unresolved/Resolved/Fixed)

The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.

JDK 19	JDK 20
19 b29Fixed	20Fixed

Related Reports

Relates :

JDK-8287982 - Concurrent implicit attach from native threads crashes VM

Description

The following test failed in the JDK19 CI:

java/lang/Thread/jni/AttachCurrentThread/AttachTest.java#id1

Here's a snippet from the log file:

#section:main
----------messages:(5/274)----------
command: main AttachTest --enable-preview --enable-native-access=ALL-UNNAMED ImplicitAttach 1
reason: User specified action: run main AttachTest --enable-preview --enable-native-access=ALL-UNNAMED ImplicitAttach 1 
Mode: agentvm
Agent id: 307
elapsed time (seconds): 38.026
----------configuration:(16/2053)----------
Boot Layer
  class path: /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/javatest.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jtreg.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/junit.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/hamcrest.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/testng.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jcommander.jar 
              /opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/guice.jar 
  patch:      java.base /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/patches/java.base

Test Layer
  class path: /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/classes/4/java/lang/Thread/jni/AttachCurrentThread/AttachTest_id1.d
              /opt/mach5/mesos/work_dir/jib-master/install/jdk-19+28-2110/src.full/open/test/jdk/java/lang/Thread/jni/AttachCurrentThread
              /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/classes/4/test/lib
              /opt/mach5/mesos/work_dir/jib-master/install/jdk-19+28-2110/src.full/open/test/lib

----------rerun:(30/6037)*----------

<snip>

----------System.out:(10/3125)----------
Command line: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+28-2110/linux-x64-debug.jdk/jdk-19/fastdebug/bin/java -cp /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/classes/4/java/lang/Thread/jni/AttachCurrentThread/AttachTest_id1.d:/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+28-2110/src.full/open/test/jdk/java/lang/Thread/jni/AttachCurrentThread:/opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/classes/4/test/lib:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/javatest.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jtreg.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/junit.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/hamcrest.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/testng.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/jcommander.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/6.1/1/bundles/jtreg-6.1+1.zip/jtreg/lib/guice.jar -Xmx768m -XX:MaxRAMPercentage=4.16667 -Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/tmp -ea -esa -Xcomp -XX:+CreateCoredumpOnCrash -ea -esa -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions -server -XX:+TieredCompilation -XX:-UseCompressedOops -cp /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8763/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2e2b6c9f-97f5-4dfd-874c-f4a97859fcf2/runs/bf95d698-c936-43da-a59f-ae950830bdbd/testoutput/test-support/jtreg_open_test_jdk_jdk_lang/classes/4/java/lang/Thread/jni/AttachCurrentThread/AttachTest_id1.d -Djava.library.path=/opt/mach5/mesos/work_dir/jib-master/install/jdk-19+28-2110/linux-x64-debug.test/jdk/jtreg/native --enable-preview --enable-native-access=ALL-UNNAMED ImplicitAttach 1 ]
[2022-06-23T18:05:16.769697758Z] Gathering output for process 591805
[2022-06-23T18:05:50.614112530Z] Waiting for completion for process 591805
[2022-06-23T18:05:50.774330474Z] Waiting for completion finished for process 591805
Output and diagnostic info for process 591805 was saved into 'pid-591805-output.log'
Thread[#30,Thread-0,5,main]


[2022-06-23T18:05:50.878509029Z] Waiting for completion for process 591805
[2022-06-23T18:05:50.878684541Z] Waiting for completion finished for process 591805
----------System.err:(10/507)----------
java.lang.RuntimeException: Test failed
	at AttachTest.main(AttachTest.java:68)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
	at java.base/java.lang.Thread.run(Thread.java:1589)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Test failed

The "RuntimeException: Test failed" failure mode is not very helpful.

I'm going to start this failure off in hotspot/runtime since my guess
is that this is a JNI attach test failure.

Comments

Changeset: 7e13cdb7 Author: Alan Bateman <alanb@openjdk.org> Date: 2022-06-27 10:22:04 +0000 URL: https://git.openjdk.org/jdk19/commit/7e13cdb799ff21cfcc350e518095dda9ce815b30
27-06-2022
A pull request was submitted for review. URL: https://git.openjdk.org/jdk19/pull/73 Date: 2022-06-26 09:50:11 +0000
26-06-2022
I think I see the issue with the test. The upcall stub is created in a implicit memory session which can be GC'ed and freed before/while the native threads are running. It needs to be changed to use a shared memory session or adding a reachability fence to keep the upcall stub alive.
26-06-2022
Any stdout/stderr from the child process should be in the .jtr but we are missing the child process exit code (133 in this case). The test runs ImplicitAttach three times to create 1, 2, and 4 threads. The failed case the first one where is creates 1 thread. We see this output from the child process: Thread[#30,Thread-0,5,main] so this means the thread was created (with pthread_create) and the upcall invoked the "callback" method. I don't see this thread in the jhsdb output but it since it is very short lived then it may have terminated. The main thread just waits for all threads (one thread in this case) to phone home but the main thread seems to be here: ----------------- 591806 ----------------- "main" #1 prio=5 tid=0x00007f1ec4029d90 nid=591806 waiting on condition [0x00007f1ece2f3000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked 0x00007f1ecdcbd45c __pthread_cond_wait + 0x1fc 0x00007f1eccb12040 os::PlatformMonitor::wait(long) + 0x110 0x00007f1ecca627df Monitor::wait(long) + 0x28f 0x00007f1ecbeb3cba CompileBroker::wait_for_completion(CompileTask) + 0xfa 0x00007f1ecbeb5f23 CompileBroker::compile_method(methodHandle const&, int, int, methodHandle const&, int, CompileTask::CompileReason, DirectiveSet, JavaThread) + 0x613 0x00007f1ecbeb6282 CompileBroker::compile_method(methodHandle const&, int, int, methodHandle const&, int, CompileTask::CompileReason, JavaThread) + 0x82 0x00007f1ecbe815e0 CompilationPolicy::compile(methodHandle const&, int, CompLevel, JavaThread) + 0x110 0x00007f1ecbe836f8 CompilationPolicy::event(methodHandle const&, methodHandle const&, int, int, CompLevel, CompiledMethod, JavaThread) + 0x3a8 0x00007f1ecbc762eb Runtime1::counter_overflow(JavaThread, int, Method) + 0x26b 0x00007f1eb456cbb1 <RuntimeStub> 0x00007f1ead0ec94b java.util.concurrent.locks.AbstractQueuedSynchronizer.signalNextIfShared(java.util.concurrent.locks.AbstractQueuedSynchronizer$Node) bci:0 line:618 (Compiled frame) * java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.util.concurrent.locks.AbstractQueuedSynchronizer$Node, int, boolean, boolean, boolean, long) bci:184 line:684 (Interpreted frame) 0x00007f1ead2b314c * java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(int) bci:21 line:1047 (Compiled frame) * java.util.concurrent.CountDownLatch.await() bci:5 line:230 (Compiled frame) * ImplicitAttach.main(java.lang.String[]) bci:134 line:65 (Compiled frame) 0x00007f1ecc3b7fa5 JavaCalls::call_helper(JavaValue, methodHandle const&, JavaCallArguments, JavaThread) + 0x505 0x00007f1ecc4febb5 jni_invoke_static(JNIEnv_, JavaValue, _jobject, JNICallType, _jmethodID, JNI_ArgumentPusher, JavaThread*) [clone .constprop.1] + 0x385 0x00007f1ecc5020c5 jni_CallStaticVoidMethod + 0x1b5 0x00007f1ece2fb7e5 JavaMain + 0xd65 0x00007f1ece2fea19 ThreadJavaMain + 0x9 I'll see if I can get anything from the core file. The gdb output just shows a SIGTRAP, which I assumed was gdb attaching but maybe it's something else. As I understand it, SIGTRAP is used by some ports for implicit null or polling but not x64.
24-06-2022
I agree with [~dcubed] comment about the unhelpful failure mode. This: int exitValue = outputAnalyzer.getExitValue(); if (exitValue != 0) throw new RuntimeException("Test failed"); should be outputAnalyzer.shouldHaveExitValue(0); so we at least get a diagnostic report. And mea culpa for not catching that in the review.
24-06-2022
This is the new test introduced by JDK-8287982 so reassigning to core-libs and [~alanb].
24-06-2022