JDK-8233725 : ProcessTools.startProcess() has output issues when using an OutputAnalyzer at the same time
  • Type: Bug
  • Component: hotspot
  • Sub-Component: test
  • Affected Version: 14,15,16,17,18
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2019-11-06
  • Updated: 2024-07-09
  • Resolved: 2023-04-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 17 JDK 21
17.0.13Fixed 21 b20Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
If you use ProcessTools.startProcess() and apply an OutputAnalyzer right afterwards as shown below:

            p = ProcessTools.startProcess("java", pb);
            out = new OutputAnalyzer(p);

Some of the output will end up with the OutputAnalyzer, and some automatically included in the .jtr file with the "[java]" prefix. It seems to be randomly divvied up between the two, whereas all the output should appear in both.

Using the Consumer argument has a similar issue:

            p = ProcessTools.startProcess("java", pb, outputConsumer);
            out = new OutputAnalyzer(p);

The lines that are directed to the Consumer are the same as the lines you see with the "[java]" prefix. The rest are directed to the OutputAnalyzer. The issue happens with both stdout and stderr.

Please see the attached test case. It runs once with without a consumer and once with. I'm not certain you will always see both test cases fail on all processors since some of it might be timing related. For example, without a consumer I see:

[2019-11-06T00:42:06.891310Z] Gathering output for process 27274
DEBUG: process started.
[java] A line on stdout 0
FAILED: wrong number of lines in OutputAnalyzer output
DEBUG: OutputAnalyzer output: got 49 lines, expected 50. Output follows:
A line on stdout 1
A line on stdout 2
<...>

So only the first line ended up with the "[java]" prefix. If it had instead ended up in the OutputAnalyzer output, the test would not have detected any failures because it can't actually see that were no lines of "[java]" output.

The Consumer case which runs second seems to do a much better job of showing this issue, at least when run on my machine:

[2019-11-06T00:42:06.923088Z] Gathering output for process 27297
DEBUG: process started.
[java] A line on stdout 0
[java] A line on stdout 26
[java] A line on stdout 30
[java] A line on stdout 33
[java] A line on stdout 35
[java] A line on stdout 37
[java] A line on stdout 39
[java] A line on stdout 42
[java] A line on stdout 44
[java] A line on stdout 47
[java] A line on stdout 49
FAILED: wrong number of lines in Consumer output
DEBUG: Consumer output: got 11 lines, expected 50. Output follow:
A line on stdout 0
A line on stdout 26
A line on stdout 30
A line on stdout 33
A line on stdout 35
A line on stdout 37
A line on stdout 39
A line on stdout 42
A line on stdout 44
A line on stdout 47
A line on stdout 49
DEBUG: done with Consumer output.
FAILED: wrong number of lines in OutputAnalyzer output
DEBUG: OutputAnalyzer output: got 39 lines, expected 50. Output follows:
A line on stdout 1
A line on stdout 2
<...>
A line on stdout 24
A line on stdout 25
A line on stdout 27
A line on stdout 28
A line on stdout 29
A line on stdout 31
A line on stdout 32
A line on stdout 34
A line on stdout 36
A line on stdout 38
A line on stdout 40
A line on stdout 41
A line on stdout 43
A line on stdout 45
A line on stdout 46
A line on stdout 48

So in this case here were 11 lines, scattered from throughout the output, that appeared with the "[java]" prefix and also with the Consumer. The rest were in the OutputAnalyzer.
Comments
[jdk17u-fix-request] Approval Request from Elif Aslan “Clean backport. Fix ProcessTools.startProcess() regression. GHA tested and ran tier2 tests additionally. This backport is required for JDK-8325567 to be backported to 17 since this bugfix is missing."
09-05-2024

A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/2456 Date: 2024-05-09 16:32:05 +0000
09-05-2024

Changeset: 2e340e85 Author: Leonid Mesnik <lmesnik@openjdk.org> Date: 2023-04-26 14:53:33 +0000 URL: https://git.openjdk.org/jdk/commit/2e340e855b760e381793107f2a4d74095bd40199
26-04-2023

A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/13594 Date: 2023-04-21 21:43:39 +0000
23-04-2023

The main problem is that we can't get stdoud/stderr stream several times. The ProcessTools.startProcess should allow either to register streams or to remember data.
20-04-2023

A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/13560 Date: 2023-04-20 16:09:29 +0000
20-04-2023

This issue recently turned up as a test bug. See JDK-8258057.
11-01-2021

Just wanted to add that I believe this makes it impossible to use ProcessTools.startProcess() with an OutputAnalyzer in any meaningful way. It also means that there is no way to do something like the following if you use startProcess(): out.stderrShouldBeEmpty(); The issue is that the Consumer gets all of both stdout and stderr, so there is no way to separately see what appears on each stream. If for some reason using an OutputAnalyzer with startProcess() is just not feasible, or won't be fixed in the near term, perhaps startProcess() should support accepting separate Consumer arguments for stdout and stderr.
06-11-2019