JDK-8269302 : serviceability/dcmd/framework/InvalidCommandTest.java still fails after JDK-8268433
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 17,18
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: windows
  • CPU: x86_64
  • Submitted: 2021-06-24
  • Updated: 2021-07-15
  • Resolved: 2021-06-25
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 17 JDK 18
17 b29Fixed 18Fixed
Related Reports
Relates :  
Description
The following test failed in the JDK18 CI:

serviceability/dcmd/framework/InvalidCommandTest.java

Here's a snippet from the log file:

test InvalidCommandTest.mainClass(): failure
nsk.share.Failure: Unable to read object from not established PipeIO Listener Thread connection
	at nsk.share.jpda.SocketConnection.readObject(SocketConnection.java:514)
	at nsk.share.jpda.SocketIOPipe.readln(SocketIOPipe.java:190)
	at TestProcessLauncher.launch(TestProcessLauncher.java:71)
	at InvalidCommandTest.mainClass(InvalidCommandTest.java:59)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
	at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
	at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
	at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
	at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
	at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at org.testng.TestRunner.privateRun(TestRunner.java:764)
	at org.testng.TestRunner.run(TestRunner.java:585)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
	at org.testng.SuiteRunner.run(SuiteRunner.java:286)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
	at org.testng.TestNG.runSuites(TestNG.java:1069)
	at org.testng.TestNG.run(TestNG.java:1037)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:833)
Running DCMD 'asdf' through 'PidJcmdExecutor'
Executing command '[c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-18+3-73\\windows-x64-debug.jdk\\jdk-18\\fastdebug\\bin\\jcmd.exe, 33092, asdf]'
[2021-06-24T12:05:35.287232400Z] Gathering output for process 6612
debugee.stdout> Test Java process started!
[2021-06-24T12:05:36.287572500Z] Waiting for completion for process 6612
[2021-06-24T12:05:36.287572500Z] Waiting for completion finished for process 6612
Output and diagnostic info for process 6612 was saved into 'pid-6612-output.log'
[2021-06-24T12:05:36.303186100Z] Waiting for completion for process 6612
[2021-06-24T12:05:36.303186100Z] Waiting for completion finished for process 6612
Command returned with exit code 1
---------------- stdout ----------------
33092:

---------------- stderr ----------------
java.lang.IllegalArgumentException: Unknown diagnostic command

----------------------------------------

test InvalidCommandTest.pid(): success

===============================================
serviceability/dcmd/framework/InvalidCommandTest.java
Total tests run: 4, Passes: 3, Failures: 1, Skips: 0
===============================================

debugee.stdout> Waiting for the quit command from the test ...
#>  
#>  WARNING: switching log to verbose mode,
#>      because error is complained
#>  
debugee.stdout> Test Java process started!
debugee.stdout> Waiting for the quit command from the test ...
# ERROR: binder> Debugee VM has not exited correctly: trying to kill it
The following stacktrace is for failure analysis.
nsk.share.TestFailure: binder> Debugee VM has not exited correctly: trying to kill it
	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
	at nsk.share.Log.complain(Log.java:403)
	at nsk.share.jpda.DebugeeProcess.complain(DebugeeProcess.java:417)
	at nsk.share.jpda.DebugeeProcess.close(DebugeeProcess.java:397)
	at nsk.share.jpda.DebugeeProcess.finalize(DebugeeProcess.java:426)
	at nsk.share.FinalizableObject.finalizeAtExit(FinalizableObject.java:48)
	at nsk.share.Finalizer$FinalizerThread.run(Finalizer.java:122)
------------ Try to print debuggee threads before killing process ------------
Can't print threads info because 'vm' is null
Killing debugee VM process


#>  
#>  SUMMARY: Following errors occured
#>      during test execution:
#>  
# ERROR: binder> Debugee VM has not exited correctly: trying to kill it
----------System.err:(14/872)----------
java.lang.Exception: failures: 1
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:96)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:833)

