php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #45191 error_log ignores date.timezone php.ini val when setting logging timestamps
Submitted: 2008-06-05 23:50 UTC Modified: 2009-05-03 19:09 UTC
From: info at organicdata dot co dot za Assigned: derick
Status: Closed Package: Date/time related
PHP Version: 5.2CVS-2008-06-05 (snap) OS: Centos el5
Private report: No CVE-ID:
 [2008-06-05 23:50 UTC] info at organicdata dot co dot za
Description:
------------
I've noticed that changing the default PHP timezone using either php.ini date.timezone or date_default_timezone_set appears to have no effect on the timestamp used for each entry PHP writes to the file set by php.ini value error_log (when php.ini log_errors = On)

It seems to use the system timestamp regardless. I've done some searching on the web but found nothing and am afraid I'm not sure whether a bug or by design but it seems strange enough to submit here

Reproduce code:
---------------
php.ini
-------
log_errors = On
error_log = myerrors.log

mycode.php
----------
error_reporting(E_STRICT);
date_default_timezone_set("UTC");
SOMEBADCONSTANT
date_default_timezone_set("Africa/Johannesburg");
ANOTHERBADCONSTANT

resulting myerrors.log
----------------------
[06-Jun-2008 00:41:34] PHP Notice:  Use of undefined constant SOMEBADCONSTANT - assumed 'SOMEBADCONSTANT' in /prj/mycode.php on line 3
[06-Jun-2008 00:41:34] PHP Notice:  Use of undefined constant ANOTHERBADCONSTANT - assumed 'ANOTHERBADCONSTANT' in /prj/mycode.php on line 5


Expected result:
----------------
As Africa/Johannesburg is 2 hours ahead of UTC, I would have expected the second myerrors.log entry to read
[06-Jun-2008 02:41:34] PHP Notice:  Use of undefined constant ANOTHERBADCONSTANT - assumed 'ANOTHERBADCONSTANT' in /prj/mycode.php on line 5

And even if the comment is that date_default_timezone_set has no effect, I saw the same when changing date.timezone in php.ini 

The error logging appears to ignore it completely and simply use the system time


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2008-07-14 10:06 UTC] derick@php.net
Thank you for taking the time to write to us, but this is not
a bug. Please double-check the documentation available at
http://www.php.net/manual/ and the instructions on how to report
a bug at http://bugs.php.net/how-to-report.php

This is normal. The error log is not *written* by PHP, but by syslog. Syslog doesn't care about PHP's internal timezone, and thus formats the log message according to the system timezone. Just change the system timezone if it's incorrect.
 [2008-07-15 17:05 UTC] info at organicdata dot co dot za
Thanks very much for the feedback - I understand that my "bug" interpretation may have been wrong. My concern is really a result of a combination of the following:

1. the PHP recommendations I've seen is that you don't rely on system time zone and set the time zone explicitly in PHP
2. I want to have a single central logging file containing all system errors 
3. The custom error handling routine I use does not catch all errors that PHP can throw, some are only captured by the internal error handler used by setting log_errors=On

Because of 3, the only way I can achieve 2 that I can see is to set the output file in my custom error handler to be the same as the value set in the inifile parameter error_log. This means that the errors I trap are then inserted into the same file as the ones I am unable to trap due to the limitation of 3 and they occur in a sensible sequence.

As per your reply however, the only way for me to ensure that the errors written to the file by my custom error handler have meaningful timestamps relative to the ones written as a result of the log_errors=On parameter means that i have to set my PHP explicit timezone to the same as that of the server.

...which means that I'm setting the value on the server and again in PHP and that if there is some change in the server timezone for whatever reason at a later stage, my log file will become "a mess" of inconsistent timestamps (depending on whether the error written to the file was as a result of my custom error handling routine or whether handled by the internal error logging.

...which in turn from my perspective means that it is in fact dangerous to explicitly set the PHP internal timezone and actually safer to allow everything to rely only on the system timezone - at least this way I can guarantee consistency in the timestamps of the errors written to the log file

well that's the way I see it anyway - not sure whether I'm missing something big here

