PHP hanging indefinitely

[leopcastro]

I was testing some html conversions using the mikehaertl/phpwkhtmltopdf, when I noticed one made PHP hang indefinitely.

Doing some debug, I found out that it was happening in the php-shellcommand/src/Command.php file at line number 317:

$this->_stdOut = stream_get_contents($pipes[1]); 

After some research, I found a similar problem in this stackoverflow question and an apparent solution. http://stackoverflow.com/questions/31194152/proc-open-hangs-when-trying-to-read-from-a-stream

According to the stackoverflow answer, there is a possibility of an execution not outputting anything to stdout (pipe[1]) when an error occurs, so stream_get_contents waits for a stream that never comes.

As pointed out in the stackoverflow answer, reading the stderr (pipe[2]) before stdout (pipe[1]) did the trick for me, with the PHP finishing execution and the error message being outputted.

$this->_stdErr = stream_get_contents($pipes[2]);
$this->_stdOut = stream_get_contents($pipes[1]); 

My system config:

• Ubuntu 14.04.1 LTS running as a headless VM on Virutalbox
• PHP Version 5.5.22-1+deb.sury.org~trusty+1
• Apache/2.4.12
• wkhtmltopdf 0.12.2 (with patched qt)

[mikehaertl]

@leonardopcastro Released 1.2.3 containing this fix. Thanks for your help!

[mikehaertl]

@leonardopcastro This change seems to have introduced other problems now. See #21.

[mikehaertl]

As proposed in mikehaertl/phpwkhtmltopdf#78 (comment) and again in #9 (comment) we could try to add stream_set_blocking() calls:

$descriptors = array(
    1 => array('pipe','w'),
    2 => array('pipe','w')
);
$process = proc_open($command, $descriptors, $pipes, $this->procCwd, $this->procEnv, $this->procOptions);

if (is_resource($process)) {
    // set streams to non blocking mode
    stream_set_blocking($pipes[1], 0);
    stream_set_blocking($pipes[2], 0);
    $this->_stdOut = trim(stream_get_contents($pipes[1]));
    $this->_stdErr = trim(stream_get_contents($pipes[2]));
    fclose($pipes[1]);
    fclose($pipes[2]);
...

There was one neutral feedback in #78 ("didn't fix it") and we have 2 positive in #6. So maybe we should really implement the fix suggested by @mkloosterman in #78.

I'd feel better if we had reliable test cases that can reproduce the issue. Any volunteers? @schmunk42, @markdboyd, @epicwally?

[markdboyd]

@mikehaertl I'm not sure when I'll have time to get to this, but would a test that reproduces the infinite hanging when trying to read the streams in this order be sufficient? I'm still not 100% clear on what the actual cause of the hanging is, but for me it seemed directly related to the size of the PDFs I was trying to generate.

[mikehaertl]

@markdboyd I'd say the size of the PDF should not matter as the problem seems to be more on the side of the buffers for error and standard message output. So I think it's about the length of the command which of course increases if you have more pages in your PDF (each page == one more argument to wkhtmltopdf).

An ideal test would use some regular shell command (echo, cat, grep, ...) and try to make it hang (e.g. by using a very long option string or letting it output very long strings to stdout / stderr or a combination of everything). When we have this it will probably also point us to the root of the problem.

I can't promise that I find time for this soon - even more so as I never had the issue myself 😛 .

[patrict]

As proposed in mikehaertl/phpwkhtmltopdf#78 (comment) and again in #9 (comment) we could try to add stream_set_blocking() calls

There was one neutral feedback in #78 ("didn't fix it") and we have 2 positive in #6. So maybe we should really implement the fix suggested by @mkloosterman in #78.

I'd feel better if we had reliable test cases that can reproduce the issue. Any volunteers? @schmunk42, @markdboyd, @epicwally?

Hi all,

We ran into this problem and ended up fixing it in exactly this way, and only found this post after the fact. I can confirm that setting the streams to non-blocking mode mode resolved the problem for us as well.

stream_set_blocking($pipes[1], 0);
stream_set_blocking($pipes[2], 0);

For what its worth :)

[mikehaertl]

@patrict Thanks for your feedback. I've finally added this feature - but it's weird: Now proc_close() always seems to return 1 (= error).

I feel like I'm missing something very obvious here because several people reported success. Maybe you can have a look at the merge request and see if that code works for you? It also contains a check for Windows systems because it was reported that non-blocking mode does not work there.

