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