Bug #72185 [NEW]: php-fpm writes stdout with contentlength =0 causing nginx 502

From: kenny at kennynet dot co dot uk Operating system: Debian 7.0 PHP version: 5.6.21 Package: FPM related Bug Type: Bug Bug description:php-fpm writes stdout with contentlength =0 causing nginx 502 Description: ------------ When error bytes written to stderr equal to sizeof(req->out_buf) - sizeof(fcgi_header) [8192 - 8] php5-fpm will emit an empty FGCI_STDOUT frame which causes nginx to trigger a 502 Gateway error (and a SIGPIPE to the FPM worker). E.g. stracing the fpm worker running the 502 script below through nginx yields: # strace -ewrite -p $WORKER_PID -s99999999 2>&1 | grep 'write(3' write(3, "\1\7\0\1\37\360\0\0PHP message: PHP Warning: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa! aaaa...\n<REMOVED FOR BREVITY> in /data/Projects/KMv3/502.php on line 15\n\1\6\0\1\0\0\0\0", 8192) = 8192 write(3, "\1\6\0\1\0003\5\0Content-type: text/html; charset=UTF-8\r\n\r\nOK: 8134\n\0\0\0\0\0\1\3\0\1\0\10\0\0\0\0\0\0\0aaa", 80) = -1 EPIPE (Broken pipe) Note: The trailing 8 bytes of the first write(3, ...): ver stdout requestid contentlen padlen reserved \1 \6 \0\1 \0\0 \0 \0 I believe this is due to the following code-path (as of 5.6.19, sorry, but I can't test 5.6.21 yet but I presume it's not changed):- fcgi_write() if (req->out_hdr && req->out_hdr->type != type) { close_packet(req); <---- Transitioning from FCGI_STDERR to FCGI_STDOUT } ... } else if (len - limit < sizeof(req->out_buf) - sizeof(fcgi_header)) { if (!req->out_hdr) { open_packet(req, type); <-- Packet closed above, so opens one for FCGI_STDOUT } ... // NB: limit == 0 so memcpy() wasn't hit. if (!fcgi_flush(req, 0)) { <-- Call fcgi_flush return -1; } ... fcgi_flush() close_packet(req); <-- Packet closed with no data added to it ... if (safe_write(req, req->out_buf, len) != len) { <-- Empty FCGI_STDOUT frame emitted with the FCGI_STDERR data. ... NB: While debugging this if your total error bytes write 8192-8+(0 < n < 8) then it looks like the open_packet() call overflows req->out_buf by 8 bytes (due to the padding) and the write() returns 8200 bytes written. (Easiest thing is to subtract from $len, 1 or 3 etc...) NBB: PoC given not heavily tested. Test script: --------------- <?php // YMMV. Ideally leave log_errors_max_len at the default of 1024 define('ERR_HDR', 'PHP message: PHP Warning: '); define('FCGI_OUT_BUF_SIZE', 8192); define('FCGI_HDR_SIZE', 8); $max = ini_get('log_errors_max_len'); $len = FCGI_OUT_BUF_SIZE - (2 * FCGI_HDR_SIZE) - strlen($_SERVER['SCRIPT_FILENAME']) - strlen(" on line 15"); $bytes = 0; sleep(30); while ($bytes < $len) { $p = str_repeat('a', min($max, $len - $bytes) - strlen(ERR_HDR) - 1); $bytes += strlen($p) + strlen(ERR_HDR) + 1; trigger_error($p, E_USER_WARNING); } echo "OK: $bytes\n"; Expected result: ---------------- No 502 error and the page renders correctly. Actual result: -------------- nginx 502 error due to empty FCGI_STDOUT frame. -- Edit bug report at https://bugs.php.net/bug.php?id=72185&edit=1 -- Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=72185&r=trysnapshot54 Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=72185&r=trysnapshot55 Try a snapshot (trunk): https://bugs.php.net/fix.php?id=72185&r=trysnapshottrunk Fixed in SVN: https://bugs.php.net/fix.php?id=72185&r=fixed Fixed in release: https://bugs.php.net/fix.php?id=72185&r=alreadyfixed Need backtrace: https://bugs.php.net/fix.php?id=72185&r=needtrace Need Reproduce Script: https://bugs.php.net/fix.php?id=72185&r=needscript Try newer version: https://bugs.php.net/fix.php?id=72185&r=oldversion Not developer issue: https://bugs.php.net/fix.php?id=72185&r=support Expected behavior: https://bugs.php.net/fix.php?id=72185&r=notwrong Not enough info: https://bugs.php.net/fix.php?id=72185&r=notenoughinfo Submitted twice: https://bugs.php.net/fix.php?id=72185&r=submittedtwice register_globals: https://bugs.php.net/fix.php?id=72185&r=globals PHP 4 support discontinued: https://bugs.php.net/fix.php?id=72185&r=php4 Daylight Savings: https://bugs.php.net/fix.php?id=72185&r=dst IIS Stability: https://bugs.php.net/fix.php?id=72185&r=isapi Install GNU Sed: https://bugs.php.net/fix.php?id=72185&r=gnused Floating point limitations: https://bugs.php.net/fix.php?id=72185&r=float No Zend Extensions: https://bugs.php.net/fix.php?id=72185&r=nozend MySQL Configuration Error: https://bugs.php.net/fix.php?id=72185&r=mysqlcfg