JDK-8248162 : serviceability/attach/RemovingUnixDomainSocketTest.java failed
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 15,16,17
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2020-06-23
  • Updated: 2021-02-18
  • Resolved: 2021-02-10
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
17 b10Fixed
Related Reports
Blocks :  
JDK-8258917 - NativeMemoryTracking is handled by launcher inconsistenly
Relates :  
JDK-8258057 - serviceability/attach/RemovingUnixDomainSocketTest.java doesn't ignore VM warnings
Sub Tasks
JDK-8258911 :  
ProblemList serviceability/attach/RemovingUnixDomainSocketTest.java on Linux-X64 - Resolved
Description
The following test failed in the JDK16 CI:

serviceability/attach/RemovingUnixDomainSocketTest.java

Here's a snippet from the log file:

----------System.out:(32/2659)----------
Command line: ['/opt/mach5/mesos/work_dir/jib-master/install/jdk-16+3-55/linux-x64-debug.jdk/jdk-16/fastdebug/bin/java' '-XX:MaxRAMPercentage=6' '-XX:NativeMemoryTracking=detail' '-cp' '/opt/mach5/mesos/work_dir/slaves/4728e7c1-7e67-490e-be0f-6bbf2a2f33db-S273/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/4d1e47c5-02f5-451b-9881-260887e6d0f3/runs/7eef243f-83c7-4e19-a4c9-431d6cc7da56/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_serviceability/classes/0/serviceability/attach/RemovingUnixDomainSocketTest.d:/opt/mach5/mesos/work_dir/slaves/4728e7c1-7e67-490e-be0f-6bbf2a2f33db-S273/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/4d1e47c5-02f5-451b-9881-260887e6d0f3/runs/7eef243f-83c7-4e19-a4c9-431d6cc7da56/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_serviceability/classes/0/test/lib' 'jdk.test.lib.apps.LingeredApp' 'ae912189-e6d0-4324-9e35-5d0ee36d19ab.lck']
[jcmd]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-16+3-55/linux-x64-debug.jdk/jdk-16/fastdebug/bin/jcmd -J-XX:MaxRAMPercentage=6 -J-XX:NativeMemoryTracking=detail 7890 VM.version
[2020-06-23T05:38:27.493747386Z] Gathering output for process 7924
[jcmd] 7890:
[2020-06-23T05:38:28.885343285Z] Waiting for completion for process 7924
[2020-06-23T05:38:28.885633392Z] Waiting for completion finished for process 7924
jcmd stdout: [Java HotSpot(TM) 64-Bit Server VM version 16-ea+3-55
JDK 16.0.0
];
jcmd  stderr: []
jcmd  exitValue = 0
[2020-06-23T05:38:28.930226202Z] Waiting for completion for process 7924
[2020-06-23T05:38:28.930377247Z] Waiting for completion finished for process 7924
Remove /tmp/.java_pid7890
[jcmd]:/opt/mach5/mesos/work_dir/jib-master/install/jdk-16+3-55/linux-x64-debug.jdk/jdk-16/fastdebug/bin/jcmd -J-XX:MaxRAMPercentage=6 -J-XX:NativeMemoryTracking=detail 7890 VM.version
[2020-06-23T05:38:28.969936254Z] Gathering output for process 7973
[jcmd] 7890:
[jcmd] Java HotSpot(TM) 64-Bit Server VM version 16-ea+3-55
[jcmd] JDK 16.0.0
[2020-06-23T05:38:29.844964734Z] Waiting for completion for process 7973
[2020-06-23T05:38:29.845645978Z] Waiting for completion finished for process 7973
jcmd stdout: [];
jcmd  stderr: [Native Memory Tracking did not setup properly, using wrong launcher?
]
jcmd  exitValue = 0
[2020-06-23T05:38:29.845854340Z] Waiting for completion for process 7973
[2020-06-23T05:38:29.845977432Z] Waiting for completion finished for process 7973
[2020-06-23T05:38:29.850685290Z] Waiting for completion for process 7973
[2020-06-23T05:38:29.850868204Z] Waiting for completion finished for process 7973
 LingeredApp stdout: [];
 LingeredApp stderr: []
 LingeredApp exitValue = 0