thanks again for the feedback
 [2008-07-28 22:46 UTC] jani@php.net
Actually error_log="somefile.log" does not use any syslog stuff to write the entries in it. This is the line from main.c:490 which gets executed if error_log != syslog:

strftime(error_time_str, sizeof(error_time_str), "%d-%b-%Y %H:%M:%S", php_localtime_r(&error_time, &tmbuf));

There are 2 problems here: [a] it's using locale sensitive %b modifier [b] It doesn't care about date.timezone. 

Solutions:
[a] IMO it should use this pattern instead: "%Y-%m-%d %H:%M:%S" (f.e. lighttpd uses this for it's error_log entries :)
[b] I don't know how to safely achieve the above mentioned issues with date.timezone vs. system timezone. Might be better leave this as is..
 [2008-07-28 22:47 UTC] jani@php.net
Derick, any comments?
 [2008-07-29 06:46 UTC] derick@php.net
It should be switched from strftime() to php_format_date(). This is not an issue with the Date/Time functionality though, but with the syslog one.
 [2009-05-03 19:09 UTC] derick@php.net
This bug has been fixed in CVS.

Snapshots of the sources are packaged every three hours; this change
will be in the next snapshot. You can grab the snapshot at
http://snaps.php.net/.
 
Thank you for the report, and for helping us make PHP better.


 [2012-01-30 09:20 UTC] wadkar at gmail dot com
This bug may still be a problem for someone, here are the details :
# php -v
PHP 5.3.8 (cli) (built: Dec  1 2011 12:23:50)

The problem is with the OS this time= CentOS 5+OpenVZ with IUS repo. The host machine (with the OpenVZ kernel) has no problems
# uname -a
Linux vz-node2 2.6.18-274.el5.028stab093.2xen #1 SMP Tue Aug 23 16:50:42 MSD 2011 x86_64 x86_64 x86_64 GNU/Linux
# echo '' > /tmp/error.log && php -dlog_errors=On -derror_log=/tmp/error.log -r 'error_reporting(-1); SOMEBADCONSTANT;' && cat /tmp/error.log && date

[30-Jan-2012 14:38:56] PHP Notice:  Use of undefined constant SOMEBADCONSTANT - assumed 'SOMEBADCONSTANT' in Command line code on line 1
Mon Jan 30 14:38:56 IST 2012

The same code snippet, however, when run on a VM gives

# uname -a
Linux container1 2.6.18-274.el5.028stab093.2xen #1 SMP Tue Aug 23 16:50:42 MSD 2011 x86_64 x86_64 x86_64 GNU/Linux
# echo '' > /tmp/error.log && php -dlog_errors=On -derror_log=/tmp/error.log -r 'error_reporting(-1); SOMEBADCONSTANT;' && cat /tmp/error.log && date
 
[30-Jan-2012 09:10:05 UTC] PHP Notice:  Use of undefined constant SOMEBADCONSTANT - assumed 'SOMEBADCONSTANT' in Command line code on line 1
Mon Jan 30 14:40:05 IST 2012

The internal TZ settings are respected though:
# php -i | grep timezone
Default timezone => Asia/Calcutta
date.timezone => Asia/Calcutta => Asia/Calcutta
# php -r 'echo date_default_timezone_get(), PHP_EOL; $d = new DateTime(); echo $d->format(DATE_RFC822), PHP_EOL;' && date
Asia/Calcutta
Mon, 30 Jan 12 14:49:17 +0530
Mon Jan 30 14:49:17 IST 2012

I am not sure if this is the bug with PHP or with virtualized environment. I just wanted to comment/report my observation. I was worried for a moment that my CLI scripts would fail to respect the TZ settings, but that is not the case.

Thanks

-Sudarshan Wadkar
 [2012-02-09 23:21 UTC] daniel dot caillibaud at sesamath dot net
In an openvz VM, with php-fpm 5.3.10 (debian squeeze OS), with a sytem date configured on UTC+1 (on physical host, but `date` in VM also show UTC+1), in php.ini I've a

date.timezone = "Europe/Paris"

but php error_log date is displayed as UTC
[09-Feb-2012 23:15:08 UTC] PHP Notice: ...
while all others logs are in the system timezone, e.g nginx
[10/Feb/2012:00:16:46 +0100] ...

and syslog as well is UTC+1 (but doesn't show it on each log line).

Hope it helps...
 [2012-02-11 18:15 UTC] christopher at specialtyproduce dot com
It seems this bug may have reappeared between 5.3.8 and 5.3.9?

I have two MS 2008 R2 VMs, built from the same starting images.  Both running IIS 7.5, system timezone is set for "Pacific Standard Time" and the TZ environment variable is not set.

Machine A : PHP 5.3.8 (cli) (built: Aug 23 2011 12:14:39)
  (Originally configured with PHP 5.2.17 and subsequently upgraded to 5.3.8)
Machine B : PHP 5.3.9 (cli) (built: Jan 10 2012 16:33:06)

Their php.ini files are virtually identical, with:
log_errors = On
date.timezone=America/Los_Angeles
error_log="C:\PHP\logs\php53_errors.log"

I ran a version of the "mycode.php" from the original bug report on both machines.

mycode.php
----------
FIRSTBADCONSTANT;
date_default_timezone_set("UTC");
SOMEBADCONSTANT;
date_default_timezone_set("America/Los_Angeles");
ANOTHERBADCONSTANT;

Machine A php53_errors.log
--------------------------
[11-Feb-2012 09:39:18] PHP Notice:  Use of undefined constant FIRSTBADCONSTANT - assumed 'FIRSTBADCONSTANT' in C:\Temp\mycode.php on line 2
[11-Feb-2012 17:39:18] PHP Notice:  Use of undefined constant SOMEBADCONSTANT - assumed 'SOMEBADCONSTANT' in C:\Temp\mycode.php on line 4
[11-Feb-2012 09:39:18] PHP Notice:  Use of undefined constant ANOTHERBADCONSTANT - assumed 'ANOTHERBADCONSTANT' in C:\Temp\mycode.php on line 6

Machine B php53_errors.log
--------------------------
[11-Feb-2012 18:06:52 UTC] PHP Notice:  Use of undefined constant FIRSTBADCONSTANT - assumed 'FIRSTBADCONSTANT' in C:\Temp\mycode.php on line 2
[11-Feb-2012 18:06:52 UTC] PHP Notice:  Use of undefined constant SOMEBADCONSTANT - assumed 'SOMEBADCONSTANT' in C:\Temp\mycode.php on line 4
[11-Feb-2012 18:06:52 UTC] PHP Notice:  Use of undefined constant ANOTHERBADCONSTANT - assumed 'ANOTHERBADCONSTANT' in C:\Temp\mycode.php on line 6

The 5.3.9 error reporting seems locked in UTC.
 [2012-02-12 09:56 UTC] wadkar at gmail dot com
@christopher
Interesting observation. My report is with 5.3.8 version, which outputs the log with UTC timestamp (the timezone is part of it). I am getting a feeling that this might not be a direct issue with php-src but somewhere in between system calls made by php-src for logging and the OS itself which passes on TZ data for this call.
 [2012-05-03 14:37 UTC] php at sboxx dot org
Red Hat Entrprise Linux 6.2
PHP 5.4.1
date.timezone = Europe/Berlin
log_errors = On
error_log = /var/log/php_errors.log

All messages in /var/log/php_errors.log have UTC timestamps.
System time is set and correctly displayed as CET/CEST.
 [2012-05-30 07:32 UTC] rohgeo at gmail dot com
php 5.4.3
all messages in /var/log/php_errors.log have UTC timestamps.
 [2012-06-23 13:55 UTC] bram at ebskamp dot me
Same problem here with PHP 5.4.3.
 [2012-07-17 09:54 UTC] rohgeo at gmail dot com
php 5.4.4
all messages in /var/log/php_errors.log have UTC timestamps
 [2012-07-20 11:28 UTC] rohgeo at gmail dot com
Same problem here with PHP 5.4.5.
 
PHP Copyright © 2001-2014 The PHP Group
All rights reserved.
Last updated: Wed Apr 16 16:02:23 2014 UTC