Edit report at https://bugs.php.net/bug.php?id=62382&edit=1
ID: 62382
Comment by: itsgoingd at luzer dot sk
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: Open
Type: Bug
Package: FPM related
Operating System: Debian Squeeze 2.6.38.2-grsec-xx
PHP Version: 5.4.4
Block user comment: N
Private report: N
New Comment:
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?
Previous Comments:
------------------------------------------------------------------------
[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...
------------------------------------------------------------------------
[2012-10-19 13:45:52] david dot guyot at web-eci dot com
I applied the patch proposed by Mauro Stettler (sorry for the delay, I didn't
subscribe to this bug) on a system without grsec, and it still bugs :
root@Apus:~# cat /var/log/nginx/www.access.log
[19/Oct/2012:15:28:58 +0200] /app.php => 38.105
[19/Oct/2012:15:28:58 +0200] /app.php?=PHPE9568F34-D428-11d2-A769-00AA001ACF42
=> 2.539
[19/Oct/2012:15:28:58 +0200] /app.php?=PHPE9568F35-D428-11d2-A769-00AA001ACF42
=> 3.132
[19/Oct/2012:15:28:58 +0200] /app.php => 5.713
[19/Oct/2012:15:32:17 +0200] [01/Jan/1970:01:00:00 +0100] /app.php => 6.921
[19/Oct/2012:15:32:17 +0200] [01/Jan/1970:01:00:00 +0100] /app.php?=PHPE9568F34-
D428-11d2-A769-00AA001ACF42 => 2.013
[19/Oct/2012:15:32:17 +0200] [01/Jan/1970:01:00:00 +0100] /app.php?=PHPE9568F35-
D428-11d2-A769-00AA001ACF42 => 1.942
[19/Oct/2012:15:32:18 +0200] [01/Jan/1970:01:00:00 +0100] /app.php => 8.550
[19/Oct/2012:15:37:26 +0200] [01/Jan/1970:01:00:00 +0100] /app.php => 7.376
[19/Oct/2012:15:37:26 +0200] [01/Jan/1970:01:00:00 +0100] /app.php?=PHPE9568F34-
D428-11d2-A769-00AA001ACF42 => 2.202
[19/Oct/2012:15:37:26 +0200] [01/Jan/1970:01:00:00 +0100] /app.php?=PHPE9568F35-
D428-11d2-A769-00AA001ACF42 => 15.996
[19/Oct/2012:15:37:26 +0200] [01/Jan/1970:01:00:00 +0100] /app.php => 7.277
root@Apus:~# php-fpm -i
phpinfo()
PHP Version => 5.4.4
System => Linux Apus 2.6.32-5-amd64 #1 SMP Sun Sep 23 10:07:46 UTC 2012 x86_64
Build Date => Oct 19 2012 14:09:47
Configure Command => './configure' '--enable-fpm' '--with-config-file-
path=/etc/php5'
Server API => FPM/FastCGI
Virtual Directory Support => disabled
Configuration File (php.ini) Path => /etc/php5
Loaded Configuration File => (none)
Scan this dir for additional .ini files => (none)
Additional .ini files parsed => (none)
PHP API => 20100412
PHP Extension => 20100525
Zend Extension => 220100525
Zend Extension Build => API220100525,NTS
PHP Extension Build => API20100525,NTS
Debug Build => no
Thread Safety => disabled
Zend Signal Handling => disabled
Zend Memory Manager => enabled
Zend Multibyte Support => disabled
IPv6 Support => enabled
DTrace Support => disabled
Registered PHP Streams => php, file, glob, data, http, ftp, phar
Registered Stream Socket Transports => tcp, udp, unix, udg
Registered Stream Filters => convert.iconv.*, string.rot13, string.toupper,
string.tolower, string.strip_tags, convert.*, consumed, dechunk
This program makes use of the Zend Scripting Language Engine:
Zend Engine v2.4.0, Copyright (c) 1998-2012 Zend Technologies
_______________________________________________________________________
Configuration
cgi-fcgi
php-fpm => active
Directive => Local Value => Master Value
cgi.discard_path => 0 => 0
cgi.fix_pathinfo => 1 => 1
cgi.force_redirect => 1 => 1
cgi.nph => 0 => 0
cgi.redirect_status_env => no value => no value
cgi.rfc2616_headers => 0 => 0
fastcgi.error_header => no value => no value
fastcgi.logging => 1 => 1
fpm.config => no value => no value
Core
PHP Version => 5.4.4
Directive => Local Value => Master Value
allow_url_fopen => On => On
allow_url_include => Off => Off
always_populate_raw_post_data => Off => Off
arg_separator.input => & => &
arg_separator.output => & => &
asp_tags => Off => Off
auto_append_file => no value => no value
auto_globals_jit => On => On
auto_prepend_file => no value => no value
browscap => no value => no value
default_charset => no value => no value
default_mimetype => text/html => text/html
disable_classes => no value => no value
disable_functions => no value => no value
display_errors => On => On
display_startup_errors => Off => Off
doc_root => no value => no value
docref_ext => no value => no value
docref_root => no value => no value
enable_dl => On => On
enable_post_data_reading => On => On
error_append_string => no value => no value
error_log => no value => no value
error_prepend_string => no value => no value
error_reporting => no value => no value
exit_on_timeout => Off => Off
expose_php => On => On
extension_dir => /usr/local/lib/php/extensions/no-debug-non-zts-20100525 =>
/usr/local/lib/php/extensions/no-debug-non-zts-20100525
file_uploads => On => On
highlight.comment => <font style="color: #FF8000">#FF8000</font> => <font
style="color: #FF8000">#FF8000</font>
highlight.default => <font style="color: #0000BB">#0000BB</font> => <font
style="color: #0000BB">#0000BB</font>
highlight.html => <font style="color: #000000">#000000</font> => <font
style="color: #000000">#000000</font>
highlight.keyword => <font style="color: #007700">#007700</font> => <font
style="color: #007700">#007700</font>
highlight.string => <font style="color: #DD0000">#DD0000</font> => <font
style="color: #DD0000">#DD0000</font>
html_errors => On => On
ignore_repeated_errors => Off => Off
ignore_repeated_source => Off => Off
ignore_user_abort => Off => Off
implicit_flush => Off => Off
include_path => .:/usr/local/lib/php => .:/usr/local/lib/php
log_errors => Off => Off
log_errors_max_len => 1024 => 1024
mail.add_x_header => Off => Off
mail.force_extra_parameters => no value => no value
mail.log => no value => no value
max_execution_time => 30 => 30
max_file_uploads => 20 => 20
max_input_nesting_level => 64 => 64
max_input_time => -1 => -1
max_input_vars => 1000 => 1000
memory_limit => 128M => 128M
open_basedir => no value => no value
output_buffering => 0 => 0
output_handler => no value => no value
post_max_size => 8M => 8M
precision => 14 => 14
realpath_cache_size => 16K => 16K
realpath_cache_ttl => 120 => 120
register_argc_argv => On => On
report_memleaks => On => On
report_zend_debug => On => On
request_order => no value => no value
sendmail_from => no value => no value
sendmail_path => /usr/sbin/sendmail -t -i => /usr/sbin/sendmail -t -i
serialize_precision => 17 => 17
short_open_tag => On => On
SMTP => localhost => localhost
smtp_port => 25 => 25
sql.safe_mode => Off => Off
track_errors => Off => Off
unserialize_callback_func => no value => no value
upload_max_filesize => 2M => 2M
upload_tmp_dir => no value => no value
user_dir => no value => no value
user_ini.cache_ttl => 300 => 300
user_ini.filename => .user.ini => .user.ini
variables_order => EGPCS => EGPCS
xmlrpc_error_number => 0 => 0
xmlrpc_errors => Off => Off
zend.detect_unicode => On => On
zend.enable_gc => On => On
zend.multibyte => Off => Off
zend.script_encoding => no value => no value
ctype
ctype functions => enabled
date
date/time support => enabled
"Olson" Timezone Database Version => 2012.3
Timezone Database => internal
Default timezone => UTC
Directive => Local Value => Master Value
date.default_latitude => 31.7667 => 31.7667
date.default_longitude => 35.2333 => 35.2333
date.sunrise_zenith => 90.583333 => 90.583333
date.sunset_zenith => 90.583333 => 90.583333
date.timezone => no value => no value
dom
DOM/XML => enabled
DOM/XML API Version => 20031129
libxml Version => 2.7.8
HTML Support => enabled
XPath Support => enabled
XPointer Support => enabled
Schema Support => enabled
RelaxNG Support => enabled
ereg
Regex Library => Bundled library enabled
fileinfo
fileinfo support => enabled
version => 1.0.5
filter
Input Validation and Filtering => enabled
Revision => $Id: e523cdc8829892d1b4f9cb7c3c57b2ba1c36b9ea $
Directive => Local Value => Master Value
filter.default => unsafe_raw => unsafe_raw
filter.default_flags => no value => no value
hash
hash support => enabled
Hashing Engines => md2 md4 md5 sha1 sha224 sha256 sha384 sha512 ripemd128
ripemd160 ripemd256 ripemd320 whirlpool tiger128,3 tiger160,3 tiger192,3
tiger128,4 tiger160,4 tiger192,4 snefru snefru256 gost adler32 crc32 crc32b
fnv132 fnv164 joaat haval128,3 haval160,3 haval192,3 haval224,3 haval256,3
haval128,4 haval160,4 haval192,4 haval224,4 haval256,4 haval128,5 haval160,5
haval192,5 haval224,5 haval256,5
iconv
iconv support => enabled
iconv implementation => glibc
iconv library version => 2.11.3
Directive => Local Value => Master Value
iconv.input_encoding => ISO-8859-1 => ISO-8859-1
iconv.internal_encoding => ISO-8859-1 => ISO-8859-1
iconv.output_encoding => ISO-8859-1 => ISO-8859-1
json
json support => enabled
json version => 1.2.1
libxml
libXML support => active
libXML Compiled Version => 2.7.8
libXML Loaded Version => 20708
libXML streams => enabled
pcre
PCRE (Perl Compatible Regular Expressions) Support => enabled
PCRE Library Version => 8.12 2011-01-15
Directive => Local Value => Master Value
pcre.backtrack_limit => 1000000 => 1000000
pcre.recursion_limit => 100000 => 100000
PDO
PDO support => enabled
PDO drivers => sqlite
pdo_sqlite
PDO Driver for SQLite 3.x => enabled
SQLite Library => 3.7.7.1
Phar
Phar: PHP Archive support => enabled
Phar EXT version => 2.0.1
Phar API version => 1.1.1
SVN revision => $Id: 2a47d3d0354109d8077e34d59f1228ccfd021d59 $
Phar-based phar archives => enabled
Tar-based phar archives => enabled
ZIP-based phar archives => enabled
gzip compression => disabled (install ext/zlib)
bzip2 compression => disabled (install pecl/bz2)
OpenSSL support => disabled (install ext/openssl)
Phar based on pear/PHP_Archive, original concept by Davey Shafik.
Phar fully realized by Gregory Beaver and Marcus Boerger.
Portions of tar implementation Copyright (c) 2003-2009 Tim Kientzle.
Directive => Local Value => Master Value
phar.cache_list => no value => no value
phar.readonly => On => On
phar.require_hash => On => On
posix
Revision => $Id: 967584c6fadb3467f31abe8e13caa8764df85867 $
Reflection
Reflection => enabled
Version => $Id: 1cf65cee164ed57874ce2d29e5c46b82f6139524 $
session
Session Support => enabled
Registered save handlers => files user
Registered serializer handlers => php php_binary
Directive => Local Value => Master Value
session.auto_start => Off => Off
session.cache_expire => 180 => 180
session.cache_limiter => nocache => nocache
session.cookie_domain => no value => no value
session.cookie_httponly => Off => Off
session.cookie_lifetime => 0 => 0
session.cookie_path => / => /
session.cookie_secure => Off => Off
session.entropy_file => /dev/urandom => /dev/urandom
session.entropy_length => 32 => 32
session.gc_divisor => 100 => 100
session.gc_maxlifetime => 1440 => 1440
session.gc_probability => 1 => 1
session.hash_bits_per_character => 4 => 4
session.hash_function => 0 => 0
session.name => PHPSESSID => PHPSESSID
session.referer_check => no value => no value
session.save_handler => files => files
session.save_path => no value => no value
session.serialize_handler => php => php
session.upload_progress.cleanup => On => On
session.upload_progress.enabled => On => On
session.upload_progress.freq => 1% => 1%
session.upload_progress.min_freq => 1 => 1
session.upload_progress.name => PHP_SESSION_UPLOAD_PROGRESS =>
PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix => upload_progress_ => upload_progress_
session.use_cookies => On => On
session.use_only_cookies => On => On
session.use_trans_sid => 0 => 0
SimpleXML
Simplexml support => enabled
Revision => $Id: 455280fc74f9f002b7314def7a456f6c3080eb92 $
Schema support => enabled
SPL
SPL support => enabled
Interfaces => Countable, OuterIterator, RecursiveIterator, SeekableIterator,
SplObserver, SplSubject
Classes => AppendIterator, ArrayIterator, ArrayObject,
BadFunctionCallException,
BadMethodCallException, CachingIterator, CallbackFilterIterator,
DirectoryIterator, DomainException, EmptyIterator, FilesystemIterator,
FilterIterator, GlobIterator, InfiniteIterator, InvalidArgumentException,
IteratorIterator, LengthException, LimitIterator, LogicException,
MultipleIterator, NoRewindIterator, OutOfBoundsException, OutOfRangeException,
OverflowException, ParentIterator, RangeException, RecursiveArrayIterator,
RecursiveCachingIterator, RecursiveCallbackFilterIterator,
RecursiveDirectoryIterator, RecursiveFilterIterator, RecursiveIteratorIterator,
RecursiveRegexIterator, RecursiveTreeIterator, RegexIterator, RuntimeException,
SplDoublyLinkedList, SplFileInfo, SplFileObject, SplFixedArray, SplHeap,
SplMinHeap, SplMaxHeap, SplObjectStorage, SplPriorityQueue, SplQueue, SplStack,
SplTempFileObject, UnderflowException, UnexpectedValueException
sqlite3
SQLite3 support => enabled
SQLite3 module version => 0.7
SQLite Library => 3.7.7.1
Directive => Local Value => Master Value
sqlite3.extension_dir => no value => no value
standard
Dynamic Library Support => enabled
Path to sendmail => /usr/sbin/sendmail -t -i
Directive => Local Value => Master Value
assert.active => 1 => 1
assert.bail => 0 => 0
assert.callback => no value => no value
assert.quiet_eval => 0 => 0
assert.warning => 1 => 1
auto_detect_line_endings => 0 => 0
default_socket_timeout => 60 => 60
from => no value => no value
url_rewriter.tags => a=href,area=href,frame=src,form=,fieldset= =>
a=href,area=href,frame=src,form=,fieldset=
user_agent => no value => no value
tokenizer
Tokenizer Support => enabled
xml
XML Support => active
XML Namespace Support => active
libxml2 Version => 2.7.8
xmlreader
XMLReader => enabled
xmlwriter
XMLWriter => enabled
Additional Modules
Module Name
Environment
Variable => Value
TERM => xterm
SHELL => /bin/bash
SSH_CLIENT => 192.168.0.162 45141 22
SSH_TTY => /dev/pts/0
USER => root
MAIL => /var/mail/root
PATH => /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
PWD => /root
LANG => fr_FR.UTF-8
SHLVL => 1
HOME => /root
LOGNAME => root
SSH_CONNECTION => 192.168.0.162 45141 192.168.0.218 22
_ => /usr/local/sbin/php-fpm
PHP Variables
Variable => Value
_SERVER["TERM"] => xterm
_SERVER["SHELL"] => /bin/bash
_SERVER["SSH_CLIENT"] => 192.168.0.162 45141 22
_SERVER["SSH_TTY"] => /dev/pts/0
_SERVER["USER"] => root
_SERVER["MAIL"] => /var/mail/root
_SERVER["PATH"] => /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
_SERVER["PWD"] => /root
_SERVER["LANG"] => fr_FR.UTF-8
_SERVER["SHLVL"] => 1
_SERVER["HOME"] => /root
_SERVER["LOGNAME"] => root
_SERVER["SSH_CONNECTION"] => 192.168.0.162 45141 192.168.0.218 22
_SERVER["_"] => /usr/local/sbin/php-fpm
_SERVER["PHP_SELF"] =>
_SERVER["REQUEST_TIME_FLOAT"] => 1350654335.7699
_SERVER["REQUEST_TIME"] => 1350654335
_SERVER["argv"] => Array
(
)
_SERVER["argc"] => 0
_ENV["TERM"] => xterm
_ENV["SHELL"] => /bin/bash
_ENV["SSH_CLIENT"] => 192.168.0.162 45141 22
_ENV["SSH_TTY"] => /dev/pts/0
_ENV["USER"] => root
_ENV["MAIL"] => /var/mail/root
_ENV["PATH"] => /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
_ENV["PWD"] => /root
_ENV["LANG"] => fr_FR.UTF-8
_ENV["SHLVL"] => 1
_ENV["HOME"] => /root
_ENV["LOGNAME"] => root
_ENV["SSH_CONNECTION"] => 192.168.0.162 45141 192.168.0.218 22
_ENV["_"] => /usr/local/sbin/php-fpm
PHP License
This program is free software; you can redistribute it and/or modify
it under the terms of the PHP License as published by the PHP Group
and included in the distribution in the file: LICENSE
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
If you did not receive a copy of the PHP license, or have any
questions about PHP licensing, please contact lice...@php.net.
------------------------------------------------------------------------
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