----------System.err:(20/1147)----------
[jcmd] Java HotSpot(TM) 64-Bit Server VM warning: Native Memory Tracking did not setup properly, using wrong launcher?
 stdout: [];
 stderr: [Native Memory Tracking did not setup properly, using wrong launcher?
]
 exitValue = 0

java.lang.RuntimeException: stderr was not empty
	at jdk.test.lib.process.OutputAnalyzer.stderrShouldBeEmptyIgnoreVMWarnings(OutputAnalyzer.java:145)
	at RemovingUnixDomainSocketTest.runJCmd(RemovingUnixDomainSocketTest.java:69)
	at RemovingUnixDomainSocketTest.main(RemovingUnixDomainSocketTest.java:88)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
	at java.base/java.lang.Thread.run(Thread.java:832)

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

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: stderr was not empty


test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: stderr was not empty


It's not clear if the failure is due to "Native Memory Tracking
did not setup properly, using wrong launcher?" or if it is
due to "RuntimeException: stderr was not empty".
Comments
Changeset: cc5691c6 Author: Alex Menkov <amenkov@openjdk.org> Date: 2021-02-10 22:17:48 +0000 URL: https://git.openjdk.java.net/jdk/commit/cc5691c6
10-02-2021
Filtering out "NativeMemoryTracking" resolves this issue, but I believe we have more general issue with launcher. I filed JDK-8258917. We have some other tests which uses OutputAnalyzer.stderrShouldBeEmptyIgnoreVMWarnings (they run other tools like jhsdb, jcmd): test/hotspot/jtreg/serviceability/sa/ClhsdbJstackXcompStress.java test/hotspot/jtreg/serviceability/sa/JhsdbThreadInfoTest.java test/hotspot/jtreg/serviceability/sa/sadebugd/DebugdConnectTest.java test/hotspot/jtreg/serviceability/sa/TestJhsdbJstackLock.java test/jdk/sun/tools/jcmd/TestJcmdDefaults.java test/jdk/sun/tools/jcmd/TestJcmdSanity.java OutputAnalyzer.stderrShouldBeEmptyIgnoreVMWarnings ignores all VM warnings (including NMT one). I think it would be better to update stderrShouldBeEmptyIgnoreVMWarnings to ignore only "safe" warnings (like deprecation) and use it in all tests
24-12-2020
[~amenkov] - I took a look at [~pchilanomate]'s suggestion for a fix and checked it out on my macOSX machine with this option: '-XX:NativeMemoryTracking=detail' $ git diff diff --git a/test/hotspot/jtreg/serviceability/attach/RemovingUnixDomainSocketTest.java b/test/hotspot/jtreg/serviceability/attach/RemovingUnixDomainSocketTest.java index e07f91ed193..fb787b5b770 100644 --- a/test/hotspot/jtreg/serviceability/attach/RemovingUnixDomainSocketTest.java +++ b/test/hotspot/jtreg/serviceability/attach/RemovingUnixDomainSocketTest.java @@ -47,7 +47,11 @@ public class RemovingUnixDomainSocketTest { private static void runJCmd(long pid) throws InterruptedException, IOException { JDKToolLauncher jcmd = JDKToolLauncher.createUsingTestJDK("jcmd"); - jcmd.addVMArgs(Utils.getFilteredTestJavaOpts("-showversion")); + // Filter out/Ignore '-showversion' option since this test doesn't + // expect or care about version info. + // Filter out/Ignore 'NativeMemoryTracking' options since they do + // not work with jcmd launchers. + jcmd.addVMArgs(Utils.getFilteredTestJavaOpts("-showversion", "NativeMemoryTracking")); jcmd.addToolArg(Long.toString(pid)); jcmd.addToolArg("VM.version"); Without the above fix, the test failed in release, fastdebug and slowdebug configs and passed with the option.
23-12-2020
When executing jcmd, JLI_Launch() is called from main with javaargs = true (-J-ms8m -m jdk.jcmd/sun.tools.jcmd.JCmd), so !IsJavaArgs() is false and SetJvmEnvironment() which sets the environment variable NMT_LEVEL_ is never called. Therefore the test will always fail when -XX:NativeMemoryTracking is specified. Before JDK-8258057, the stderr output was almost always captured by the wrong StreamPumper so the failure was intermittent. I think a possible fix would be to just filter the NativeMemoryTracking option when launching jcmd, like the test already does with "-showversion": - jcmd.addVMArgs(Utils.getFilteredTestJavaOpts("-showversion")); + jcmd.addVMArgs(Utils.getFilteredTestJavaOpts("-showversion", "NativeMemoryTracking"));
22-12-2020
After fixing JDK-8258057 (now the test ignores only "deprecated" warnings) the test fails quite often Looks like the problem is with all j-command launchers. But other tests do not verifies command stderr or ignore all VM warnings
21-12-2020
Filed JDK-8258057.
10-12-2020
Thanks for the analysis [~pchilanomate]! I did not look at the test. It sounds like the test logic is significantly flawed.
10-12-2020
I can take the new bug [~dholmes]. This new failure mode due to biased locking being enabled is intermittent (fails very rarely actually), so it took me some time to figure it out given that we are also already ignoring VM warnings in the test (out.stderrShouldBeEmptyIgnoreVMWarnings() on line 69). It turns out that ProcessTools.startProcess() starts the process and creates its own StreamPumper objects to process stdout and stderr. Those will consume the output of the process and print it to System.out and System.err respectively, with some minor line formatting. Later we create the new OutputAnalyzer object, which also creates its own StreamPumper objects to process the stdout and stderr of the executed process. This time the output consumed is written to a ByteArrayOutputStream instead, and later read with getStdout() and getStderr(). This two sets of StreamPumper objects conflict with each other since they are consuming from the same streams. In the failing cases, part of the stderr output is read by one and part by the other one. In particular, the StreamPumper processing thread created in ProcessTools.startProcess() consumes "OpenJDK 64-Bit Server VM warning:", while the one created by OutputAnalyzer consumes the rest, i.e "Option UseBiasedLocking was deprecated in version 15.0 and will likely be removed in a future release.". So now since out.getStderr() is not empty and does not contain the string "VM warning:" anymore, the test fails.
10-12-2020
I would expect it to fail every time it is run with an explicit biased-locking flag applied - which should now be the case in tier3. I would not think it the role of this test to detect unexpected warnings. We can have warnings issued for numerous reasons during testing and we don't want tests that fail because of such "unexpected" output. The only solution then would be to either create a list of known good warnings that can be ignored, or else always run the test with full control over flags so that a flag related warning can never happen incidentally. But the latter has its own problems as it means we don't test this test under different GC/JIT/etc configuration settings. Happy to file a new bug to deal with the new warning.
10-12-2020
I assume it fails every time now? Is that correct? This biased-locking failure is different than original reason this CR was filed, which was due to a intermittent warning message that read "Native Memory Tracking did not setup properly, using wrong launcher". Ignoring warnings in the output would fix both problems, but also can hide problems, and I'd consider the NMT warning one we want to figure out and not hide.
09-12-2020
The test needs to ignore VM warnings i.e. allow them to appear in stderr, but nothing else. There is an API in OutputAnalyzer precisely for this. The test currently fails due to: [Java HotSpot(TM) 64-Bit Server VM warning: Option UseBiasedLocking was deprecated in version 15.0 and will likely be removed in a future release. (we just enabled additional biased-locking testing in tier3.)
09-12-2020
stderr: [Native Memory Tracking did not setup properly, using wrong launcher? ] NMT needs to be enabled very early on in the JVM startup process, before the parsing of command line arguments. For this reason the launcher (java.c) is involved and sets up an environment variable called NMT_LEVEL_<pid>. This is read early on when the VM starts up by MemTracker::init_tracking_level. By the time we get to the argument parsing code that produces the above message, it's not actually trying to enable NMT, but simply verifying that the current NMT level matches what is being requested. No idea why they don't match up. The suggestion is that java.c (or some other NMT aware launcher) was not used, but I don't see how.
23-06-2020
The test expects jcmd exits with exitCode == 0 and its stderr is empty (i.e. no errors occured). In the case exitCode is zero, but for some reason we have the warning in stderr. Removing requirement for empty stderr does not looks like a good fix. The question why the warning is generated.
23-06-2020