dev/core#4270 createDebugLogger/ConfigAndLog: use a standard date format

[mlutfy]

Overview

Discussion: https://lab.civicrm.org/dev/core/-/issues/4270

The CiviCRM "ConfigAndLog" logs use a weird custom format, which depends on the system/user's locale, so it can be, for example:

août 01 09:02:59  [info] $IDS Detector Details = Array
[...]

This format is difficult to parse.

Before

août 01 09:02:59  [info] $IDS Detector Details = Array

After

2023-08-01 09:02:59-0500  [info] $IDS Detector Details = Array

Technical Details

strftime is deprecated as of PHP 8.1, but PEAR Log seems to be using a shim for now.

Comments

I'd rather avoid the larger questions around logging. This is really just about the date format.

It might break extensions such as logviewer.

Example promtail (Grafana/Loki) config:

- job_name: civicrm_log
  static_configs:
  - targets:
      - localhost
    labels:
      job: civicrm_log
      host: myhost1.example.org
      __path__: /var/aegir/platforms/*/sites/*/files/civicrm/ConfigAndLog/CiviCRM.*.log
  pipeline_stages:
  - match:
      selector: '{job="civicrm_log"}'
      stages:
      - multiline:
          # Identify timestamps as first line of a multiline block. Enclose the string in single quotes.
          # Ex: 2038-01-01 23:50:12 (not matching on the TZ, less important here)
          firstline: '^\d{4}-\d{2}-\d{2}.\d{1,2}:\d{2}:\d{2}'
          max_wait_time: 3s
          # Backtraces can be insane sometimes
          max_lines: 5000
      - regex:
          # Flag (?s:.*) needs to be set for regex stage to capture full traceback log in the extracted map.
          # Ex: 2023-09-21 23:48:57-0500  [error] Error message..
          expression: '^(?P<time>\d{4}-\d{2}-\d{2}.\d{1,2}:\d{2}:\d{2}.\d{4})  \[?P<level>(\w+)\] (?P<message>(?s:.*))$'
      - timestamp:
          source: time
          format: '2006-01-02 15:04:05-0700'

cc @adixon @artfulrobot

[civibot]

🤖 Thank you for contributing to CiviCRM! ❤️ We will need to test and review this PR. 👷

Introduction for new contributors...

• If this is your first PR, an admin will greenlight automated testing with the command ok to test or add to whitelist.
• A series of tests will automatically run. You can see the results at the bottom of this page (if there are any problems, it will include a link to see what went wrong).
• A demo site will be built where anyone can try out a version of CiviCRM that includes your changes.
• If this process needs to be repeated, an admin will issue the command test this please to rerun tests and build a new demo site.
• Before this PR can be merged, it needs to be reviewed. Please keep in mind that reviewers are volunteers, and their response time can vary from a few hours to a few weeks depending on their availability and their knowledge of this particular part of CiviCRM.
• A great way to speed up this process is to "trade reviews" with someone - find an open PR that you feel able to review, and leave a comment like "I'm reviewing this now, could you please review mine?" (include a link to yours). You don't have to wait for a response to get started (and you don't have to stop at one!) the more you review, the faster this process goes for everyone 😄
• To ensure that you are credited properly in the final release notes, please add yourself to contributor-key.yml
• For more information about contributing, see CONTRIBUTING.md.

Quick links for reviewers...

• ➡️ PR Demo site (can be rebuilt with the command test this please).
• 📖 Review standards
• 🗒️ Review template (brief or verbose)

➡️ Online demo of this PR 🔗

[civibot]

The issue associated with the Pull Request can be viewed at https://lab.civicrm.org/dev/core/-/issues/4270

[artfulrobot]

Yes from me!

[eileenmcnaughton]

Endorsed emphatically by @artfulrobot - mergeable on a thumbs up from @adixon or after a few days if no response

[artfulrobot]

Aside: strftime() that parses this date format is deprecated as of php8.1...

[mlutfy]

@artfulrobot right - from what I understand, we are applying this PR from @seamuslee001 for PHP 8.1 compatibility: pear/Log#23

[adixon]

Yes please, break the log viewer! Any reason we can't add a timezone in that formatting string?

[colemanw]

@mlutfy ^

[totten]

+1 for switching to Y-m-d

+1 for adding %Z or %z. (I don't see anything in pear/log to normalize time-zone. The PHP time-zone can fluctuate based on the user/request/configuration.)

[artfulrobot]

I'd go for %z. Feels more parseable.

e.g. difference is

• 2022-05-23 00:00:00+0100 vs 2022-05-23 00:00:00 CEST
• 2022-12-23 00:00:00+0000 vs 2022-12-23 00:00:00 CET

Various date parsing things can be troublesome with understanding timezones. e.g. Javascript Date API is implemented differently on Chromium and Firefox and supports different timezones.

[mlutfy]

I went with %z (ex: 2022-05-23 00:00:00+0100)

For a moment I pondered on being more ISO8601 compliant by using the T separator, such as 2022-05-23T00:00:00+0100, but I figured most parsers don't care and it's less readable for humans.

[mlutfy]

Works well in Grafana/Loki:

(I updated the promtail config example in the PR summary, if anyone is curious)

[totten]

Yay!

[agileware-justin]

Just noting that this PR fixed the following PHP fatal error we had observed on sites when using CiviCRM 5.66.2 and CiviCRM 5.64.4 and PHP 8.1.

PHP 8.1 - Got error 'PHP message: PHP Fatal error: Uncaught IntlException: datefmt_create: invalid locale: U_ILLEGAL_ARGUMENT_ERROR

Posting here to help others with Googl'ing.

Might want to fast track this release given that PHP 8.1 is now the recommended version. We suspect this problem only impacts non-US sites.

Agileware Ref: CIVICRM-2187

[mlutfy]

@agileware-justin interesting, thanks for posting. If my calculations are correct 🧐 this change will be in the next stable, which I think is out this wed/thursday.

[agileware-justin]

Thanks @mlutfy

[seamuslee001]

@agileware-justin I would also add that it seems that something broke in a point release of PHP as @demeritcowboy found this php/php-src#12561

[agileware-justin]

Yes @seamuslee001 that's the problem, right there - PHP 8.1.25

[agileware-justin]

xkcd spot on yet again...

https://xkcd.com/2347/

[artfulrobot]

FYI: next up: I'd like to (a) centralise all log calls to use Civi::log() and (b) prevent any civi logging funciton from storing binary data in the log files (which makes them hard to grep, amongst other annoyances).