JavaTest Message: Test threw exception: java.lang.Exception: failures: 1
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.Exception: failures: 1
----------rerun:(45/7091)*----------

This looks like the same failure mode that the following bug tracks:

JDK-8268433 serviceability/dcmd/framework/VMVersionTest.java fails with Unable to send object throw not established PipeIO Listener Thread connection
Comments
The fix for this bug is in jdk-17+29-2551.
26-06-2021

Changeset: 1404e4bf Author: Alex Menkov <amenkov@openjdk.org> Date: 2021-06-25 22:10:48 +0000 URL: https://git.openjdk.java.net/jdk17/commit/1404e4bf44e28cadda3949f9e398e664cb98a5e2
25-06-2021

We're seeing these test failures in the JDK17 CI also. Please integrate this test fix in the JDK17 repo first. I've bumped the priority from P4 -> P3 since we have Tier3 failures in the CI...
25-06-2021

Here's log file snippets for the jdk-18+4-86-tier3 sighting: serviceability/dcmd/framework/VMVersionTest.java ---------------- stderr ---------------- ---------------------------------------- test VMVersionTest.jmx(): success WARNING: IOPipe is not connected test VMVersionTest.mainClass(): failure nsk.share.Failure: Unable to read object from not established PipeIO Listener Thread connection at nsk.share.jpda.SocketConnection.readObject(SocketConnection.java:514) at nsk.share.jpda.SocketIOPipe.readln(SocketIOPipe.java:190) at TestProcessLauncher.launch(TestProcessLauncher.java:71) at VMVersionTest.mainClass(VMVersionTest.java:65) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132) at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599) at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174) at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46) at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822) at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) at org.testng.TestRunner.privateRun(TestRunner.java:764) at org.testng.TestRunner.run(TestRunner.java:585) at org.testng.SuiteRunner.runTest(SuiteRunner.java:384) at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378) at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337) at org.testng.SuiteRunner.run(SuiteRunner.java:286) at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53) at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96) at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218) at org.testng.TestNG.runSuitesLocally(TestNG.java:1140) at org.testng.TestNG.runSuites(TestNG.java:1069) at org.testng.TestNG.run(TestNG.java:1037) at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94) at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:833) debugee.stdout> Test Java process started! debugee.stdout> Waiting for the quit command from the test ... debugee.stdout> Test Java process started! debugee.stdout> Waiting for the quit command from the test ... Running DCMD 'VM.version' through 'MainClassJcmdExecutor' Executing command '[c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-18+4-86\\windows-x64-debug.jdk\\jdk-18\\fastdebug\\bin\\jcmd.exe, testprocess.jar, VM.version]' [2021-06-25T13:09:01.747728500Z] Gathering output for process 29832 [2021-06-25T13:09:03.720280800Z] Waiting for completion for process 29832 [2021-06-25T13:09:03.720280800Z] Waiting for completion finished for process 29832 Output and diagnostic info for process 29832 was saved into 'pid-29832-output.log' [2021-06-25T13:09:03.737174Z] Waiting for completion for process 29832 [2021-06-25T13:09:03.737174Z] Waiting for completion finished for process 29832 Command returned with exit code 0 ---------------- stdout ----------------
25-06-2021

This wrong condition causes the error if ListenerThread.getConnection() reaches "synchronized (this)" section earlier than ListenerThread.run()
25-06-2021

The issue was introduced by JDK-8237388 fix - cycle condition in ListenerThread.getConnection() is incorrect: while (!connection.isConnected() && error != null) { try { wait(); } catch (InterruptedException e) { } } The cycle should wait while connection is established (connection.isConnected() == true) or error occurred (error != null) So "while" condition should be (!connection.isConnected() && error == null)
25-06-2021

With JDK-8268433 fix we see real error - the test fails trying to read "ready" notification from debuggee. But I still don't see code flow to get the error.
24-06-2021

The fix for JDK-8268433 is in jdk-18+3-73 and this latest sighting is in the same build-ID.
24-06-2021