[patrict]

@mikehaertl I've implemented your exact code and I am unable to reproduce the error you get - in my environment proc_close() always returns 0.

I did note the following on the PHP proc_close() documentation page:

Return Values
Returns the termination status of the process that was run. In case of an error then -1 is returned.

Then look at the most recent user contributed notes by Uwe Ohse:

Regarding: "Returns the termination status of the process that was run. In case of an error then -1 is returned."

This is, at best, misleading. It returns:

• -1 on error,
• WEXITSTATUS(status) if WIFEXITED(status) is true, or
• status if WIFEXITED(status) is false,
  where status is the status parameter of waitpid().

This makes it impossible to differentiate between a relatively normal exit or a termination by signal, and reduces the value of the proc_close return code to a binary one (ok / something broke).

This can be seen in proc_open_rsrc_dtor() in ext/standard/proc_open.c (PHP 5.4.44, 5.6.12).

On the system I tested this on, Im running PHP 5.6.40 (yes yes, don't judge...)

In light of this I would suggest simply testing for an exit code < 0, which will tell you there is an error, but not what/why.

HTH

[mikehaertl]

@patrict Thanks for the update. This is very weird. Are you sure, you've used exactly the same code I have in my latest pull request? You can see, that we get the same error also for the Travis tests (even for PHP 5.6), so it's not a local issue on my machine.

Regarding the exit code: For shell commands it's usually 0 in success. Anything else indicates an error. See this TLDP page:

A successful command returns a 0, while an unsuccessful one returns a non-zero value that usually can be interpreted as an error code.

So does your quote mean that proc_open() does not return the "real" exit code? Will have to dig into the internals of how processes are handled in C (if I find time to to so).

Apart from that the question is still, why does proc_open() suddenly return 1 for the same command? All we changed was to use non-blocking mode for the output streams.

[patrict]

Hi @mikehaertl

Are you sure, you've used exactly the same code I have in my latest pull request?

Yup, I used your exact version

Regarding the exit code: For shell commands it's usually 0 in success. Anything else indicates an error.

Agreed

So does your quote mean that proc_open() does not return the "real" exit code?

Exactly - unexpected and strange, but that's what the documentation seems to indicate.
As I understand it, if the shell command returns any error at all, then proc_close() will return -1, and there is no way to know what the real exit code was. This is why I suggested testing only for < 0 instead of !== 0, since according to the documentation, a response >= 0 is not an error.

From the user contributed notes:

This makes it impossible to differentiate between a relatively normal exit or a termination by signal, and reduces the value of the proc_close return code to a binary one (ok / something broke).
This can be seen in proc_open_rsrc_dtor() in ext/standard/proc_open.c (PHP 5.4.44, 5.6.12).

Apart from that the question is still, why does proc_open() suddenly return 1 for the same command? All we changed was to use non-blocking mode for the output streams.

That is a good question. I can't even think of a reason to speculate on 🤕 The only thing I can think of is to dig into and debug the PHP source, which is a bit of a shlep to say the least...

Read all the user contributed notes on the proc_close() page, all except the last one are about the return value:

[mikehaertl]

@patrict Just curious: Did you also run the test cases with phpunit? If not, could you maybe try that? I still can't believe that you get different results than me/travis.

UPDATE: Running the tests is very easy: You only need phpunit installed and run it from the root directory of the repo. I'm using version 6.5.5 here.

[patrict]

UPDATE: Running the tests is very easy: You only need phpunit installed and run it from the root directory of the repo. I'm using version 6.5.5 here.

@mikehaertl Ive installed phpunit 6.5.14 - do I need to specify a test file or any parameters?

php-shellcommand-20-add-stream_set_blocking-calls$ ./phpunit
PHPUnit 6.5.14 by Sebastian Bergmann and contributors.

This version of PHPUnit is supported on PHP 7.0 and PHP 7.1.
You are using PHP 5.6.40-0+deb8u4 (/usr/bin/php5).

php-shellcommand-20-add-stream_set_blocking-calls$ ./phpunit tests/CommandTest.php
PHPUnit 6.5.14 by Sebastian Bergmann and contributors.

This version of PHPUnit is supported on PHP 7.0 and PHP 7.1.
You are using PHP 5.6.40-0+deb8u4 (/usr/bin/php5).

/php-shellcommand-20-add-stream_set_blocking-calls$ ./phpunit tests/bootstrap.php
PHPUnit 6.5.14 by Sebastian Bergmann and contributors.

This version of PHPUnit is supported on PHP 7.0 and PHP 7.1.
You are using PHP 5.6.40-0+deb8u4 (/usr/bin/php5).

[mikehaertl]

Ah, sorry, seems like this version doesn't run with PHP 5.6 anymore. Hmm, older versions are probably incompatible with some test assertions. Well, then nevermind and thanks for trying.

I still need to find some time to think about a proper fix for this mess :).

