Process isolation blocks infinitely upon fatal error in child process

[sun]

PHPUnit	Platform
4.1.3	Windows 7 64-bit

When using --process-isolation, @runTestsInSeparateProcess, or @runInSeparateProcess and the child process terminates with a PHP Fatal Error, the parent process blocks infinitely on Windows.

The fix is to read stderr before stdout.

cf. https://bugs.php.net/bug.php?id=51800:

If called as shown below, the script will hang in the loop that reads the STDOUT pipe. The same would happen if you would read the STDERR pipe before. If you lower the amount of data in process.php the script will run to the end. In my tests everything below ~2000 bytes was ok, above this value the script hang.

If you change the script below to not include the STDERR descriptor or if you change the STDERR descriptor to a file output everything will work fine. Also if you close the STDERR pipe before reading from STDOUT it will work. There seems to be some deadlock.

---

stderr contains the fatal error, stdout is empty. I had to debug this phantom for the past two days…:

After stdin is written/processed and closed, stream_get_meta_data($pipes[1]) reports that stdout still appears to be present:

$ phpunit -v --debug --process-isolation ...
PHPUnit 4.1.3 by Sebastian Bergmann.

Starting test '...'.
array(7) {
  'stream_type' =>
  string(5) "STDIO"
  'mode' =>
  string(1) "r"
  'unread_bytes' =>
  int(0)
  'seekable' =>
  bool(false)
  'timed_out' =>
  bool(false)
  'blocked' =>
  bool(true)
  'eof' =>
  bool(false)
}

But as soon as $stdout = stream_get_contents($pipes[1]) is called, the script hangs.

Changing the order in which $stdout and $stderr are read suddenly fixes the problem, and stream_get_meta_data() reports the same info for both pipes.

---

All of the usual resolutions for this common problem did not work in this case, and I'm not able to explain why. However, I'd like to make clear that I did try all of the below:

1. Opening stderr in append mode instead of write mode: Normally, that is almost always the solution. However, for some reason, this caused the parent process to not receive any output on stderr at all, and so a test passed despite a fatal error.
2. Setting stderr to non-blocking: As mentioned in this user comment, that's not supported by proc_open() on Windows.
   • https://bugs.php.net/bug.php?id=51800
   • https://bugs.php.net/bug.php?id=34972
   • https://bugs.php.net/bug.php?id=47918
3. …

D'oh. Somehow I didn't notice the first PHP bug link. #51800 fully cuts it. Nothing further to add to that.

Since the bug is still unresolved, I'd recommend to move forward with this PR as-is and just simply change the order in which stderr and stdout are read.

[sun]

FWIW, despite lots of manual testing, I'm not sure how to add an environment-specific test for this. - It wouldn't run anyway by default (because travis != Windows).

Also, running all tests of clean master yields plenty of failures on Windows — doesn't really count as an argument, just mentioning…

[sun]

Oh my.

Unfortunately, the changes of this PR are causing the same effect on Linux (as opposed to Windows), but already in case of a PHP Notice (as opposed to a Fatal error). (example)

[whatthejeff]

Unfortunately, the changes of this PR are causing the same effect on Linux (as opposed to Windows), but already in case of a PHP Notice (as opposed to a Fatal error). (example)

Maybe only switch the behavior for Windows then?

[whatthejeff]

Also, running all tests of clean master yields plenty of failures on Windows — doesn't really count as an argument, just mentioning…

Which tests fail under Windows?

[whatthejeff]

I should have some time to look into this and #1169 over the weekend. If the solution doesn't break BC, we should probably target the 4.1 branch instead of master.

[sun]

Maybe only switch the behavior for Windows then?

Maybe. Need to debug further before concluding on anything.

One combination I didn't test yet is append mode on top of this change, so that's one additional possibility…

Meanwhile I suspect that the pipes are unexpectedly closed ahead of time — a regular PHP Notice is normally supposed to be caught by PHPUnit's error handler (within the child process, as opposed to causing a special behavior in the parent process), so it should, theoretically, appear in the regular test result output like any other test…

Which tests fail under Windows?

More than happy to provide test output + help to make them pass, but separate issue 😉

[sun]

I suspect that the pipes are unexpectedly closed ahead of time

Based on that, the most obvious consideration (was):

diff --git a/src/Util/PHP/Default.php b/src/Util/PHP/Default.php
index fb21932..ebce217 100644
--- a/src/Util/PHP/Default.php
+++ b/src/Util/PHP/Default.php
@@ -87,14 +87,15 @@ public function runJob($job, array $settings = array())
         }

         $this->process($pipes[0], $job);
-        fclose($pipes[0]);

         $stderr = stream_get_contents($pipes[2]);
-        fclose($pipes[2]);

         $stdout = stream_get_contents($pipes[1]);
+
+        fclose($pipes[0]);
         fclose($pipes[1]);
+        fclose($pipes[2]);

         proc_close($process);
         $this->cleanup();

…but for yet another unknown reason, that happens to halt script execution altogether. (example)

---

Reverting that idea, and instead changing stderr to append mode… still mutes the fatal error entirely (despite reading stderr first):

$ phpunit -v --debug -c core/ --process-isolation --testsuite Kernel core/tests/Drupal/Tests/ProcessIsolationUnitTest.php
PHPUnit 4.1.3 by Sebastian Bergmann.

