JDK-8228625 : [TESTBUG] sun/tools/jhsdb/JShellHeapDumpTest.java fails with RuntimeException 'JShellToolProvider' missing from stdout/stderr
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 11.0.5,14
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2019-07-25
  • Updated: 2021-06-29
  • Resolved: 2019-09-26
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 11 JDK 13 JDK 14
11.0.6-oracleFixed 13.0.4Fixed 14 b17Fixed
Related Reports
Relates :  
JDK-8231288 - "jhsdb jmap" test needed to reproduce issues that used to be reproduced by JShellHeapDumpTest
Relates :  
JDK-8230872 - sun/tools/jhsdb/JShellHeapDumpTest.java fails with RuntimeException: Test ERROR java.io.EOFException
Relates :  
JDK-8225715 - jhsdb jmap fails to write binary heap dump of a jshell process
Relates :  
JDK-8269556 - sun/tools/jhsdb/JShellHeapDumpTest.java fails with RuntimeException 'JShellToolProvider' missing from stdout/stderr
Description
----------System.err:(18/1330)----------
java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'JShellToolProvider' missing from stdout/stderr
	at JShellHeapDumpTest.printStackTraces(JShellHeapDumpTest.java:100)
	at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:117)
	at JShellHeapDumpTest.main(JShellHeapDumpTest.java:141)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:565)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:830)
Caused by: java.lang.RuntimeException: 'JShellToolProvider' missing from stdout/stderr
	at JShellHeapDumpTest.printStackTraces(JShellHeapDumpTest.java:97)
	... 8 more

JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'JShellToolProvider' missing from stdout/stderr
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'JShellToolProvider' missing from stdout/stderr
Comments
Fix requrest (13u) Request backport. Test only change, applies clean.
18-05-2020
Fix requrest (11u) Request backport for parity with Oracle 11.0.6. Test only change, applies clean.
12-11-2019
URL: https://hg.openjdk.java.net/jdk/jdk/rev/2c87d191056c User: cjplummer Date: 2019-09-26 21:42:22 +0000
26-09-2019
The test launches a jshell process and then has issues the jmap command on the jshell process to generate an hprof file. The test then uses HprofReader.getStack() to read in the stack traces in the generated hprof file. The test expects to find JShellToolProvider somewhere in the main jshell stack trace the since the bottom of the jshell stack trace looks like: ... jdk.internal.jshell.tool.JShellTool.resetState()V (JShellTool.java:1080) jdk.internal.jshell.tool.JShellTool.start([Ljava/lang/String;)I (JShellTool.java:933) jdk.internal.jshell.tool.JShellToolBuilder.start([Ljava/lang/String;)I (JShellToolBuilder.java:254) jdk.internal.jshell.tool.JShellToolProvider.main([Ljava/lang/String;)V (JShellToolProvider.java:120) When the test fails, the jshell stack trace is not present in the HprofReader.getStack() results. Other standard JDK stack traces are such as the Finalizer thread. So it looks like in general the jmap command and HprofReader.getStack() are working, but the main jstack thread is missing. The reason seems to be that the test does not wait long enough for jshell to launch and be in the main thread. I've seen evidence of this both in how far along the main thread seems to be when passing (it varies from barely started to fully initialized), and also the frequent lack of a few other jshell threads, which I get to always appear by adding a 5 second sleep after the test launches jshell. The fix could be as simple as just adding a short delay (how long is long enough?) or doing a number of retries with a 1 second delay in between (how many retries should be done?). BTW, this is kind of an odd thing to test for in the first place. The pass/fail of this is test is mainly based on whether or not jshell launches. The testing of the heap dump (jmap) is limited to not getting a bad exit value from jmap. Apparently exitcode 134 is a crash.
16-09-2019
Here's yet another failure mode for this test: sun/tools/jhsdb/JShellHeapDumpTest.java ----------System.out:(12/502)---------- Starting Jshell Starting jmap against 28468 [2019-08-05T12:44:41.434367900Z] Gathering output for process 42000 stdout: Attaching to process ID 28468, please wait... stderr: [2019-08-05T12:44:42.106298100Z] Waiting for completion for process 42000 [2019-08-05T12:44:42.106298100Z] Waiting for completion finished for process 42000 [2019-08-05T12:44:42.106298100Z] Waiting for completion for process 42000 [2019-08-05T12:44:42.106298100Z] Waiting for completion finished for process 42000 ----------System.err:(39/2372)---------- Error attaching to process: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process) sun.jvm.hotspot.debugger.DebuggerException: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process) at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.setupVM(HotSpotAgent.java:413) at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.go(HotSpotAgent.java:306) at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.attach(HotSpotAgent.java:141) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:185) at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:118) at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:176) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:369) at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:538) stdout: [Attaching to process ID 28468, please wait... ]; stderr: [] exitValue = 1 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:79) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:90) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:111) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:141) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:565) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:830) Caused by: java.lang.RuntimeException: Expected to get exit value of [0] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:455) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:77) ... 9 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] ----------rerun:(40/5070)*----------
05-08-2019
----------System.err:(31/1555)---------- stdout: [Attaching to process ID 32393, please wait... Debugger attached successfully. Server compiler detected. JVM version is 14-ea+7-200 ]; stderr: [] exitValue = 134 java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:79) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:90) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:111) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:141) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:567) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:830) Caused by: java.lang.RuntimeException: Expected to get exit value of [0] at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:442) at JShellHeapDumpTest.launch(JShellHeapDumpTest.java:77) ... 9 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0] JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: Expected to get exit value of [0]
31-07-2019
----------System.err:(22/1308)---------- illegal bci java.lang.RuntimeException: Test ERROR java.io.EOFException at JShellHeapDumpTest.printStackTraces(JShellHeapDumpTest.java:100) at JShellHeapDumpTest.testHeapDump(JShellHeapDumpTest.java:117) at JShellHeapDumpTest.main(JShellHeapDumpTest.java:141) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:565) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:830) Caused by: java.io.EOFException at java.base/java.io.DataInputStream.readInt(DataInputStream.java:397) at jdk.test.lib.hprof.parser.HprofReader.read(HprofReader.java:229) at jdk.test.lib.hprof.parser.Reader.getStack(Reader.java:128) at JShellHeapDumpTest.printStackTraces(JShellHeapDumpTest.java:95) ... 8 more JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.io.EOFException JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Test ERROR java.io.EOFException
31-07-2019
There seem to be a few different failures with this test. I suggest we track them together for now.
31-07-2019