MWExceptionHandler.php

Go to the documentation of this file.

<?php
use MediaWiki\Logger\LoggerFactory;
use MediaWiki\MediaWikiServices;
use Psr\Log\LogLevel;
use Wikimedia\NormalizedException\INormalizedException;
use Wikimedia\Rdbms\DBError;
use Wikimedia\Rdbms\DBQueryError;
 
class MWExceptionHandler {
    public const CAUGHT_BY_HANDLER = 'mwe_handler';
    public const CAUGHT_BY_ENTRYPOINT = 'entrypoint';
    public const CAUGHT_BY_OTHER = 'other';
 
    protected static $reservedMemory;
 
    protected static $fatalErrorTypes = [
        E_ERROR,
        E_PARSE,
        E_CORE_ERROR,
        E_COMPILE_ERROR,
        E_USER_ERROR,
 
        // E.g. "Catchable fatal error: Argument X must be Y, null given"
        E_RECOVERABLE_ERROR,
    ];
 
    public static function installHandler() {
        // This catches:
        // * Exception objects that were explicitly thrown but not
        //   caught anywhere in the application. This is rare given those
        //   would normally be caught at a high-level like MediaWiki::run (index.php),
        //   api.php, or ResourceLoader::respond (load.php). These high-level
        //   catch clauses would then call MWExceptionHandler::logException
        //   or MWExceptionHandler::handleException.
        //   If they are not caught, then they are handled here.
        // * Error objects for issues that would historically
        //   cause fatal errors but may now be caught as Throwable (not Exception).
        //   Same as previous case, but more common to bubble to here instead of
        //   caught locally because they tend to not be safe to recover from.
        //   (e.g. argument TypeError, division by zero, etc.)
        set_exception_handler( 'MWExceptionHandler::handleUncaughtException' );
 
        // This catches recoverable errors (e.g. PHP Notice, PHP Warning, PHP Error) that do not
        // interrupt execution in any way. We log these in the background and then continue execution.
        set_error_handler( 'MWExceptionHandler::handleError' );
 
        // This catches fatal errors for which no Throwable is thrown,
        // including Out-Of-Memory and Timeout fatals.
        // Reserve 16k of memory so we can report OOM fatals.
        self::$reservedMemory = str_repeat( ' ', 16384 );
        register_shutdown_function( 'MWExceptionHandler::handleFatalError' );
    }
 
    protected static function report( Throwable $e ) {
        try {
            // Try and show the exception prettily, with the normal skin infrastructure
            if ( $e instanceof MWException ) {
                // Delegate to MWException until all subclasses are handled by
                // MWExceptionRenderer and MWException::report() has been
                // removed.
                $e->report();
            } else {
                MWExceptionRenderer::output( $e, MWExceptionRenderer::AS_PRETTY );
            }
        } catch ( Throwable $e2 ) {
            // Exception occurred from within exception handler
            // Show a simpler message for the original exception,
            // don't try to invoke report()
            MWExceptionRenderer::output( $e, MWExceptionRenderer::AS_RAW, $e2 );
        }
    }
 
    public static function rollbackPrimaryChangesAndLog(
        Throwable $e,
        $catcher = self::CAUGHT_BY_OTHER
    ) {
        $services = MediaWikiServices::getInstance();
        if ( !$services->isServiceDisabled( 'DBLoadBalancerFactory' ) ) {
            // Rollback DBs to avoid transaction notices. This might fail
            // to rollback some databases due to connection issues or exceptions.
            // However, any sane DB driver will rollback implicitly anyway.
            try {
                $services->getDBLoadBalancerFactory()->rollbackPrimaryChanges( __METHOD__ );
            } catch ( DBError $e2 ) {
                // If the DB is unreacheable, rollback() will throw an error
                // and the error report() method might need messages from the DB,
                // which would result in an exception loop. PHP may escalate such
                // errors to "Exception thrown without a stack frame" fatals, but
                // it's better to be explicit here.
                self::logException( $e2, $catcher );
            }
        }
 
        self::logException( $e, $catcher );
    }
 
    public static function rollbackMasterChangesAndLog(
        Throwable $e,
        $catcher = self::CAUGHT_BY_OTHER
    ) {
        wfDeprecated( __METHOD__, '1.37' );
        self::rollbackPrimaryChangesAndLog( $e, $catcher );
    }
 
