Page MenuHomePhabricator

DeferredUpdates should not silently ignore critical exceptions
Open, NormalPublic

Description

Currently, any critical exceptions thrown from any DeferrableUpdate are silently ignored by DeferredUpdates::runUpdate.

Expected:
Exceptions thrown by a DeferrableUpdate cause a code 500 response (if still possible), and should go to the error log per default. They should also cause unit tests to fail.

Observed:
Critical exceptions (such as RuntimeExceptions or LogicExceptions) thrown by a DeferrableUpdate are silently ignored. They are only visible in the debug log if the "exception" channel is explcitly enabled.

Analysis:

  • DeferredUpdates::runUpdate calls MWExceptionHandler::rollbackMasterChangesAndLog
  • MWExceptionHandler::rollbackMasterChangesAndLog calls MWExceptionHandler::logException, which calls error() on a Logger returned by LoggerFactory::getInstance( 'exception' ).
  • The logger used by MWExceptionHandler is per default a LegacyLogger. LegacyLogger::error forwards to LegacyLogger::log, which, per default, ends up calling MWDebug::debugMsg, but not LegacyLogger::emit(), because shouldEmit() returns false.
  • shouldEmit() returns false unless $wgDebugLogGroups[] contains 'exception', which is this LegacyLogger's default channel as per the call to LoggerFactory::getInstance().

Proposal:

  • LegacyLogger::log should default to the wfErrorLog chennel if $level is >= LogLevel::ERROR. In addition, MWDebug::warning should be called instead of MWDebug::debugMsg if $level is >= LogLevel::WARNING.
  • It's unclear if level LogLevel::WARNING should be considered a "developer warning" which just causes tests to fail, or a "production warning" that also goes into error logs. In any case, unit tests should fail when warning are triggered (unless the warnign was specifically suppressed).
  • Alternatively, if the behavior of LegacyLogger should not be changed, DeferredUpdates::runUpdate should be changed to call wfLogWarning() for all exceptions that are not ErrorPageErrors (and maybe even for them).

Event Timeline

daniel created this task.Mar 20 2018, 4:09 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 20 2018, 4:09 PM
Krinkle added a subscriber: Krinkle.EditedMar 28 2018, 10:33 PM

unit tests should fail when warning are triggered

For the record, this is already the case. Any "php error" (notice, warning, error) is turned into an exception by PHPUnit and fails the test. Any "mediawiki error" (not debug/info) that goes to mw-exception.log or mw-error.log in Jenkins, will make the job fail per T50002. Our Jenkins jobs, after completing the PHPUnit run, assert that these files are empty/non-existent.

However, if they are turned into debug-level errors, then, naturally, those don't cause tests to fail given we have (and should have) plenty of debug messages being output normally.

daniel added a comment.EditedMar 29 2018, 7:41 PM

@Krinkle wrote:

Any "php error" (notice, warning, error) is turned into an exception by PHPUnit and fails the test.

I know, I wrote that code :) My point is, calling LegacyLogger::log with LogLevel::WARNING does not do this. But should.

Any "mediawiki error" (not debug/info) that goes to mw-exception.log or mw-error.log in Jenkins, will make the job fail per T50002

That is correct for jenkins, but local tests will not fail. Also, for a vanilla install, such errors will be invisible on the live system, unless someone enables and monitors mw-exception.log.

Change 423035 had a related patch set uploaded (by Daniel Kinzler; owner: Daniel Kinzler):
[mediawiki/core@master] Make DeferredUpdates re-throw exceptions during testing.

https://gerrit.wikimedia.org/r/423035

@Krinkle wrote:

Any "php error" (notice, warning, error) is turned into an exception by PHPUnit and fails the test.

Just to clarify, I was referring to convertErrorsToExceptions.

We currently enable $wgDebugLogFile (which writes all severities and all channels of MediaWiki logging) in Jenkins' LocalSettings file for MediaWiki jobs. We also have separate files for specific channels (php-exception, php-error, and ratelimit).

Perhaps we can also configure it so that of all channels, messages with severity of WARNING and higher, are written emitted as php errors. That would naturally make them show up in stderrr and/or caught by PHPUnit.

I'm not entirely sure how yet, but I believe this would be possible using the modern $wgMWLoggerDefaultSpi configuration format (instead of the older wgDebugLogGroups config, which just feeds into that).

Change 423035 merged by jenkins-bot:
[mediawiki/core@master] Make DeferredUpdates re-throw exceptions during testing.

https://gerrit.wikimedia.org/r/423035

daniel added a comment.May 3 2018, 9:26 AM

@Krinkle wrote:

Perhaps we can also configure it so that of all channels, messages with severity of WARNING and higher, are written emitted as php errors. That would naturally make them show up in stderrr and/or caught by PHPUnit.

I think that would be a good idea. I looked into doing that, but got very confused by LegacyLogger.

daniel added a comment.May 3 2018, 9:28 AM

For the record: a stop gap solution is merged, but it's a Volkswagen solution: DeferredUpdates changes behavior based on whether it's invoked during a unit test.

In any case, critical errors thrown in DeferredUpdates should not be invisible per default on 3rd party installations. This ticket should stay open until that problem is resolved.

Krinkle triaged this task as Normal priority.Jul 11 2018, 2:44 AM
Krinkle moved this task from Untriaged to Meta on the Wikimedia-production-error board.
Krinkle removed a project: MediaWiki-Logging.

In any case, critical errors thrown in DeferredUpdates should not be invisible per default on 3rd party installations. This ticket should stay open until that problem is resolved.

Just want to add a giant +1 to that (after spending a couple hours trying to track down errors which i assumed didn't exist because they didn't show up in my php error log despite E_DEPRECATED things from the same code showing up there).