[patrict]

@mikehaertl I tried PHPUnit 5.7.27 out of curiousity, and it seems you are right:

php-shellcommand-20-add-stream_set_blocking-calls$ ./phpunit-5
PHP Warning: require(php-shellcommand-20-add-stream_set_blocking-calls/tests/../vendor/autoload.php): failed to open stream: No such file or directory in php-shellcommand-20-add-stream_set_blocking-calls/tests/bootstrap.php on line 9
PHP Fatal error: require(): Failed opening required 'php-shellcommand-20-add-stream_set_blocking-calls/tests/../vendor/autoload.php' (include_path='.:/usr/share/php:/usr/share/pear') in php-shellcommand-20-add-stream_set_blocking-calls/tests/bootstrap.php on line 9

Im not familiar enough with PHPUnit to know what to do with that 😂

Sorry I could not be of more help, let me know if there is anything else you would like me to try

[mikehaertl]

The only option would be to let the tests run under PHP 7 somewhere. But I'm pretty sure you get the same results as me - otherwhise I'd start to loose confidence that this universe acts logically 👽 .

Actually that you didn't run the tests so far explains why you get different results. It probably very much depends on the command you try to run. Can you share that command? If it's nothing weird I could try it on my machine and see if I get the same result. Maybe it also helps to better understand the return code logic.

[patrict]

@mikehaertl Im not sure I understand correctly - are you asking what phpunit command I ran?

[mikehaertl]

No no, I mean, what did you use the php-shellcommand for? You said even with my change you get the correct exit code 0. Or did you use phpwkhtmltopdf?

[patrict]

Ah, Im with you now. I grabbed your changes, then used phpwkhtmltopdf to generate the same dataset that I previously got the hang on, to see if it would successfully generate the PDF. The PDF did generate succesfully, which is what I based my response on :)

[mikehaertl]

Alright, thanks. Then I'll try this too. I want to get a better understanding of what this all means and how the comands differ.

[mikehaertl]

@patrict and all those interested, I share what I learned so far:

When we set non-blocking mode then the PHP main process is - well - not blocked anymore. That means that the process opened by proc_open() can still be running in parallel while your PHP code continues with execution. So now it's quite likely that we call proc_close() before the external process has completed - and thus it gets ended abnormally. That explains why we get a different return code now.

This basically means, that we need a loop where we check the process status with proc_get_status() continously and check if has ended. Only then it's safe to call proc_close() - and the status code should be the correct one.

Now comes the tricky part: According to this comment, in that loop both pipes for stdout and stderr have to be checked both alternately to avoid a potential lock. At least that's how I understand it so far.

I'm still thinking how to combine all the above in a proper fix. But I feel like I'm on the right track.

Finally we can only pray that things will also work on Windows.

[mikehaertl]

@patrict It seems I finally have a working solution. It looks a bit complex but actually was the only way I could make everything work. The nice part: It now also works with huge inputs/outputs, even as streams. If you could help testing this (or even review if you dare) that would be great.

[patrict]

@mikehaertl oh wow, well done! What a convoluted situation to have to handle!

I reviewed your changes and everything looks good.
I grabbed a copy of the branch and ran it in the same environment I was using previously when we hit the original issue with the process hanging, and everything worked perfectly.

Well done!

[mikehaertl]

Cool! I want to wait for some more feedback from @schmunk42 , too. He also had issues and I think he was using input streams (i.e. open file handles).

If things go well I'll create a new release very soon. Thanks again for your help which brought me on the right track.

[schmunk42]

I didn't further investigate the issue, so I can't really provide feedback.

[epicwally]

Just tried this branch in our linux environment, and it works comparably with the hack I had implemented a while ago.

[mikehaertl]

Release 1.5.0 now contains this new logic. Thanks everyone for the help and feedback!

[patrict]

Awesome, thanks and well done!