Configuration read from H:\unleashedmind\test\drupal8\core\phpunit.xml.dist

Starting test 'Drupal\Tests\ProcessIsolationUnitTest::testSameProcess'.
.
Starting test 'Drupal\Tests\ProcessIsolationUnitTest::testIsolated'.
.
Starting test 'Drupal\Tests\ProcessIsolationUnitTest::testIsolatedFatalError'.
.

Time: 9.57 seconds, Memory: 3.75Mb

OK (3 tests, 2 assertions)

The first two are simple counter-tests, expected to pass, testIsolatedFatalError() does exactly what it says, expected to blow up (but only in the child process).

---

I originally planned to save the following for a completely separate PR…

We're using proc_open() in Drupal's homegrown test runner, too, even with built-in parallelization, but we never experienced issues like this.
(Replacing our legacy code with PHPUnit is the immediate goal I'm working on.)

The more I'm looking into this, the more I suspect that the anti-behavior is caused by piping a script into stdin of the PHP binary.

The STDIN injection is problematic for several reasons anyway:

1. As mentioned in PHP core bug #51800, the special snowflake behavior of proc_open() on Windows is (partially) caused by STDIN input that is larger than 2KB.
   • The size of the process isolation template is not under PHPUnit's control.
2. As I already prepared for the separate PR, this gist explains that executing a PHP script via stdin does not instantiate the STDIN, STDOUT, STDERR streams that normally exist by default on CLI.
   • Among other code, this difference affects vfsStream when executed in an isolated child process; STDOUT/STDERR simply doesn't exist.
   • vfsStream is an officially recommended/endorsed library for PHPUnit. Regardless, such hairy differences in test execution simply should not exist.

Fact is, PHPUnit_Util_PHP_Windows already contains the necessary code to avoid the stdin script injection. But instead of its (slightly weird) file inclusion indirection (again via stdin), the PHP binary should simply receive the (temporary file) script to execute:

-    protected function process($pipe, $job)
-        fwrite(
-          $pipe,
-          "<?php require_once " . var_export($this->tempFile, true) .  "; ?>"
-        );
+    public function runJob($job, array $settings = array())
+        $process = proc_open(
-          $runtime->getBinary() . $this->settingsToParameters($settings),
+          $runtime->getBinary() . $this->settingsToParameters($settings) . ' -f ' . escapeshellarg($this->tempFile),

I prepared a local branch to use the Windows-specific temp file approach by default (and removing the Windows-specific code), but was confronted with PHPUnit's Usage Help text when executing tests (i.e., phpunit --help). Even after studying code paths and existing GH issues, I wasn't able to figure out what causes that behavior…

Now, there's a fair chance that I'm misguided, but I wasn't even aware that it's possible to inject a script via STDIN into the PHP binary in the way PHPUnit does it. I've never seen that approach in any other project, so there's a good chance that this custom approach is the root cause of the weird behaviors we're facing (because apparently not well-tested/supported by PHP core either way).

Thoughts?

[sun]

Need to step back and sleep over this. The newly added regression test unexpectedly runs against master (on Windows), but it freezes against the proposed stdout/stderr swap (on Windows). In fact, the isolated test case freezes before it even starts… That behavior is negated to the one I'm seeing sans isolation.

[sun]

Alright - figuring this out was extremely painful.

Ultimately, I had a brainwave and checked whether and how Symfony Process is doing it — turns out they ran into the same problem and equally implemented the only workaround that works: Using a temporary file handle for either STDOUT or STDERR, instead of a pipe. Their code apparently also points to https://bugs.php.net/bug.php?id=51800, so that's indeed the canonical bug report.

Up until this week, I totally wasn't aware that proc_open() and I/O streams are so terribly broken on Windows. Lesson learned.

Speaking of, I think we should consider to replace all of PHPUnit's custom process handling with the Symfony Process component - it certainly doesn't make sense to duplicate efforts and figure out this (hair-pulling) stuff more than once. Separate issue though.

For now, I'd recommend to move forward with this PR.

[sun]

Ouch. Latest build passed on all versions, except hhvm. hhvm seems to print STDERR during test execution already, and doesn't print "Call stack:" before a call stack of a fatal error.

[sun]

Sorry for all the noise, rebasing, etc.

Tests finally pass on all platforms, including Windows (locally). Ready to merge from my perspective.

Created #1342 to potentially replace this code with Symfony Process.

[whatthejeff]

No worries, @sun. All of this information has been very helpful for me :)

[sun]

@whatthejeff In that case, I probably should have pushed all of my countless local debugging iteration steps and should only have performed a squash/rebase last prior to a potential merge, in order to share the maximum info instead of only the result… — Anyway, consider me exhausted ;)

[whatthejeff]

Anyway, consider me exhausted

Well your hard work is very much appreciated. I hate to ask one more thing, but would you mind opening a new PR against the 4.1 branch for this bug fix? Otherwise it won't land in the next patch-level update.

[sun]

Oh, isaacs/github#18 is still not possible? Sad panda.

Sure, let me do that in a moment — I assume it's OK to leave the issue #id of the regression tests as-is.

[whatthejeff]

Sure, let me do that in a moment — I assume it's OK to leave the issue #id of the regression tests as-is.

Yeah, the regression tests are fine as-is.