    public static function handleUncaughtException( Throwable $e ) {
        self::handleException( $e, self::CAUGHT_BY_HANDLER );
 
        // Make sure we don't claim success on exit for CLI scripts (T177414)
        if ( wfIsCLI() ) {
            register_shutdown_function(
                static function () {
                    exit( 255 );
                }
            );
        }
    }
 
    public static function handleException( Throwable $e, $catcher = self::CAUGHT_BY_OTHER ) {
        self::rollbackPrimaryChangesAndLog( $e, $catcher );
        self::report( $e );
    }
 
    public static function handleError(
        $level,
        $message,
        $file = null,
        $line = null
    ) {
        global $wgPropagateErrors;
 
        // Map PHP error constant to a PSR-3 severity level.
        // Avoid use of "DEBUG" or "INFO" levels, unless the
        // error should evade error monitoring and alerts.
        //
        // To decide the log level, ask yourself: "Has the
        // program's behaviour diverged from what the written
        // code expected?"
        //
        // For example, use of a deprecated method or violating a strict standard
        // has no impact on functional behaviour (Warning). On the other hand,
        // accessing an undefined variable makes behaviour diverge from what the
        // author intended/expected. PHP recovers from an undefined variables by
        // yielding null and continuing execution, but it remains a change in
        // behaviour given the null was not part of the code and is likely not
        // accounted for.
        switch ( $level ) {
            case E_WARNING:
            case E_CORE_WARNING:
            case E_COMPILE_WARNING:
                $prefix = 'PHP Warning: ';
                $severity = LogLevel::ERROR;
                break;
            case E_NOTICE:
                $prefix = 'PHP Notice: ';
                $severity = LogLevel::ERROR;
                break;
            case E_USER_NOTICE:
                // Used by wfWarn(), MWDebug::warning()
                $prefix = 'PHP Notice: ';
                $severity = LogLevel::WARNING;
                break;
            case E_USER_WARNING:
                // Used by wfWarn(), MWDebug::warning()
                $prefix = 'PHP Warning: ';
                $severity = LogLevel::WARNING;
                break;
            case E_STRICT:
                $prefix = 'PHP Strict Standards: ';
                $severity = LogLevel::WARNING;
                break;
            case E_DEPRECATED:
                $prefix = 'PHP Deprecated: ';
                $severity = LogLevel::WARNING;
                break;
            case E_USER_DEPRECATED:
                $prefix = 'PHP Deprecated: ';
                $severity = LogLevel::WARNING;
                $real = MWDebug::parseCallerDescription( $message );
                if ( $real ) {
                    // Used by wfDeprecated(), MWDebug::deprecated()
                    // Apply caller offset from wfDeprecated() to the native error.
                    // This makes errors easier to aggregate and find in e.g. Kibana.
                    $file = $real['file'];
                    $line = $real['line'];
                    $message = $real['message'];
                }
                break;
            default:
                $prefix = 'PHP Unknown error: ';
                $severity = LogLevel::ERROR;
                break;
        }
 
        $e = new ErrorException( $prefix . $message, 0, $level, $file, $line );
        self::logError( $e, 'error', $severity, self::CAUGHT_BY_HANDLER );
 
        // If $wgPropagateErrors is true return false so PHP shows/logs the error normally.
        // Ignore $wgPropagateErrors if track_errors is set
        // (which means someone is counting on regular PHP error handling behavior).
        return !( $wgPropagateErrors || ini_get( 'track_errors' ) );
    }
 
    public static function handleFatalError() {
        // Free reserved memory so that we have space to process OOM
        // errors
        self::$reservedMemory = null;
 
        $lastError = error_get_last();
        if ( $lastError === null ) {
            return false;
        }
 
        $level = $lastError['type'];
        $message = $lastError['message'];
        $file = $lastError['file'];
        $line = $lastError['line'];
 
        if ( !in_array( $level, self::$fatalErrorTypes ) ) {
            // Only interested in fatal errors, others should have been
            // handled by MWExceptionHandler::handleError
            return false;
        }
 
        $url = WebRequest::getGlobalRequestURL();
        $msgParts = [
            '[{reqId}] {exception_url}   PHP Fatal Error',
            ( $line || $file ) ? ' from' : '',
            $line ? " line $line" : '',
            ( $line && $file ) ? ' of' : '',
            $file ? " $file" : '',
            ": $message",
        ];
        $msg = implode( '', $msgParts );
 
        // Look at message to see if this is a class not found failure (Class 'foo' not found)
        if ( preg_match( "/Class '\w+' not found/", $message ) ) {
            // phpcs:disable Generic.Files.LineLength
            $msg = <<<TXT
{$msg}
 
MediaWiki or an installed extension requires this class but it is not embedded directly in MediaWiki's git repository and must be installed separately by the end user.
 
Please see <a href="https://www.mediawiki.org/wiki/Download_from_Git#Fetch_external_libraries">mediawiki.org</a> for help on installing the required components.
TXT;
            // phpcs:enable
        }
 
        $e = new ErrorException( "PHP Fatal Error: {$message}", 0, $level, $file, $line );
        $logger = LoggerFactory::getInstance( 'exception' );
        $logger->error( $msg, self::getLogContext( $e, self::CAUGHT_BY_HANDLER ) );
 
        return false;
    }
 
