Edit report at https://bugs.php.net/bug.php?id=62382&edit=1
ID: 62382
Comment by: philipp dot wahala at web dot de
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:
I just ran into this issue on Darwin OS X 10.9.5. Both PHP 5.5.20 and PHP 5.6.4 are affected.
Previous Comments:
------------------------------------------------------------------------
[2014-09-09 07:27:10] rob dot bast at gmail dot com
Same problem still persists on PHP 5.5.16 (Archlinux 3.16.1-1-ARCH)
------------------------------------------------------------------------
[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.
------------------------------------------------------------------------
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