Bug #62382 [Com]: Wrong timestamp and time per request in access format of a PHP-FPM pool

Edit report at https://bugs.php.net/bug.php?id=62382&edit=1 ID: 62382 Comment by: rob dot bast at gmail dot com Reported by: david dot guyot at europecamions-interactive dot co Summary: Wrong timestamp and time per request in access format of a PHP-FPM pool Status: Assigned Type: Bug Package: FPM related Operating System: Debian Squeeze 2.6.38.2-grsec-xx PHP Version: 5.4.4 Assigned To: tony2001 Block user comment: N Private report: N New Comment: Same problem still persists on PHP 5.5.16 (Archlinux 3.16.1-1-ARCH) Previous Comments: ------------------------------------------------------------------------ [2013-07-08 11:54:52] itsgoingd at luzer dot sk Note that this bug still exists in PHP 5.5.0 as well as 5.4.17 (testing on FreeBSD 9.1). Fix proposed by Mauro Stettler (thanks!), moving the accepted_epoch cleanup code from fpm_request_finished() [fpm_request.c:209] to fpm_request_reading_headers() [fpm_request.c:61] solves the problem for me, not sure about how correct this solution is. Any input on this by fpm developers? ------------------------------------------------------------------------ [2013-02-20 09:42:24] timur at gnu dot org I don't think corruption is connected with nginx or keepalive. I'd assume that it happens on the late stage when your script is about to finish and just washed out by restarting PHP process. With keepalive you are entering the next request with already corrupted time value. Well, just speculating :) At least, we see the same behaviour with the upstream keepalive disabled... ------------------------------------------------------------------------ [2013-02-20 09:35:58] andreas dot lindemann at de dot bp dot com I've seen the exact same thing on Solaris with nginx as frontend. For us it happens when nginx uses keepalives to the fastcgi backend. Turning fastcgi keepalives off resolves this weird behaviour. Makes the logs much better readable but sacrifices some performance. Should really be fixed as otherwise the access log is pretty much useless in these scenarios when you can't rely on the logged timestamps and time taken to serve the request. ------------------------------------------------------------------------ [2013-02-06 15:01:11] timur at gnu dot org Hi! We are using: # php -v PHP 5.3.19-1~dotdeb.0 with Suhosin-Patch (cli) (built: Nov 24 2012 07:05:58) Copyright (c) 1997-2012 The PHP Group Zend Engine v2.3.0, Copyright (c) 1998-2012 Zend Technologies On: Description: Debian GNU/Linux 6.0.6 (squeeze) Release: 6.0.6 Codename: squeeze and experience the same bug. Simple test, consisting of: <?php echo "hello"; if (!isset($_GET['noffr'])) { fastcgi_finish_request(); } ?> Producing those entries in the php5-fpm.log file: Feb 6 15:35:28 php/www: [01/Jan/1970:01:00:00 +0100] - - 200 5562742898304 768 /var/www/adlantic/test/ffr.php "GET /test/ffr.php" 0.00% Feb 6 15:35:38 php/www: [06/Feb/2013:15:35:33 +0100] - - 200 322 768 /var/www/adlantic/test/ffr.php "GET /test/ffr.php?noffr" 3105.59% For the log format like: access.format = "[%t] %R - %u %s %{micro}d %{kilo}M %f \"%m %r%Q%q\" %C%%" So both %t and %{micro}d are affected. ------------------------------------------------------------------------ [2012-10-19 13:52:55] david dot guyot at web-eci dot com Well, I didn't double check... The problem concerning the time taken to serve the request seems to have vanished. The bug still exists, but, at least, %t doesn't alter %{mili}d results anymore. Looks like Mauro Stettler found something related... ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at https://bugs.php.net/bug.php?id=62382 -- Edit this bug report at https://bugs.php.net/bug.php?id=62382&edit=1