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

From: Date: Tue, 10 May 2016 15:26:40 +0000
Subject: Bug #72185 [Opn]: php-fpm writes stdout with contentlength =0 causing nginx 502
References: 1  Groups: php.bugs 
Request: Send a blank email to php-bugs+get-200994@lists.php.net to get a copy of this message
Edit report at https://bugs.php.net/bug.php?id=72185&edit=1

 ID:                 72185
 User updated by:    kenny at kennynet dot co dot uk
 Reported by:        kenny at kennynet dot co dot uk
 Summary:            php-fpm writes stdout with contentlength =0 causing
                     nginx 502
 Status:             Open
 Type:               Bug
 Package:            FPM related
 Operating System:   Debian 7.0
 PHP Version:        5.6.21
 Block user comment: N
 Private report:     N

 New Comment:

(The sleep(30) is obviously not required. It was just to give me time to attach the strace!)


Previous Comments:
------------------------------------------------------------------------
[2016-05-10 15:21:13] kenny at kennynet dot co dot uk

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: 
aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!
 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...\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 this bug report at https://bugs.php.net/bug.php?id=72185&edit=1


Thread (2 messages)

« previous php.bugs (#200994) next »