8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test #3049

RogerRiggs · 2021-03-17T14:16:36Z

Intermittent failures on Windows in a test of destroying the child warrant extending the time the parent waits after starting the child before destroying the child.

Progress

Change must not contain extraneous whitespace
Commit message must refer to an issue
Change must be properly reviewed

Issue

JDK-8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test

Reviewers

Thomas Stuefe (@tstuefe - Reviewer)
Ioi Lam (@iklam - Reviewer) ⚠️ Review applies to 6313399

Download

To checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/3049/head:pull/3049
$ git checkout pull/3049

To update a local copy of the PR:
$ git checkout pull/3049
$ git pull https://git.openjdk.java.net/jdk pull/3049/head

…sBuilder Basic test

bridgekeeper · 2021-03-17T14:16:50Z

👋 Welcome back rriggs! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2021-03-17T14:18:24Z

@RogerRiggs The following label will be automatically applied to this pull request:

core-libs

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

mlbridge · 2021-03-17T14:21:59Z

Webrevs

plevart · 2021-03-17T14:52:36Z

test/jdk/java/lang/ProcessBuilder/Basic.java

@@ -2179,7 +2179,7 @@ public void run() {

                thread.start();
                latch.await();
-                Thread.sleep(10);
+                Thread.sleep(100L);     // Wait for child initialization to settle



Hi Roger,
Shouldn't the code that follows this sleep already be enough to wait for child thread to get a lock on the stream?

Thread.sleep(100L); // Wait for child initialization to settle if (s instanceof BufferedInputStream) { // Wait until after the s.read occurs in "thread" by // checking when the input stream monitor is acquired // (BufferedInputStream.read is synchronized) while (!isLocked(s, 10)) { Thread.sleep(100); } }

From 1st glance I would conclude that the 1st sleep is unnecessary. Is there a platform where Input/Error stream is not a BufferedInputStream? Or is it calling Process.destory() immediately after the child thread enters BufferedInputStream.read synchronized method perhaps too early to trigger appropriate exception in the child thread? In that case the additional sleep should be added after the while(!isLocked... loop.

That loop is checking that the Thread (in the parent) reading from the child is in the correct state (blocked). On Windows, it is a BufferedInputStream.

But it does not indicate anything about the state of the child process.
From the scant information from previous failures, it appears that the the creation of some thread (not a java thread) in the child has failed.
The additional time is to avoid destroying the child while it is still initializing.

The failures happened in tiers 6 and 8. The system may be overloaded so even 100ms may not be enough for the child process to start sleeping. From the error log, the child process tried to spawn a thread (probably one of those usually started during VM bootstrap) at around 118ms

[0.118s][warning][os,thread] Failed to start thread - _beginthreadex failed (EACCES) for attributes: stacksize: default, flags:

The test runs 4 times. Each time it checks only STDOUT or STDERR, but not both. So I think we can use the other stream to signal to the main process that the child process is ready. That would be more reliable than an arbitrary wait time.

That complicates the test and the child quite a bit for minimal gain.

Arbitrary time out has been a reliable source of intermittent failures.

Since we have spent a lot of time analyzing this failure, I think it's worthwhile to fix it properly, which doesn't seem that complicated. That's better than the same bug happening again a year later and a different set of people would spend hours to analyze it again.

The test expects there to be zero output from the child (and it doesn't matter what state the child is in).
Can the logging from the VM be disabled or re-directed?

The test expects there to be zero output from the child (and it doesn't matter what state the child is in).
Can the logging from the VM be disabled or re-directed?

Not to the extend that it would be guaranteed never to happen. Even if we control all output in the hotspot, there are other libraries. E.g. glibc writes a lengthy report to stderr in case of a heap corruption, which I believe does not result in a hs-err file.

One simple solution, simpler than using two threads, could be to use ProcessBuilder::redirectError(Redirect.INHERIT) if reading stdout resp. ProcessBuilder::redirectOutput(Redirect.INHERIT) if reading stderr. One line, takes care of the stream you don't read does not block, and, we can see the child output in the parent stdout/err.

That complicates the test and the child quite a bit for minimal gain.

Suppose that the child process writes 1 byte to STDOUT and 1 byte to STDERR. In the monitoring thread in the parent process, you could read 1 byte from either STDOUT or STDERR, then count-down the latch and then block in next read. The main thread could then just wait for the latch, wait for the monitoring thread to re-enter the synchronized read method and then destroy the process... It doesn't sound too complicated. WDYT?

Redirecting the stream not being tested to INHERIT may be useful.
But the failing case is when the vm output is being directed to the stream being tested.
The command line arguments are:

Arrays.asList(javaExe, "-XX:+DisplayVMOutputToStderr", "-classpath", absolutifyPath(classpath), "Basic$JavaChild");``` A combination of redirecting to inherited and sending the VM output to the same (untested) stream seems like a good option.

@plevart, I prototyped using that technique but was concerned that it might change the test case to be different in some subtle way from the original. It adds a new subcommand to the JavaChild to add the specific behavior.
Not particularly complex but more code and dependencies to explain.

tstuefe

Hi Roger, thanks for taking my suggestion. Minor point below.

Cheers, Thomas

tstuefe · 2021-03-19T16:54:43Z

test/jdk/java/lang/ProcessBuilder/Basic.java

+                            break;
+                        case 1:
+                            childArgs.set(1, "-XX:+DisplayVMOutputToStdout");
+                            pb.redirectInput(INHERIT);


not redirectOutput() ?

You are correct. will fix.
(The Process streams are from the point of view of parent).

Yes, I have to look this up every time. Its not intuitive.

iklam

LGTM. Just a small nit.

iklam · 2021-03-19T18:11:03Z

test/jdk/java/lang/ProcessBuilder/Basic.java

-                List<String> childArgs = new ArrayList<String>(javaChildArgs);
+                List<String> childArgs = new ArrayList<>(javaChildArgs);
+                final ProcessBuilder pb = new ProcessBuilder(childArgs);
+                {


I was a little confused until I looked up the JavaDoc of ProcessBuilder.

Maybe add a comment like "ProcessBuilder does NOT make a copy of childArgs so it's OK to modify it below"?

tstuefe

Looks good to me, if the intent was to fix potential write blockages in the child process (in which case maybe reformulate the issue title).

I'm sorry I derailed your original wait idea, as well as Ioi's ideas of syncing with the child. Both may still be needed after this fix.

Cheers, Thomas

openjdk · 2021-03-22T14:48:42Z

@RogerRiggs This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test

Reviewed-by: stuefe, iklam

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 68 new commits pushed to the master branch:

6c2220e: 8263861: Shenandoah: Remove unused member in ShenandoahGCStateResetter
5262d95: 8263855: Use the blessed modifier order in java.management/naming
6f1bcb0: 8263593: Fix multiple typos in hsdis README
a9d2267: 8260589: Crash in JfrTraceIdLoadBarrier::load(_jclass*)
42104e5: 8263488: Verify CWarningWindow works with metal rendering pipeline
5a7f22a: 8263579: ZGC: Concurrent mark hangs with debug loglevel
35cd945: 8263908: Build fails due to initialize_static_field_for_dump defined but not used after JDK-8263771
cd45538: 8263771: Refactor javaClasses initialization code to isolate dumping code
118a49f: 8263846: Bad JNI lookup getFocusOwner in accessibility code on Mac OS X
cb742f9: 8255255: Update Apache Santuario (XML Signature) to version 2.2.1
... and 58 more: https://git.openjdk.java.net/jdk/compare/000012a3b08d5f21d4cb2369d2122adfae1a3e9b...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

RogerRiggs · 2021-03-22T14:49:52Z

Thanks for the reviews and the suggestion to redirect the output to the inherited streams.
/integrate

openjdk · 2021-03-22T14:51:23Z

@RogerRiggs Since your change was applied there have been 68 commits pushed to the master branch:

6c2220e: 8263861: Shenandoah: Remove unused member in ShenandoahGCStateResetter
5262d95: 8263855: Use the blessed modifier order in java.management/naming
6f1bcb0: 8263593: Fix multiple typos in hsdis README
a9d2267: 8260589: Crash in JfrTraceIdLoadBarrier::load(_jclass*)
42104e5: 8263488: Verify CWarningWindow works with metal rendering pipeline
5a7f22a: 8263579: ZGC: Concurrent mark hangs with debug loglevel
35cd945: 8263908: Build fails due to initialize_static_field_for_dump defined but not used after JDK-8263771
cd45538: 8263771: Refactor javaClasses initialization code to isolate dumping code
118a49f: 8263846: Bad JNI lookup getFocusOwner in accessibility code on Mac OS X
cb742f9: 8255255: Update Apache Santuario (XML Signature) to version 2.2.1
... and 58 more: https://git.openjdk.java.net/jdk/compare/000012a3b08d5f21d4cb2369d2122adfae1a3e9b...master

Your commit was automatically rebased without conflicts.

Pushed as commit 0abbfb2.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

8263729: [test] Extend time to wait before destroying child in Proces…

ba3d947

…sBuilder Basic test

openjdk bot added the rfr Pull request is ready for review label Mar 17, 2021

openjdk bot added the core-libs core-libs-dev@openjdk.org label Mar 17, 2021

plevart reviewed Mar 17, 2021

View reviewed changes

Redirect VM output away from stream under test

d8d4fcc

tstuefe reviewed Mar 19, 2021

View reviewed changes

Correct redirect of stdout

6313399

iklam approved these changes Mar 19, 2021

View reviewed changes

Clarify modification of argument list after creating ProcessBuilder

31c35be

tstuefe approved these changes Mar 20, 2021

View reviewed changes

RogerRiggs changed the title ~~8263729: [test] Extend time to wait before destroying child in ProcssBuilder Basic test~~ [test] divert spurious output away from stream under test in ProcessBuilder Basic test Mar 21, 2021

openjdk bot removed the rfr Pull request is ready for review label Mar 21, 2021

RogerRiggs changed the title ~~[test] divert spurious output away from stream under test in ProcessBuilder Basic test~~ 8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test Mar 22, 2021

openjdk bot added ready Pull request is ready to be integrated rfr Pull request is ready for review labels Mar 22, 2021

openjdk bot closed this Mar 22, 2021

openjdk bot added integrated Pull request has been integrated and removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Mar 22, 2021

RogerRiggs deleted the 8263729-basic-wait branch March 22, 2021 15:00

8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test #3049

8263729: [test] divert spurious output away from stream under test in ProcessBuilder Basic test #3049

Uh oh!

Conversation

RogerRiggs commented Mar 17, 2021 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Issue

Reviewers

Download

Uh oh!

bridgekeeper bot commented Mar 17, 2021

Uh oh!

openjdk bot commented Mar 17, 2021

Uh oh!

mlbridge bot commented Mar 17, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

plevart Mar 17, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tstuefe left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

RogerRiggs Mar 19, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

iklam left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tstuefe left a comment

Choose a reason for hiding this comment

Uh oh!

openjdk bot commented Mar 22, 2021

Uh oh!

RogerRiggs commented Mar 22, 2021

Uh oh!

openjdk bot commented Mar 22, 2021

Uh oh!

Uh oh!

RogerRiggs commented Mar 17, 2021 •

edited by openjdk bot

Loading

mlbridge bot commented Mar 17, 2021 •

edited

Loading

plevart Mar 17, 2021 •

edited

Loading

RogerRiggs Mar 19, 2021 •

edited

Loading