    public static function getRedactedTraceAsString( Throwable $e ) {
        $from = 'from ' . $e->getFile() . '(' . $e->getLine() . ')' . "\n";
        return $from . self::prettyPrintTrace( self::getRedactedTrace( $e ) );
    }
 
    public static function prettyPrintTrace( array $trace, $pad = '' ) {
        $text = '';
 
        $level = 0;
        foreach ( $trace as $level => $frame ) {
            if ( isset( $frame['file'] ) && isset( $frame['line'] ) ) {
                $text .= "{$pad}#{$level} {$frame['file']}({$frame['line']}): ";
            } else {
                // 'file' and 'line' are unset for calls from C code
                // (T57634) This matches behaviour of
                // Throwable::getTraceAsString to instead display "[internal
                // function]".
                $text .= "{$pad}#{$level} [internal function]: ";
            }
 
            if ( isset( $frame['class'] ) && isset( $frame['type'] ) && isset( $frame['function'] ) ) {
                $text .= $frame['class'] . $frame['type'] . $frame['function'];
            } elseif ( isset( $frame['function'] ) ) {
                $text .= $frame['function'];
            } else {
                $text .= 'NO_FUNCTION_GIVEN';
            }
 
            if ( isset( $frame['args'] ) ) {
                $text .= '(' . implode( ', ', $frame['args'] ) . ")\n";
            } else {
                $text .= "()\n";
            }
        }
 
        $level++;
        $text .= "{$pad}#{$level} {main}";
 
        return $text;
    }
 
    public static function getRedactedTrace( Throwable $e ) {
        return static::redactTrace( $e->getTrace() );
    }
 
    public static function redactTrace( array $trace ) {
        return array_map( static function ( $frame ) {
            if ( isset( $frame['args'] ) ) {
                $frame['args'] = array_map( static function ( $arg ) {
                    return is_object( $arg ) ? get_class( $arg ) : gettype( $arg );
                }, $frame['args'] );
            }
            return $frame;
        }, $trace );
    }
 
    public static function getURL() {
        global $wgRequest;
        if ( !isset( $wgRequest ) || $wgRequest instanceof FauxRequest ) {
            return false;
        }
        return $wgRequest->getRequestURL();
    }
 
    public static function getLogMessage( Throwable $e ) {
        $id = WebRequest::getRequestId();
        $type = get_class( $e );
        $message = $e->getMessage();
        $url = self::getURL() ?: '[no req]';
 
        if ( $e instanceof DBQueryError ) {
            $message = "A database query error has occurred. Did you forget to run"
                . " your application's database schema updater after upgrading"
                . " or after adding a new extension?\n\nPlease see"
                . " https://www.mediawiki.org/wiki/Special:MyLanguage/Manual:Upgrading and"
                . " https://www.mediawiki.org/wiki/Special:MyLanguage/Manual:How_to_debug"
                . " for more information.\n\n"
                . $message;
        }
 
        return "[$id] $url   $type: $message";
    }
 
    public static function getLogNormalMessage( Throwable $e ) {
        if ( $e instanceof INormalizedException ) {
            $message = $e->getNormalizedMessage();
        } else {
            $message = $e->getMessage();
        }
        if ( !$e instanceof ErrorException ) {
            // ErrorException is something we use internally to represent
            // PHP errors (runtime warnings that aren't thrown or caught),
            // don't bother putting it in the logs. Let the log message
            // lead with "PHP Warning: " instead (see ::handleError).
            $message = get_class( $e ) . ": $message";
        }
 
        return "[{reqId}] {exception_url}   $message";
    }
 
    public static function getPublicLogMessage( Throwable $e ) {
        $reqId = WebRequest::getRequestId();
        $type = get_class( $e );
        return '[' . $reqId . '] '
            . gmdate( 'Y-m-d H:i:s' ) . ': '
            . 'Fatal exception of type "' . $type . '"';
    }
 
