RFR: 8321718: ProcessTools.executeProcess calls waitFor before logging [v2]

[Stefan Karlsson]

On Tue, 12 Dec 2023 09:01:08 GMT, Stefan Karlsson <stefank at openjdk.org> wrote:

>> 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
>> 
>> 
>> testNewOutp...
>
> Stefan Karlsson has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Typo

Thanks for reviewing! I'll remove the test, merge, and will do some sanity checks before integrating.

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

PR Comment: https://git.openjdk.org/jdk/pull/17052#issuecomment-1874162036