RFR: 8321718: ProcessTools.executeProcess calls waitFor before logging

[Stefan Karlsson]

There is some logging printed when tests spawns processes. This logging is triggered from calls to `OutputAnalyzer`, when it delegates calls to `LazyOutputBuffer`.

If we write code like this:

ProcessBuilder pb = ProcessTools.createTestJavaProcessBuilder(...);
OutputAnalyzer output = new OutputAnalyzer(pb.start());
int exitValue = output.getExitValue();


We get the following logging:

[timestamp0] "Gathering output for process <pid>
[timestamp1] Waiting for completion for process <pid>
[timestamp2] Waiting for completion finished for process <pid>


The first line comes from the `OutputAnalyzer` constructor and the two other lines comes from the `getExitValue` call, which calls logs the above messages around the call to `waitFor`.

If instead write the code above as:

ProcessBuilder pb = ProcessTools.createTestJavaProcessBuilder(...);
OutputAnalyzer output = ProcessTools.executeProcess(pb);
int exitValue = output.getExitValue();


We get the same logging, but timestamp1 and timestamp2 are almost the same. This happens because there's an extra call to `waitFor` inside `executeProcess`, but that `waitFor` does not have the "wait for" logging. So, instead we get the logging for the no-op `waitFor` inside `getExitValue`.

I would like to propose a small workaround to solve this. The workaround is that `executeProcess` delegates the `waitFor` call to the `LazyOutputBuffer` via `OutputAnalyzer`.  This is a small, limited workaround for this issue. Ideally I would like to extract the entire Process handling code out of LazyOutputBuffer and OutputAnalyzer, but the prototype for that rewrites all usages of `new OutputAnalyzer(pb.start())` and stretches far and wide in the test directories, so I'm starting out with this suggestion.

We can see of this patch by looking at the timestamps generated from the included test. Without the proposed workaround:

Without

testExecuteProcessExit
[2023-12-11T11:05:41.854579260Z] Gathering output for process 2547719
[2023-12-11T11:05:44.018335073Z] Waiting for completion for process 2547719
[2023-12-11T11:05:44.018851972Z] Waiting for completion finished for process 2547719

testExecuteProcessStdout
[2023-12-11T11:05:44.049509860Z] Gathering output for process 2547741
[2023-12-11T11:05:46.227768897Z] Waiting for completion for process 2547741
[2023-12-11T11:05:46.228021173Z] Waiting for completion finished for process 2547741


testNewOutputAnalyzerExit
[2023-12-11T11:05:46.231475003Z] Gathering output for process 2547782
[2023-12-11T11:05:46.231972095Z] Waiting for completion for process 2547782
[2023-12-11T11:05:48.421324123Z] Waiting for completion finished for process 2547782

testNewOutputAnalyzerStdout
[2023-12-11T11:05:48.424801269Z] Gathering output for process 2547929


With the proposed workaround:

testExecuteProcessExit
[2023-12-11T11:06:12.203633363Z] Gathering output for process 2550961
[2023-12-11T11:06:12.285826294Z] Waiting for completion for process 2550961
[2023-12-11T11:06:14.361912745Z] Waiting for completion finished for process 2550961

testExecuteProcessStdout
[2023-12-11T11:06:14.398685794Z] Gathering output for process 2550982
[2023-12-11T11:06:14.399518617Z] Waiting for completion for process 2550982
[2023-12-11T11:06:16.595986889Z] Waiting for completion finished for process 2550982

testNewOutputAnalyzerExit
[2023-12-11T11:06:16.602218373Z] Gathering output for process 2551067
[2023-12-11T11:06:16.603176801Z] Waiting for completion for process 2551067
[2023-12-11T11:06:18.793886942Z] Waiting for completion finished for process 2551067

testNewOutputAnalyzerStdout
[2023-12-11T11:06:18.796332176Z] Gathering output for process 2551172


See how the timestamp for "Waiting for completion for process" becomes "earlier" in the "executeProcess" cases.

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

Commit messages:
 - Whitespace cleanups
 - 8321718: ProcessTools.executeProcess calls waitFor before logging

Changes: https://git.openjdk.org/jdk/pull/17052/files
 Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=17052&range=00
  Issue: https://bugs.openjdk.org/browse/JDK-8321718
  Stats: 159 lines in 4 files changed: 145 ins; 11 del; 3 mod
  Patch: https://git.openjdk.org/jdk/pull/17052.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/17052/head:pull/17052

PR: https://git.openjdk.org/jdk/pull/17052