On Mon, 11 Dec 2023 11:16:05 GMT, Stefan Karlsson <stef...@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 > > > testNewOutputAnalyzerExit > [2023-12-11T11:05:46.231475003Z] Gathering output for process 2547782 > [2023... This pull request has now been integrated. Changeset: 9ab29f8d Author: Stefan Karlsson <stef...@openjdk.org> URL: https://git.openjdk.org/jdk/commit/9ab29f8dcd1c0092e4251f996bd53c704e87a74a Stats: 61 lines in 3 files changed: 47 ins; 11 del; 3 mod 8321718: ProcessTools.executeProcess calls waitFor before logging Reviewed-by: dholmes, jpai ------------- PR: https://git.openjdk.org/jdk/pull/17052
