JDK-8273187 : jtools tests fail with missing markerName check
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 18
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2021-08-31
  • Updated: 2022-01-21
  • Resolved: 2021-09-20
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 18
18 b16Fixed
Related Reports
Relates :  
JDK-8260265 - UTF-8 by Default
Sub Tasks
JDK-8273197 :  
ProblemList 2 jtools tests due to JDK-8273187 - Resolved
Description
The following tests failed in the JDK18 CI:

   6 sun/tools/jcmd/JcmdOutputEncodingTest.java
   6 sun/tools/jstack/BasicJStackTest.java

There are sightings of this test failure on all platforms in Tier5.

Here's a snippet from one of the log files:

 stderr: []
 exitValue = 0

java.lang.RuntimeException: 'markerName????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????' missing from stdout/stderr 

	at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:221)
	at BasicJStackTest.testJstackUTF8Encoding(BasicJStackTest.java:67)
	at BasicJStackTest.main(BasicJStackTest.java:46)
	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.RuntimeException: 'markerName????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????' missing from stdout/stderr 

JavaTest Message: shutting down test

STATUS:Failed.<EncodeD>60 6d 61 69 6e 27 20 74 68 72 65 77 20 65 78 63 65 70 74 69 6f 6e 3a 20 6a 61 76 61 2e 6c 61 6e 67 2e 52 75 6e 74 69 6d 65 45 78 63 65 70 74 69 6f 6e 3a 20 27 6d 61 72 6b 65 72 4e 61 6d 65 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 e4 bb5 27 20 6d 69 73 73 69 6e 67 20 66 72 6f 6d 20 73 74 64 6f 75 74 2f 73 74 64 65 72 72 </EncodeD>
----------rerun:(40/7002)*----------


The output in question does have a line that contain markerName:

"markerName????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????" #14 prio=5 os_prio=31 cpu=212.90ms elapsed=2.16s tid=0x00007ffc5c00a020 nid=40451 in Object.wait()  [0x0000700007e58000]
   java.lang.Thread.State: WAITING (on object monitor)
Thread: 0x00007ffc5c00a020  [0x9e03] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@18-ea/Native Method)
	- waiting on <0x00000007efaae268> (a java.lang.ProcessImpl)
	at java.lang.Object.wait(java.base@18-ea/Object.java:338)
	at java.lang.ProcessImpl.waitFor(java.base@18-ea/ProcessImpl.java:434)
	- locked <0x00000007efaae268> (a java.lang.ProcessImpl)
	at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:445)
	at BasicJStackTest.jstack(BasicJStackTest.java:86)
	at BasicJStackTest.testJstackUTF8Encoding(BasicJStackTest.java:65)
	at BasicJStackTest.main(BasicJStackTest.java:46)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@18-ea/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@18-ea/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@18-ea/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@18-ea/Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.lang.Thread.run(java.base@18-ea/Thread.java:833)