    public static function getLogContext( Throwable $e, $catcher = self::CAUGHT_BY_OTHER ) {
        $context = [
            'exception' => $e,
            'exception_url' => self::getURL() ?: '[no req]',
            // The reqId context key use the same familiar name and value as the top-level field
            // provided by LogstashFormatter. However, formatters are configurable at run-time,
            // and their top-level fields are logically separate from context keys and cannot be,
            // substituted in a message, hence set explicitly here. For WMF users, these may feel,
            // like the same thing due to Monolog V0 handling, which transmits "fields" and "context",
            // in the same JSON object (after message formatting).
            'reqId' => WebRequest::getRequestId(),
            'caught_by' => $catcher
        ];
        if ( $e instanceof INormalizedException ) {
            $context += $e->getMessageContext();
        }
        return $context;
    }
 
    public static function getStructuredExceptionData(
        Throwable $e,
        $catcher = self::CAUGHT_BY_OTHER
    ) {
        global $wgLogExceptionBacktrace;
 
        $data = [
            'id' => WebRequest::getRequestId(),
            'type' => get_class( $e ),
            'file' => $e->getFile(),
            'line' => $e->getLine(),
            'message' => $e->getMessage(),
            'code' => $e->getCode(),
            'url' => self::getURL() ?: null,
            'caught_by' => $catcher
        ];
 
        if ( $e instanceof ErrorException &&
            ( error_reporting() & $e->getSeverity() ) === 0
        ) {
            // Flag surpressed errors
            $data['suppressed'] = true;
        }
 
        if ( $wgLogExceptionBacktrace ) {
            $data['backtrace'] = self::getRedactedTrace( $e );
        }
 
        $previous = $e->getPrevious();
        if ( $previous !== null ) {
            $data['previous'] = self::getStructuredExceptionData( $previous, $catcher );
        }
 
        return $data;
    }
 
    public static function jsonSerializeException(
        Throwable $e,
        $pretty = false,
        $escaping = 0,
        $catcher = self::CAUGHT_BY_OTHER
    ) {
        return FormatJson::encode(
            self::getStructuredExceptionData( $e, $catcher ),
            $pretty,
            $escaping
        );
    }
 
    public static function logException(
        Throwable $e,
        $catcher = self::CAUGHT_BY_OTHER,
        $extraData = []
    ) {
        if ( !( $e instanceof MWException ) || $e->isLoggable() ) {
            $logger = LoggerFactory::getInstance( 'exception' );
            $context = self::getLogContext( $e, $catcher );
            if ( $extraData ) {
                $context['extraData'] = $extraData;
            }
            $logger->error(
                self::getLogNormalMessage( $e ),
                $context
            );
 
            $json = self::jsonSerializeException( $e, false, FormatJson::ALL_OK, $catcher );
            if ( $json !== false ) {
                $logger = LoggerFactory::getInstance( 'exception-json' );
                $logger->error( $json, [ 'private' => true ] );
            }
 
            Hooks::runner()->onLogException( $e, false );
        }
    }
 
    private static function logError(
        ErrorException $e,
        $channel,
        $level,
        $catcher
    ) {
        // The set_error_handler callback is independent from error_reporting.
        // Filter out unwanted errors manually (e.g. when
        // Wikimedia\suppressWarnings is active).
        $suppressed = ( error_reporting() & $e->getSeverity() ) === 0;
        if ( !$suppressed ) {
            $logger = LoggerFactory::getInstance( $channel );
            $logger->log(
                $level,
                self::getLogNormalMessage( $e ),
                self::getLogContext( $e, $catcher )
            );
        }
 
        // Include all errors in the json log (surpressed errors will be flagged)
        $json = self::jsonSerializeException( $e, false, FormatJson::ALL_OK, $catcher );
        if ( $json !== false ) {
            $logger = LoggerFactory::getInstance( "{$channel}-json" );
            // Unlike the 'error' channel, the 'error-json' channel is unfiltered,
            // and emits messages even if wikimedia/at-ease was used to suppress the
            // error. To avoid clobbering Logstash dashboards with these, make sure
            // those have their level casted to DEBUG so that they are excluded by
            // level-based filteres automatically instead of requiring a dedicated filter
            // for this channel. To be improved: T193472.
            $unfilteredLevel = $suppressed ? LogLevel::DEBUG : $level;
            $logger->log( $unfilteredLevel, $json, [ 'private' => true ] );
        }
 
        Hooks::runner()->onLogException( $e, $suppressed );
    }
}