Description
Hi there,
I started this thread on GitHub but Christoph (cmb69) suggested this
is the better place to discuss such a thing.
(initial post: https://github.com/php/php-src/issues/9745)
Basically, we have quite a high-loaded environment and we really want
to see timestamps
containing milli-/microseconds in our logs. It is easy to do for our
custom logger
but error messages from the PHP itself narrowed down to seconds (I'm
talking about method php_log_err_with_severity()
Link: https://github.com/php/php-src/blob/master/main/main.c#L799:~:text=php_log_err_with_severity
In our repository, we have a hacky patch that adds microsecs in this
log as well.
Unfortunately, such a solution is not really a good approach to
looking into the future.
I wanted to adopt our patch to share it with the community and
potentially merge it into upstream
but stumbled upon the fact that it isn't really straightforward to
format a date/time with microseconds
using the standard API available for an extension.
Basically, I found a couple of options:
(1) We can instantiate a DateTime object and call DateTime::format().
It looks working but it makes the logging function way more complicated
and potentially heavy
(2) date_format works directly with timelib_time and can properly
handle microsecs
but it is hidden inside ext/date/php_date.c, Not really sure if
it's a good idea to make it public
(3) In theory, it is possible to add one more parameter to php_format_date
but it'll break all the existing code. The change of signature
doesn't look like a good option.
However, we might be able to introduce another function if we
want to encapsulate work
with timelib_time within the ext/date.
(4) Derrek Rethans suggested introducing a new function (e.g.
php_format_date_ex) that
takes care of usecs (see the thread on Github)
Looking into the future, probably we would like to have this format
configurable, if so it looks easy to do but still I
can't see an easy way to handle the microseconds issue.
Could you please help me to find the right way and share your thoughts
about this topic (maybe there are
strong objections against such a change)?
Basically, we have quite a high-loaded environment and we really want
to see timestamps containing milli-/microseconds in our logs.
I'm not knowledgeable enough to comment on the implementation details, but from a user point of view I agree the feature would be useful. It would definitely need to be behind an ini setting, though, to avoid existing log parsers failing unexpectedly on the new format.
Regards,
Hi Mikhail,
--
Rowan Tommins
[IMSoP]
Hello everyone,
I tried following Derrek's approach (to introduce a new function).
A couple of considerations:
We used to have some pain when this format changed last time (I can't
remember details, unfortunately) but I don't feel like making an
option to provide backward compatibility is a good idea. Early or
lately, we will need to drop this compatibility and the users face
absolutely the same issue.
I hear people don't want to have this format configurable -- I tend to
agree that it's a bit overcomplication.
I'm not sure if I'm ready to switch to ISO8601 but if we have a
consensus here, I'm open to updating the patch. Basically, I'm open to
everything, please share your opinions.
Pull-request: https://github.com/php/php-src/pull/9844
Basically, we have quite a high-loaded environment and we really want
to see timestamps containing milli-/microseconds in our logs.I'm not knowledgeable enough to comment on the implementation details, but from a user point of view I agree the feature would be useful. It would definitely need to be behind an ini setting, though, to avoid existing log parsers failing unexpectedly on the new format.
Regards,
Hi Mikhail,--
Rowan Tommins
[IMSoP]--
To unsubscribe, visit: https://www.php.net/unsub.php
Hi,
Please try to not top post.
On Fri, Oct 28, 2022 at 10:29 AM Mikhail Galanin via internals <
internals@lists.php.net> wrote:
Hello everyone,
I tried following Derrek's approach (to introduce a new function).
A couple of considerations:
We used to have some pain when this format changed last time (I can't
remember details, unfortunately) but I don't feel like making an
option to provide backward compatibility is a good idea. Early or
lately, we will need to drop this compatibility and the users face
absolutely the same issue.I hear people don't want to have this format configurable -- I tend to
agree that it's a bit overcomplication.I'm not sure if I'm ready to switch to ISO8601 but if we have a
consensus here, I'm open to updating the patch. Basically, I'm open to
everything, please share your opinions.Pull-request: https://github.com/php/php-src/pull/9844
I think the consensus is more that it needs to be configurable and I'm in
favour of configurable option as well as we should not break the current
format.
Regards
Jakub
I think the consensus is more that it needs to be configurable and I'm
in favour of configurable option as well as we should not break the
current format.
In case of any confusion, I think this should be configurable as
"include microseconds: on / off", not configurable as "enter date format".
Regards,
--
Rowan Tommins
[IMSoP]
In case of any confusion, I think this should be configurable as
"include microseconds: on / off", not configurable as "enter date format".
Any reason it can't be configured to use ISO 8601?
Apache 2.4 allows you to use LogFormat "... [%{%Y-%m-%dT%H:%M:%S}t.%{msec_frac}t] ..." format_name
https://httpd.apache.org/docs/trunk/mod/mod_log_config.html
And MySQL uses "YYYY-MM-DDThh:mm:ss.uuuuuu":
https://dev.mysql.com/doc/refman/8.0/en/error-log-format.html#error-log-format-system-variables
When I'm doing some quick log checking, I often forget that PHP uses a
different date format... admittedly, it can help having the month spelled
out, so no one accidentally thinks it's the American format :-)
Craig
On Sun, 30 Oct 2022 at 17:42, Rowan Tommins rowan.collins@gmail.com
wrote:In case of any confusion, I think this should be configurable as "include microseconds: on / off", not configurable as "enter date format".Any reason it can't be configured to use ISO 8601?
That is really a separate question: ISO 8601 actually defines a whole
set of date/time formats, and allows any fraction of a second you want,
or none, or even omitting the seconds completely.
My main point is that I don't think it's necessary to complicate the
error handling routines with handling for arbitrary user-supplied date
formats; a single on/off ini setting would be a single if statement in
the C code, and only two possibilities that tools would need to parse if
they wanted to support both run-time modes.
I guess we could have the setting be "use new date format", and control
both the precision and whether the format is ISO 8601 compliant, but I'm
not convinced of the value.
Regards,
--
Rowan Tommins
[IMSoP]
I guess we could have the setting be "use new date format", and control
both the precision and whether the format is ISO 8601 compliant, but I'm
not convinced of the value
Thanks, and that's fair to avoid complicating the error handling routines.
It's not the end of the world to grep for "2022-11-01" in the other logs,
then have to change it to "01-Nov-2022" for the PHP error logs... and yes,
I know, those logs should be empty, but it's not my code, and there's a few
million "Passing null to parameter" errors to ignore ;-)
Craig
Hello good people,
(really hope I'm writing into the right thread this time).
I updated the patch considering the thoughts from this thread. Thank
you all for being so much responsive and helpful!
Meanwhile, there are two changes:
- Added function
php_format_timestamp' that takes microseconds part,php_format_date' remains unchanged to keep backward compatibility. - Added INI
error_log_usec= on|off (off by default) that changes
the timestamp.
Questions I have at the moment:
-
Naming (the most difficult part of our job, yeah) - does anyone
feel that they could suggest something better? Maybe someone can think
up something better, more clear/consistent with other parts of the
codebase? -
The INI-thing. When initially I mentioned being configurable, I
realised that it could've been perceived in many different ways:
- we can enable/disable the microseconds
- we can choose from a pre-defined list of formats (PHP7, PHP7 + msec,
PHP7+ usec, ISO8601, ISO8601+usec, etc...) - we also might want to use an Apache/HTTPd-like approach, e.g.
"[${time:format} $pid $hostname] $error_message"
Or, once we enable microseconds, we can switch to the ISO format, for
example (no, I don't like this approach but if we change the setting
name it might be not that confusing)
What do you think?
In case of any confusion, I think this should be configurable as
"include microseconds: on / off", not configurable as "enter date format".Any reason it can't be configured to use ISO 8601?
Apache 2.4 allows you to use
LogFormat "... [%{%Y-%m-%dT%H:%M:%S}t.%{msec_frac}t] ..." format_namehttps://httpd.apache.org/docs/trunk/mod/mod_log_config.html
And MySQL uses "YYYY-MM-DDThh:mm:ss.uuuuuu":
https://dev.mysql.com/doc/refman/8.0/en/error-log-format.html#error-log-format-system-variables
When I'm doing some quick log checking, I often forget that PHP uses a
different date format... admittedly, it can help having the month spelled
out, so no one accidentally thinks it's the American format :-)Craig
On Fri, 25 Nov 2022 at 14:01, Mikhail Galanin <
mikhail.galanin@team.bumble.com> wrote:
- The INI-thing. When initially I mentioned being configurable, I
realised that it could've been perceived in many different ways:
- we can enable/disable the microseconds
- we can choose from a pre-defined list of formats (PHP7, PHP7 + msec,
PHP7+ usec, ISO8601, ISO8601+usec, etc...)- we also might want to use an Apache/HTTPd-like approach, e.g.
"[${time:format} $pid $hostname] $error_message"Or, once we enable microseconds, we can switch to the ISO format, for
example (no, I don't like this approach but if we change the setting
name it might be not that confusing)What do you think?
While I’d personally like a bit more than microseconds on/off (just so I
can use the same format as other logs)… I think Rowan has the stronger case
on not overcomplicating the code, while still addressing the original issue.
And I’m not going to comment on naming, I’ve got my own I cannot decide on
(literal, vs literal-string, vs LiteralString).
Craig
Hi Mikhail,
Basically, we have quite a high-loaded environment and we really want
to see timestamps containing milli-/microseconds in our logs.I'm not knowledgeable enough to comment on the implementation details, but from a user point of view I agree the feature would be useful. It would definitely need to be behind an ini setting, though, to avoid existing log parsers failing unexpectedly on the new format.
I agree that I'd want this functionality available.
I found https://www.ietf.org/rfc/rfc3164.txt for syslogs which allows 1-6 digits after .. (haven't checked for any followup rfcs or how widely they are supported)
https://www.w3.org/TR/NOTE-datetime appears to document a useful subset of the iso 8601 functionality for anything documented as accepting iso 8601 dates, which allows microseconds
s = one or more digits representing a decimal fraction of a second
Does anyone know of commonly used tools for syslogs where the recent releases work with milliseconds but not microseconds (I'd hope not, since syslog has been around for decades, but it'd be useful to know)? PHP's fast so I'd agree microseconds would be useful to have, e.g. I've wanted this when debugging the order of db/cache calls or other operations in a web app
E.g. https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Date/toISOString (JavaScript dates and Date.now are in milliseconds)
The toISOString() method returns a string in simplified extended ISO format (ISO 8601), which is always 24 or 27 characters long (YYYY-MM-DDTHH:mm:ss.sssZ or ±YYYYYY-MM-DDTHH:mm:ss.sssZ, respectively).
I'd agree I'd want an ini setting, e.g. for non-technical users that wanted to upgrade to the next php minor version
without researching how to change their ad-hoc or external syslog parsers
(e.g. when logs are parsed using regex to extract the date and following fields)
An example: syslogs can be sent over the network to various services, e.g., https://www.elastic.co/guide/en/logstash/current/plugins-inputs-syslog.html#plugins-inputs-syslog-grok_pattern
Thanks,
Tyson
(4) Derrek Rethans suggested introducing a new function (e.g.
php_format_date_ex) that
takes care of usecs (see the thread on Github)
It's 'Derick' :-)
Looking into the future, probably we would like to have this format
configurable, if so it looks easy to do but still I can't see an easy
way to handle the microseconds issue.
Making things configurable requires an ini setting, which we generally
don't like to add. It wouldn't really work in this situation, as
warnings/errors happen either before or during INI file parsing, meaning
that it can't (yet) use the new format.
Could you please help me to find the right way and share your thoughts
about this topic (maybe there are strong objections against such a
change)?
I don't think we should change anything in PHP. Instead, use your
system's syslog. You can configure PHP to send all warnings to syslog by
setting "log_errors=1 error_log=syslog" in PHP.ini. In order to separate
out just the PHP issues, you can also set "syslog.facility=local1" (or
any other local).
On Unix systems, you can configure syslog to add milliseconds to the log
file messages. See https://askubuntu.com/a/1266114
If your system already uses systemd and journald, then you don't have to
use any configuration settings, and you can query the journal with:
journalctl -o short-iso-precise -r --facility=local1
A PHP warning would show up in there, with something like:
$ sudo journalctl -o short-iso-precise -r --facility=local1
2022-11-28T16:06:53.862980+0000 gargleblaster php[3143059]: PHP Warning: Undefined variable $fasd in Command line code on line 1
cheers,
Derick
--
https://derickrethans.nl | https://xdebug.org | https://dram.io
Author of Xdebug. Like it? Consider supporting me: https://xdebug.org/support
Host of PHP Internals News: https://phpinternals.news
mastodon: @derickr@phpc.social @xdebug@phpc.social
twitter: @derickr and @xdebug
Looking into the future, probably we would like to have this format
configurable, if so it looks easy to do but still I can't see an easy
way to handle the microseconds issue.Making things configurable requires an ini setting, which we generally
don't like to add. It wouldn't really work in this situation, as
warnings/errors happen either before or during INI file parsing, meaning
that it can't (yet) use the new format.
I'm not sure I understand this because error_log itself is already
configurable using INI so obviously if the file path is specified there,
then the logged time format should be the same if configured in ini. By
default there is no error log so errors that happen before should not be
logged anyway. Or do I miss anything?
Could you please help me to find the right way and share your thoughts
about this topic (maybe there are strong objections against such a
change)?I don't think we should change anything in PHP. Instead, use your
system's syslog. You can configure PHP to send all warnings to syslog by
setting "log_errors=1 error_log=syslog" in PHP.ini. In order to separate
out just the PHP issues, you can also set "syslog.facility=local1" (or
any other local).On Unix systems, you can configure syslog to add milliseconds to the log
file messages. See https://askubuntu.com/a/1266114If your system already uses systemd and journald, then you don't have to
use any configuration settings, and you can query the journal with:journalctl -o short-iso-precise -r --facility=local1
A PHP warning would show up in there, with something like:
$ sudo journalctl -o short-iso-precise -r --facility=local1
2022-11-28T16:06:53.862980+0000 gargleblaster php[3143059]: PHP Warning:
Undefined variable $fasd in Command line code on line 1
It is not always practical to use system log for PHP especially for users
using more than one FPM pool. Log files also offer some advantages like
easier export and post processing so I think there is still place for log
files and we should support the users that still use them which includes
new features like this one.
Cheers
Jakub
Hi Derick, Jakub and the team,
Thank you so much for your input. Sorry for being so slow with this --
I haven't forgotten, it's just unfortunately, I'm not capable to
handle all the things going around but I keep trying :)
I did some research about why we keep using plain log files and our
folks basically follow what Jakub said - we have our custom log
collector (similar to Scribe, Fluentd and others) which has quite
complicated routing rules and it was pretty straightforward to use
files but adding Syslog adds undesirable complexity to this system.
Although, it certainly doesn't look impossible.
Speaking about backward compatibility stuff - I can think of another
option, to postpone such a change till PHP v9.0, where we tend to
introduce breaking changes. We are not a startup anymore - can wait
for a couple of years.
I saw the suggestion to draft an RFC for this to thoroughly walk
through the question. I'm pretty open to this but it'll take a lot of
time. So guys, do you feel it's feasible to do? I can imagine some
people don't want to be harsh to say "please, stop this nonsense" :)
I can see that this change might not bring a lot of value and appeared
to be controversial so I'm fine to stop - we can keep this as our
private patch. But if someone feels it might be something good, I can
proceed with the RFC or something.
Thank you for your patience so far.
Looking into the future, probably we would like to have this format
configurable, if so it looks easy to do but still I can't see an easy
way to handle the microseconds issue.Making things configurable requires an ini setting, which we generally
don't like to add. It wouldn't really work in this situation, as
warnings/errors happen either before or during INI file parsing, meaning
that it can't (yet) use the new format.I'm not sure I understand this because error_log itself is already configurable using INI so obviously if the file path is specified there, then the logged time format should be the same if configured in ini. By default there is no error log so errors that happen before should not be logged anyway. Or do I miss anything?
Could you please help me to find the right way and share your thoughts
about this topic (maybe there are strong objections against such a
change)?I don't think we should change anything in PHP. Instead, use your
system's syslog. You can configure PHP to send all warnings to syslog by
setting "log_errors=1 error_log=syslog" in PHP.ini. In order to separate
out just the PHP issues, you can also set "syslog.facility=local1" (or
any other local).On Unix systems, you can configure syslog to add milliseconds to the log
file messages. See https://askubuntu.com/a/1266114If your system already uses systemd and journald, then you don't have to
use any configuration settings, and you can query the journal with:journalctl -o short-iso-precise -r --facility=local1
A PHP warning would show up in there, with something like:
$ sudo journalctl -o short-iso-precise -r --facility=local1
2022-11-28T16:06:53.862980+0000 gargleblaster php[3143059]: PHP Warning: Undefined variable $fasd in Command line code on line 1It is not always practical to use system log for PHP especially for users using more than one FPM pool. Log files also offer some advantages like easier export and post processing so I think there is still place for log files and we should support the users that still use them which includes new features like this one.
Cheers
Jakub