dev/mail#72 Remove call to custom fatal error handler from CRM_Core_E…

[seamuslee001]

…rror::debug_log_message

Overview

This removes the call to the custom fatal error that is proving to be problematic as per the report in the lab ticket https://lab.civicrm.org/dev/mail/-/issues/72

Before

Custom fatal error handler called from debug_log_message causing an exception to be thrown which blocks email sending

After

Email not blocked in sending

ping @MegaphoneJon @totten @eileenmcnaughton

[civibot]

(Standard links)

• If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
• If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

[eileenmcnaughton]

@seamuslee001 should we do a full revert?

[seamuslee001]

@eileenmcnaughton I would say no because the other part of the PR isn't the problem only this part because of https://github.com/civicrm/civicrm-core/blob/master/CRM/Core/Error.php#L962. I would add that looking at the reportError Extension only the part of the patch I am keeping in looks to be needed by it https://lab.civicrm.org/extensions/reporterror

[totten]

I agree with the partial revert on its merits.

Consider the question: what is fatalErrorHandler for? There are two different answers -- (1) quietly logging error info and (2) actively directing presentation of the error. I always assumed that this conflation of answers was a sort of organic/emergent/revisionist take on fatalErrorHandler, but it's actually explicit in the original framing:

https://issues.civicrm.org/jira/browse/CRM-841

IMHO CRM-841 was correct in identifying the problem and the two use-cases, but it was mistaken to conflate the two use-cases into one interface with a singular consumer. It's a mistake because:

• Applications need to write a log for many different reasons - even if they're not displaying a fatal error.
• Opinions about (1)-logging (e.g. "write to this file; send that email; insert to this DB table") are orthogonal to opinions about (2)-presentation (e.g. "format the error page with this branding; redirect to that generic help page; etc").
• The multiplicity is different:
  • For (1)-logging, many different logging opinions may coexist (with different priorities and filters).
  • For (2)-presentation, there is only one final, authoritative opinion. (It's not sensible to render two different stylized error-screens at the same time.)

The prior patch (#17277) to debug_log_message() delegates to fatalErrorHandler; I think the appeal of that was getting some leverage for the (1)-logging use-case. But from where we sit, we cannot tell if the specific fatalErrorHandler will do (1)-logging or (2)-presentation. And a listener which addresses (2)-presentation will do crazy-shit (like outputting HTML templates and sending redirects and throwing exceptions) that doesn't make sense for regular logging.

[eileenmcnaughton]

OK - that feels like good analysis - test fails do not relate

[mattwire]

@totten @seamuslee001 The idea of adding fatalErrorHandler into debug_log_message is that it allows it to work with eg. reporterror - I haven't actually pushed a patch for reporterror yet to make use of it.

The idea behind it came from the fact that you have no way of knowing what has gone into the log files without actually going and taking a look at them (or using some 3rd-party log parsing tools). With the fatalErrorHandler the idea is that you can use something like reporterror to be notified via email / other methods on any situation that might need the attention of a sysadmin.

Agree with reverting for 5.27/5.28 but do we have an idea of how we might resolve this properly in master while still having the "one place to capture all errors" functionality? The first step is almost certainly to remove the fatalErrorHandler from JobManager and replace with temporaryerrorscope?

[totten]

+1 for removing fatalErrorHandler from JobManager

With the (ed: patch based upon) fatalErrorHandler the idea is that you can use something like reporterror to be notified via email / other methods on any situation that might need the attention of a sysadmin... how we might resolve this properly in master while still having the "one place to capture all errors" functionality?

OK, with the caveat that (1)-logging of errors and (2)-final presentation of fatals are different things, I think I agree that we need a better interface to customize (1)-logging. The current interfaces are bit piecemeal/incomplete.

If I interpret correctly, you're looking for an interface along the lines of one of these:

## Tapping into core logging - if core used Monolog
Civi::log()->pushHandler(new CRM_Reporterror_LogHandler());

## Tapping into core logging - via internal-event
Civi::dispatcher()->addListener('civi.log.append', function($logMsg){
  // use $logMsg->level, $logMsg->message, $logMsg->context
});

## Tapping into core logging - via public-hook
function reporterror_civicrm_log($level, string $message, array $context) {
  ...
}

## Tapping into core logging - replace psr_log
function reporterror_civicrm_container($c) {
  $container->setDefinition('psr_log', new Definition('CRM_Reporterror_Log', []))->setPublic(TRUE);
}

## Tapping into core logging - similar style to Monolog, but repurpose some PSR-3 interfaces
Civi::log()->addLogger(new \MyPsr3Logger());

And there would be an expectation that (whichever notation it is) it would get access to all error messages, whether they're submitted to Civi::log() or CRM_Core_Error::debug_log_message() or whatever.

There are some implied variations in those examples:

• In the first, civicrm-core would depend on monolog. That's good - in getting a standard library of handlers. That's bad in that external packages (say, Drupal 10? Or some D8 customization?) may introduce version-conflicts down the line.
• In the second and third, it's a thinner API and not prone to external version-conflicts, but maybe it's not as rich as Monolog's API. (Between them, the internal-event is maybe more performance-friendly than using the public-hook. Not a big deal if there's only ERROR logging... but if there's DEBUG logging...)
• In the fourth, core's contract is extremely thin (almost anemic). It's not possible to have more than one party listening to the log.

However, the thing that strikes me most is that they all have a bootstrap issue. Basically, if the logging is "extensible", then it takes a few more moments before the "extension" comes online. Some errors that arise early (like if the MySQL/Redis credentials are bad or if the data-store is unavailable) can never be reported to an "extensible" logger... because our "extensibility" patterns (hooks, extension-modules, APIvX, settings, containers, etc) aren't available until latter part of bootstrap.

IMHO, there are two basic ways to address that:

1. Designate a non-extensible "boot logger" policy which applies during early bootstrap. Toward the middle or end of bootstrap, switch over to the "standard", extensible logging policy. The "standard" logging can use whatever patterns/tools we like.
   • Ex: "During bootstrap, only+always use PHP error_log()"
   • Ex: "During bootstrap, only+always use CiviCRM.log.XXXX"
2. In civicrm.settings.php (or an adjacent file), store a list of the preferred handlers. Preferably bundle a full library of handlers (eg bundle monolog) so that you can make a decent policy without needing to wire-up further addons.
   • Ex: "In civicrm.settings.php, the admin can use a define() or global to list their preferred log handlers."
   • Ex: "In civicrm.settings.php, the admin can write a custom log-function."
   • Ex: "Add a file civicrm.logging.php with a list of handlers. It is loaded along with civicrm.settings.php. (The upshot is that we can tighten the file-format of the adjacent file... so it's possible to have GUI tools which read+write the file.)

NOTE: Related discussion: https://lab.civicrm.org/community/feature-request/-/issues/12