Comments
Changeset: f71df142 Author: Naoto Sato <naoto@openjdk.org> Date: 2021-09-20 13:38:38 +0000 URL: https://git.openjdk.java.net/jdk/commit/f71df142a97f522b40e90c3105e0e5bd8d5af9a2
20-09-2021
The proposed fix is to pass sun.stdout.encoding=UTF-8 as well as file.encoding so that tool process' System.out is in UTF-8 as well.
17-09-2021
JDK-8260265 was mainly moving the default charset to UTF-8, but it also modified the default System.out/err encoding *not in terminal* to the following: --- - // defaults to Charset.defaultCharset() - setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding"))); - setErr0(newPrintStream(fdErr, props.getProperty("sun.stderr.encoding"))); + // defaults to native.encoding + setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding", StaticProperty.nativeEncoding()))); + setErr0(newPrintStream(fdErr, props.getProperty("sun.stderr.encoding", StaticProperty.nativeEncoding()))); --- So the environment that is not a terminal (e.g. a process created by ProcessBuilder), it now defaults to `native.encoding` instead of Charset.defaultCharset(). Thus the output from ProcessBuilder's process has to be compared with the marker string through the encoder with native.encoding. In case of 'C' locale on macOS, the native.encoding is `US-ASCII`, thus the problem occurs. Before JDK-8260865, it happened to be working because native.encoding == Charset.defaultCharset() == US_ASCII.
02-09-2021
Spotted in the jdk-18+13-659-tier8 CI job set: https://mach5.us.oracle.com/mdash/jobs/mach5-one-jdk-18+13-659-tier8-20210901-2207-24211149/results?search=status%3Afailed%20AND%20-state%3Ainvalid%20AND%20(name%3Asun%2Ftools%2Fjstack%2FBasicJStackTest.java%20OR%20name%3Asun%2Ftools%2Fjcmd%2FJcmdOutputEncodingTest.java) sun/tools/jstack/BasicJStackTest.java sun/tools/jcmd/JcmdOutputEncodingTest.java 2 sightings (1 for each test, so far)
01-09-2021
I ran the tests 3 additional times in release, fast debug and slow debug and did not get any failures.
31-08-2021
Built a new repo with the HEAD just before the fix for: JDK-8260265 UTF-8 by Default $ git log HEAD^! commit 32048536e9ea9245437eb37308e905435cce6305 (HEAD) Author: Ioi Lam <iklam@openjdk.org> Date: Mon Aug 30 21:06:26 2021 +0000 8272343: Remove MetaspaceClosure::FLAG_MASK Reviewed-by: ccheung, minqi $ do_java_test "sun/tools/jcmd/JcmdOutputEncodingTest.java sun/tools/jstack/BasicJStackTest.java java/lang/instrument/BootClassPath/BootClassPathTest.sh" INFO: GNUMAKE=make INFO: GNUMAKE version is: GNU Make 3.81 INFO: JTREG options: INFO: JOBS=1 INFO: TEST_MODE=agentvm INFO: EXTRA_PROBLEM_LISTS=ProblemList-extra.txt INFO: VM_OPTIONS= INFO: test_val=sun/tools/jcmd/JcmdOutputEncodingTest.java sun/tools/jstack/BasicJStackTest.java java/lang/instrument/BootClassPath/BootClassPathTest.sh Test Config: macosx-x86_64-normal-server-release INFO: TIMEOUT_FACTOR=4 Done testing Test Run macosx-x86_64-normal-server-release time: 0.67 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/jdk/sun/tools/jcmd/JcmdOutputEncodingTest.java 1 1 0 0 jtreg:open/test/jdk/sun/tools/jstack/BasicJStackTest.java 1 1 0 0 jtreg:open/test/jdk/java/lang/instrument/BootClassPath/BootClassPathTest.sh 1 1 0 0 Test Config: macosx-x86_64-normal-server-fastdebug INFO: TIMEOUT_FACTOR=6 Done testing Test Run macosx-x86_64-normal-server-fastdebug time: 1.13 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/jdk/sun/tools/jcmd/JcmdOutputEncodingTest.java 1 1 0 0 jtreg:open/test/jdk/sun/tools/jstack/BasicJStackTest.java 1 1 0 0 jtreg:open/test/jdk/java/lang/instrument/BootClassPath/BootClassPathTest.sh 1 1 0 0 Test Config: macosx-x86_64-normal-server-slowdebug INFO: TIMEOUT_FACTOR=12 Done testing Test Run macosx-x86_64-normal-server-slowdebug time: 3.27 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/jdk/sun/tools/jcmd/JcmdOutputEncodingTest.java 1 1 0 0 jtreg:open/test/jdk/sun/tools/jstack/BasicJStackTest.java 1 1 0 0 jtreg:open/test/jdk/java/lang/instrument/BootClassPath/BootClassPathTest.sh 1 1 0 0 Total test time: 5.08 minutes. While not proof, this is a strong indicator that these test failures: sun/tools/jcmd/JcmdOutputEncodingTest.java sun/tools/jstack/BasicJStackTest.java is a regression caused by JDK-8260265.
31-08-2021
Reproduced the two test failures on my MBP13 with release, fastdebug and slow debug bits. Attached the logs: $ unzip -l 8273187-repro-logs.zip Archive: 8273187-repro-logs.zip Length Date Time Name --------- ---------- ----- ---- 71961 08-31-2021 11:48 test_failures.2021-08-31-114444/BasicJStackTest.jtr.fastdebug 62964 08-31-2021 11:45 test_failures.2021-08-31-114444/BasicJStackTest.jtr.release 71975 08-31-2021 11:52 test_failures.2021-08-31-114444/BasicJStackTest.jtr.slowdebug 33420 08-31-2021 11:47 test_failures.2021-08-31-114444/JcmdOutputEncodingTest.jtr.fastdebug 31068 08-31-2021 11:44 test_failures.2021-08-31-114444/JcmdOutputEncodingTest.jtr.release 33324 08-31-2021 11:51 test_failures.2021-08-31-114444/JcmdOutputEncodingTest.jtr.slowdebug --------- ------- 304712 6 files
31-08-2021
Most likely related to JDK-8260265
31-08-2021
jdk-18+13-659 contains only three change sets: 2021-08-31 00:24 minqi: 9732fb - OpenJDK 8273153 Consolidate file_exists into os:file_exists 2021-08-30 21:13 naoto: 7fc854 - OpenJDK 8260265 UTF-8 by Default 2021-08-30 21:16 vromero: 060942 - OpenJDK 8272347 ObjectMethods::bootstrap should specify NPE if any argument except lookup is null Of these three, this fix looks the most related: JDK-8260265 UTF-8 by Default [~naoto] - Can you investigate to see if JDK-8260265 has caused these test failures?
31-08-2021