Everything
php
Learn Community Releases The PHP Project
Home » Project » Newsgroups » php.internals » Microseconds to error log »

Microseconds to error log

php.internals

Unnamed Person

3 years ago
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)?

Rowan Collins

3 years ago
On 21 October 2022 08:47:30 BST, Mikhail Galanin via internals <internals@lists.php.net> wrote:
>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]

Unnamed Person

3 years ago
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 On Fri, Oct 21, 2022 at 11:46 AM Rowan Tommins <rowan.collins@gmail.com> wrote:

Jakub Zelenka

3 years ago
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

Rowan Collins

3 years ago
On 30/10/2022 11:38, Jakub Zelenka wrote:
> > 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]

Craig Francis

3 years ago
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? 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

Rowan Collins

3 years ago
On 31/10/2022 10:16, Craig Francis wrote:
> 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]

Craig Francis

3 years ago
On Mon, 31 Oct 2022 at 18:23, Rowan Tommins <rowan.collins@gmail.com> wrote:
> 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

Unnamed Person

3 years ago
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: 1. 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? 2. 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? On Mon, Oct 31, 2022 at 10:16 AM Craig Francis <craig@craigfrancis.co.uk> wrote:

Craig Francis

3 years ago
On Fri, 25 Nov 2022 at 14:01, Mikhail Galanin < mikhail.galanin@team.bumble.com> wrote:
> 2. 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

tyson andre

3 years ago
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

Derick Rethans

3 years ago
On Fri, 21 Oct 2022, Mikhail Galanin via internals wrote:
> (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

Jakub Zelenka

3 years ago
On Mon, Nov 28, 2022 at 4:13 PM Derick Rethans <derick@php.net> wrote:
> On Fri, 21 Oct 2022, Mikhail Galanin via internals wrote: > > 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/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 > >
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

Unnamed Person

3 years ago
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. On Tue, Nov 29, 2022 at 11:43 AM Jakub Zelenka <bukka@php.net> wrote: