Bug #75584 [NEW]: Docs?: stream_select() ignores proc_open() streams for buffered fopen() streams

From: asmqb7 at gmail dot com Operating system: Arch Linux=Y Windows=? macOS=? PHP version: 7.1.12 Package: Streams related Bug Type: Bug Bug description:Docs?: stream_select() ignores proc_open() streams for buffered fopen() streams Description: ------------ Sorry for the terse title - there were 0 characters left in the input field (but it's cool when it fits perfectly...) I've discovered an interesting edge-case stream buffering glitch. - I opened a file using fopen() and started a process using proc_open(). I wanted to read the file and write its contents into the process's standard input. - To keep my I/O loop clean, I used stream_select() to marshal/multiplex reading and writing between the file stream and the process stdin/stdout/stderr streams. - For some reason, my script did not begin writing to the process stdin until it had completely read the file contents. (?!) - Investigation showed that stream_select() was not reporting the stdin stream as writable as long as the file stream was being passed to stream_select() (my code stopped passing the file stream when it detected EOF on the file). It took me some time to wrap my head around the fact that that stream_select() was not acknowledging a writeable stream passed in the $write array as writeable, for as long as I was passing in an entirely unrelated stream (from a random disk file) into the $read array. I initially discovered that setting the stream_select() timeout to 0 (as a hack) and then manually adding the file stream to the $read array _after_ stream_select() made the script consistently work perfectly (as my code looped through the readable arrays and did the correct things). But (as far as I understand) a timeout of 0 effectively removes the buffer-ratelimiting advantages of using stream_select() in the first place so I didn't want to use this workaround. Intending to report a bug with the info I'd gathered, I asked in ##php on freenode about the 20-line limit for testcases, as it's hard to write stream-management PHP code in less than 20 lines without golfing, and I really didn't want to add external links that would invariably eventually die. (The reached consensus was that if a concise, minimal testcase was >20lines, then it shouldn't be the end of the world to attach the whole thing.) While in ##php someone gave some consideration to my repro testcase and pointed me toward https://github.com/php/php-src/blob/dcdd4abdb2eb622c72c0b271e4f3a173ca8e6765/ext/standard/streamsfuncs.c#L822-L836. I'll quote the comment from that point in the source: /* slight hack to support buffered data; if there is data sitting in the * read buffer of any of the streams in the read array, let's pretend * that we selected, but return only the readable sockets */ This gave me the idea to go digging to see if there were any buffer-control functions, discover there were, and rapidly find that stream_set_read_buffer($file, 0); on the file stream completely rectified the issue I was having! Obviously this is the clean, universal solution to this problem I was looking for - my thanks to the person who helped me on IRC! (Around Mon Nov 24 2017 1:24AM UTC, for reference, and I was i336_.) The attached testcase perfectly reproduces this issue (and the fix) on Arch Linux, but considering the abstract nature of the stream subsystem, testing on Windows and other UNIX (*BSD, IllumOS, macOS, etc) is probably a very good idea, and I'm interested to find out what the status of this issue is on various platforms. (I incidentally only have Linux machines at my disposal at the moment.) After having gone round in circles with this for a couple days (mercifully not very long) I share the conclusion reached by the person who helped me on IRC, which is that this is a documentation problem - it's obvious to me that all the language components/features are "working as intended" individually, but when put together violate the principle of least surprise somewhat. I'll be linking to this bug in a few comment sections, but this is enough of a gotcha that adding it where everyone will invariably see it is probably a very good idea. I know I can queue documentation changes but I'm not really sure how to go about adding info about this and would prefer to defer to other(s) with more experience with documenting and who have a better idea of the right spot to put this. Beyond documentation, I added a "?" after "Docs" in the summary/subject because I'm not sure if this would be classified as a language bug to some extent as well (something something "slight hack"). I can see a clear argument that things are _technically_ working as intended, but still... :) Test script: --------------- <?php // See "Actual Results" section for description of code and (extremely simple) usage directives $file_bufsize = 64; $stdin_bufsize = 1024; $stdout_bufsize = 1024; $delayms = 10000; $inputfile = 'input.txt'; $file = fopen($inputfile, 'r'); $filesize = fstat($file)['size']; for (;;) { $proc = proc_open("cat", [['pipe', 'r'], ['pipe', 'w'], ['pipe', 'w']], $pipes); /*1*/ #stream_set_read_buffer($file, 0); $readbytes = $proc_in = $proc_out = $proc_err = $zerowrites = 0; $proc_sendq = ""; $stdin_done = false; print "starting\n"; for (;;) { $read = $write = $except = []; foreach ([1, 2] as $i) if (!feof($pipes[$i])) $read[] = $pipes[$i]; if (!$stdin_done && $proc_sendq != "") $write[] = $pipes[0]; /*2*/ if ($filesize - $readbytes > 0) $read[] = $file; dump_fds($read, $write, $pipes, $file); print "=> <sel"; if ($read || $write) { /*3a*/ stream_select($read, $write, $except, null); #/*3b*/ stream_select($read, $write, $except, 0); } print "ect> => "; dump_fds($read, $write, $pipes, $file); print "\n"; foreach ($read as $rfd) { switch ($rfd) { case $file: // file input $data = fread($file, min($file_bufsize, $filesize - $readbytes)); $readbytes += strlen($data); $proc_sendq .= $data; break; case $pipes[1]: case $pipes[2]: // process stdout or stderr (which is input from PHP's POV) // cat never writes stderr so use stdout's bufsize $l = strlen($data = fread($rfd, $stdout_bufsize)); if ($rfd == $pipes[1]) { $proc_out += $l; $s = "out"; } else { $proc_err += $l; $s = "err"; } print "\nstd".$s.": \"".$data."\"\n\n"; } } // only $pipes[0] will ever be in the $write array if (in_array($pipes[0], $write) && $proc_sendq != "") { $len = fwrite($pipes[0], $proc_sendq, $stdin_bufsize); if ($len == 0) { if ($zerowrites++ == 5) { // note zerowrites is zeroed just below; this counts // a series of successive write failures as fatal. print "\n\nI/O error\n\n"; die; } } else { $proc_in += $len; $zerowrites = 0; $proc_sendq = substr($proc_sendq, $len); if ($proc_in == $filesize) { fclose($pipes[0]); $stdin_done = true; print "\nstdin done\n\n"; } } } print "file($readbytes) buf:".strlen($proc_sendq) ." proc(I:$proc_in O:$proc_out E:$proc_err)\n"; // if process has quit AND its stdout/stderr are closed, it's done. if (!proc_get_status($proc)['running'] && feof($pipes[1]) && feof($pipes[2]) ) { print "\n\nbreaking\n"; break; } usleep($delayms); print "\n"; } print "\nloop finished => proc_close()\n"; fclose($pipes[1]); fclose($pipes[2]); proc_close($proc); } /* Aesthetic printing function, buried at the bottom to improve * general readability. Implementation unimportant */ function dump_fds($read, $write, $pipes, $file) { foreach (['R' => $read, 'W' => $write] as $label => $fds) { print $label.": [ "; foreach ($fds as $f) { print ($f == $file ? 'file' : ['in', 'out', 'err'] [array_search($f, $pipes)]).'#'.(int)$f.' '; } print "] "; } } Expected result: ---------------- I'm not sure what to expect - this issue may ultimately be judged to be working as intended, or it may be acknowledged as a bug. (Not going to duplicate problem description for this field) Actual result: -------------- The attached testcase launches "cat", opens a file of data, pushes that data into cat's stdin, reads cat's stdout, and prints the data from stdout to the screen. It also displays debugging commentary. Its output (there is a lot) is ratelimited (by usleep()ing for $delayms set at the top of the script) so it won't overload the terminal/console. You need a file to open. Any existing bit of data will do, as long as it can be sanely printed to stdout. ~40KB of input combines well with the 10µs delay I'm using. In case it's useful: (written for Linux, unsure if these work the same on *BSD et al) $ cat /dev/urandom | od -An -vtx1 | head -c 40960 > input.txt My apologies the testcase is long. Only a couple of lines need to be carefully scrutinized/reasoned about. The total length is primarily due to the scaffolding required to read from a file and push it into a pipe. I have absolutely no idea how to trigger the described failure mode with a shorter sequence of code - I expect there is a shorter reproduction case, but I have no idea how I'd go about finding it. I'll quote a bit of script output so I can point out a few things. --------------------------------------------------------------------------- R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(65344) buf:64896 proc(I:448 O:384 E:0) R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(65408) buf:64960 proc(I:448 O:384 E:0) R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(65472) buf:65024 proc(I:448 O:384 E:0) R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(65535) buf:65087 proc(I:448 O:384 E:0) R: [ out#7 err#8 ] W: [ in#6 ] => <select> => R: [ out#7 ] W: [ in#6 ] stdout: "8 8a 7b b8 ef 04 03 87 f5 82 b9 b2 7e 82 db 6e 15 b4 2f ab e2 " file(65535) buf:65023 proc(I:512 O:448 E:0) R: [ out#7 err#8 ] W: [ in#6 ] => <select> => R: [ out#7 ] W: [ in#6 ] stdout: "3b b3 16 e5 1f ef f2 a4 95 6e 53 54 32 22 a1 c4 d6 96 a0 07 a2 " file(65535) buf:64959 proc(I:576 O:512 E:0) R: [ out#7 err#8 ] W: [ in#6 ] => <select> => R: [ out#7 ] W: [ in#6 ] stdout: "90 7d 4c 80 98 03 c3 63 78 e1 7e 23 1d 4c 00 43 a3 22 52 46 d6 " file(65535) buf:64895 proc(I:640 O:576 E:0) R: [ out#7 err#8 ] W: [ in#6 ] => <select> => R: [ out#7 ] W: [ in#6 ] stdout: "6a 49 b2 09 74 e7 44 b3 f2 11 aa 0e db a0 74 28 05 fd bc 32 56" --------------------------------------------------------------------------- - The hexadecimal output is meaningless and is the contents of my test file. - The <select> lines show the streams being passed to stream_select(), and then what is being passed back by stream_select() when it's done. The stream IDs are annotated with "file", "in", "out" and "err". I think it's worth noting/remembering that stdin goes in the writeable array. - The lines like "file(65535) buf:64895 proc(I:640 O:576 E:0)" are saying that 64K has been read from the file; 64895 bytes are in $proc_sendq (which is .= appended to by file reads, and substr()ed from [the beginning of] when stdin is writeable); and that the "proc"ess has had 640 bytes written to its stdin, 576 bytes read from its stdout and 0 bytes read from its stderr. - The first four iterations shown here describe that the file is repeatedly being read in without much attention being paid to writing stdin. Once the file hits exactly 64K, the script hits file EOF, removes the file stream from the $read array, and then begins to write consistently to cat's stdin on every loop (and subsequently read from cat's stdout and display data). What's clearly visible here is the cutoff point where "file#5" stops being passed to stream_select(), and "in#6" immediately shows up consistently after the stream_select() as a direct result. I think the following may be a significant area to investigate: you may have noticed that the four iterations at the top indicate (with "proc(I:448 O:384 E:0)") that cat _does_ actually have a tiny bit of data written to its stdin and read from its stdout. This is true. What's actually happening is that... --------------------------------------------------------------------------- R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(8192) buf:8192 proc(I:0 O:0 E:0) R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ in#6 ] file(8256) buf:7232 proc(I:1024 O:0 E:0) R: [ out#7 err#8 file#5 ] W: [ in#6 ] => <select> => R: [ file#5 ] W: [ ] file(8320) buf:7296 proc(I:1024 O:0 E:0) --------------------------------------------------------------------------- ...every few thousand iterations, PHP randomly decides the stdin stream is writeable. (You have to not blink in order to notice the "in#6" fly past and hit ^C!) IMO, 8192 bytes read from the file is a really odd point for the first stdout write to be happening on/near/just after. I'm not sure how to interpret this but I'm sure it's somehow significant and worth mentioning. Adjusting the various $*_bufsize values will control the frequency at which these rare-ish stdin writes occur. In particular adjusting the $file_bufsize will make the most difference; small multiples such as 128, 256, 512 or 1024 are recommended (at 1024 it reads the whole file pretty quickly). Regarding the defaults I've set: in any other circumstance, having a $file_bufsize of 64 and a $stdin_bufsize of 1024 would be useless: if the source is reading 64 bytes at a time then sinking with a larger buffer size is going to have no effect. It does have an effect in this situation because PHP only decides stdin is writeable "every once in a while" - so when it does eventually write, it's built up enough data to easily write 1024 bytes. Final notes: - To reproduce my initial hack/workaround, move the line marked with /*1*/ immediately below the if(){} block containing the stream_select() calls, and switch the stream_select() from a null timeout to a 0 timeout. - The rectifying stream_set_read_buffer() call is near the top, commented out. -- Edit bug report at https://bugs.php.net/bug.php?id=75584&edit=1 -- Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=75584&r=trysnapshot54 Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=75584&r=trysnapshot55 Try a snapshot (trunk): https://bugs.php.net/fix.php?id=75584&r=trysnapshottrunk Fixed in SVN: https://bugs.php.net/fix.php?id=75584&r=fixed Fixed in release: https://bugs.php.net/fix.php?id=75584&r=alreadyfixed Need backtrace: https://bugs.php.net/fix.php?id=75584&r=needtrace Need Reproduce Script: https://bugs.php.net/fix.php?id=75584&r=needscript Try newer version: https://bugs.php.net/fix.php?id=75584&r=oldversion Not developer issue: https://bugs.php.net/fix.php?id=75584&r=support Expected behavior: https://bugs.php.net/fix.php?id=75584&r=notwrong Not enough info: https://bugs.php.net/fix.php?id=75584&r=notenoughinfo Submitted twice: https://bugs.php.net/fix.php?id=75584&r=submittedtwice register_globals: https://bugs.php.net/fix.php?id=75584&r=globals PHP 4 support discontinued: https://bugs.php.net/fix.php?id=75584&r=php4 Daylight Savings: https://bugs.php.net/fix.php?id=75584&r=dst IIS Stability: https://bugs.php.net/fix.php?id=75584&r=isapi Install GNU Sed: https://bugs.php.net/fix.php?id=75584&r=gnused Floating point limitations: https://bugs.php.net/fix.php?id=75584&r=float No Zend Extensions: https://bugs.php.net/fix.php?id=75584&r=nozend MySQL Configuration Error: https://bugs.php.net/fix.php?id=75584&r=mysqlcfg