I noticed something odd yesterday while reviewing log data on one of the RHEL 7 web servers I look after. Peering through the PHP error log, I noticed that all of the timestamps were formatted using the Coordinated Universal Time (UTC ... because acronyms that make sense are for losers).
[29-Jul-2015 14:26:04 UTC] PHP [redacted] on line 511
[29-Jul-2015 14:26:04 UTC] PHP [redacted] on line 530
[29-Jul-2015 14:26:04 UTC] PHP [redacted] on line 574
[29-Jul-2015 14:26:04 UTC] PHP [redacted] on line 607
[29-Jul-2015 14:26:04 UTC] PHP [redacted] on line 629
There is nothing wrong with UTC. UTC avoids the calamities inherent in the highly politicized, frequently changed, deeply flawed and inevitably pointless Daylight Savings rules. And unlike epoch-based timestamps, UTC is human readable. It's good stuff. Your hwclock should use it.
With that said, with this particular server a decision was made for logging to consistently be Eastern Time. So I jumped through a number of hoops to make this the case while maintaining reliability. I set the system clock timezone, and enabled regular check-ins with an NTP server pool:
# timedatectl
Local time: Wed 2015-07-29 10:40:22 EDT
Universal time: Wed 2015-07-29 14:40:22 UTC
RTC time: Wed 2015-07-29 14:40:21
Timezone: America/New_York (EDT, -0400)
NTP enabled: yes
NTP synchronized: yes
PHP itself demands that timezone be explicitly declared in php.ini. Failing to do so produces `
E_NOTICE` notifications in PHP logs. So, I assigned that value to Eastern time also:
[Date]
; Defines the default timezone used by the date functions
; http://php.net/date.timezone
date.timezone = America/New_York
Meanwhile, this server uses rsyslog v7.4.7, and relies on the default timestamp template for logs handled by rsyslog.
# rsyslogd -v
rsyslogd 7.4.7, compiled with:
FEATURE_REGEXP: Yes
FEATURE_LARGEFILE: No
GSSAPI Kerberos 5 support: Yes
FEATURE_DEBUG (debug build, slow code): No
32bit Atomic operations supported: Yes
64bit Atomic operations supported: Yes
Runtime Instrumentation (slow code): No
uuid support: Yes
# less /etc/rsyslog.conf
[...]
# Use default timestamp format
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
The upshot of this is that every log file on this server that uses time stamps uses the Eastern Time Zone, even `dmesg -e`, with the sole exception of the PHP error log. I point out the rsyslog settings despite the fact that php.ini's error log settings could give readers the impression that with the current configuration of my system syslog settings wouldn't be managing this situation.
log_errors = On
; Log errors to specified file. PHP's default behavior is to leave this value
; empty.
; http://php.net/error-log
; Example:
;error_log = php_errors.log
; Log errors to syslog (Event Log on NT, not valid in Windows 95).
;error_log = syslog
error_log = /var/log/httpd/php.log
See how the role of syslog is a big vague?
Its entirely possible I have overlooked something painfully obvious. It certainly wouldn't be the first time. I am just a dude; I make mistakes (
and yet the Dude abides).
But - I am not the first person to come across this issue.
Bug report #45191 was filed over 7 years ago to address this issue:
[2008-06-05 23:50 UTC] info at organicdata dot co dot zaDescription:
------------
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
Derick Rethans handled the bug report initially. I'm not going to bust Derick's balls too hard; I don't know him personally but even a brief look at his contribution history is enough to demonstrate his competency as a developer. He has certainly done more for the PHP project than I have.
That said, Derick wasn't interested in dealing with this.
[2008-07-14 10:06 UTC] derick@php.netThank 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.
MAN. You are a
dumbass info at organicdata dot co dot za. RTFM, right? organicdata's reply would seem to confirm Derick's finding. It was a lengthy complaint about what a hassle it is to set timezone in two places, particularly in situations where your server in the Netherlands is hosting HawaiiAutoMechanics.Biz or something. This scenario is indeed a bummer, but don't forget what's going on with my server - changing the system timezone doesn't do a damn thing with this issue (in a version of PHP two minor releases later: 5.2 -> 5.4). Fortunately, Jani jumps in with here 2 cents.
[2008-07-28 22:46 UTC] jani@php.netActually 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..
To which Derick responds:
[2008-07-29 06:46 UTC] derick@php.netIt 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.netThis 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.
All better!
Well, not quite. strftime() was in fact replaced, and references to `%b` were removed, in the PHP source files.
However by 5.3.8, the bug was being reported continuously for RHEL and CentOS users. As of my version, here is what I believe to be the relevant handler; starting from main.c:615
/* Try to use the specified logging location. */
if (PG(error_log) != NULL) {
#ifdef HAVE_SYSLOG_H
if (!strcmp(PG(error_log), "syslog")) {
php_syslog(LOG_NOTICE, "%s", log_message);
PG(in_error_log) = 0;
return;
}
#endif
fd = VCWD_OPEN_MODE(PG(error_log), O_CREAT | O_APPEND | O_WRONLY, 0644);
if (fd != -1) {
char *tmp;
int len;
char *error_time_str;
time(&error_time);
#ifdef ZTS
if (!php_during_module_startup()) {
error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 1 TSRMLS_CC);
} else {
error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 0 TSRMLS_CC);
}
#else
error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 1 TSRMLS_CC);
#endif
len = spprintf(&tmp, 0, "[%s] %s%s", error_time_str, log_message, PHP_EOL);
Additional bug reports were opened where #45191 left off in 2012, demonstrating errors in IIS, Debian, Gentoo and other operating systems. Apparently,
the fix for this issue caused segfaults in Windows ZTS builds per bug report #60373. A
patch was released in
report #60723. The distinction between the patch and the release I am using is ... subtle to say the least.
@@ -627,7 +627,15 @@ PHPAPI void php_log_err(char *log_message TSRMLS_DC)
char *error_time_str;
time(&error_time);
- error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 0 TSRMLS_CC);
+#ifdef ZTS
+ if (php_during_module_startup()) {
+ error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 0 TSRMLS_CC);
+ } else {
+ error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 1 TSRMLS_CC);
+ }
+#else
+ error_time_str = php_format_date("d-M-Y H:i:s e", 13, error_time, 1 TSRMLS_CC);
+#endif
len = spprintf(&tmp, 0, "[%s] %s%s", error_time_str, log_message, PHP_EOL);
#ifdef PHP_WIN32
php_flock(fd, 2);
The only difference appears to be the inversion of the `if (php_during_module_startup())` loop, and the attendant flipping of the TSRMLS_CC that would appear to ensure that the patch is substantively identical to the source for 5.4.16.
This sort of thing is just obnoxious enough to drive my OCD side up a wall, while not posing any serious security or functionality risks given the current deployment it's not worth it to spend a ton of energy testing multiple versions of PHP to resolve it.
Has anyone had success resolving this issue with more recent versions of PHP? Let me know!
