MWExceptionHandler.php

Go to the documentation of this file.

<?php
use MediaWiki\Logger\LoggerFactory;
use MediaWiki\MediaWikiServices;
use Psr\Log\LogLevel;
use Wikimedia\Rdbms\DBError;

class MWExceptionHandler {
    const CAUGHT_BY_HANDLER = 'mwe_handler'; // error reported by this exception handler
    const CAUGHT_BY_OTHER = 'other'; // error reported by direct logException() call

    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,

        // HHVM's FATAL_ERROR constant
        16777217,
    ];
    protected static $handledFatalCallback = false;

    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 (on PHP 7+), 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 TypeErorr, devision by zero, etc.)
        set_exception_handler( 'MWExceptionHandler::handleUncaughtException' );

        // This catches:
        // * Non-fatal 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.
        // * Fatal errors (on HHVM in PHP5 mode) where PHP 7 would throw Throwable.
        set_error_handler( 'MWExceptionHandler::handleError' );

        // This catches:
        // * Fatal error for which no Throwable is thrown (PHP 7), and no Error emitted (HHVM).
        //   This includes 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( $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 ( Exception $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 rollbackMasterChangesAndLog( $e ) {
        $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()->rollbackMasterChanges( __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, self::CAUGHT_BY_HANDLER );
            }
        }

        self::logException( $e, self::CAUGHT_BY_HANDLER );
    }

    public static function handleUncaughtException( $e ) {
        self::handleException( $e );

        // Make sure we don't claim success on exit for CLI scripts (T177414)
        if ( wfIsCLI() ) {
            register_shutdown_function(
                function () {
                    exit( 255 );
                }
            );
        }
    }

    public static function handleException( $e ) {
        self::rollbackMasterChangesAndLog( $e );
        self::report( $e );
    }

    public static function handleError(
        $level, $message, $file = null, $line = null
    ) {
        global $wgPropagateErrors;

        if ( in_array( $level, self::$fatalErrorTypes ) ) {
            return self::handleFatalError( ...func_get_args() );
        }

        // 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:
                $levelName = 'Warning';
                $severity = LogLevel::ERROR;
                break;
            case E_NOTICE:
                $levelName = 'Notice';
                $severity = LogLevel::ERROR;
                break;
            case E_USER_NOTICE:
                // Used by wfWarn(), MWDebug::warning()
                $levelName = 'Notice';
                $severity = LogLevel::WARNING;
                break;
            case E_USER_WARNING:
                // Used by wfWarn(), MWDebug::warning()
                $levelName = 'Warning';
                $severity = LogLevel::WARNING;
                break;
            case E_STRICT:
                $levelName = 'Strict Standards';
                $severity = LogLevel::WARNING;
                break;
            case E_DEPRECATED:
            case E_USER_DEPRECATED:
                $levelName = 'Deprecated';
                $severity = LogLevel::WARNING;
                break;
            default:
                $levelName = 'Unknown error';
                $severity = LogLevel::ERROR;
                break;
        }

        $e = new ErrorException( "PHP $levelName: $message", 0, $level, $file, $line );
        self::logError( $e, 'error', $severity );

        // 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(
        $level = null, $message = null, $file = null, $line = null,
        $context = null, $trace = null
    ) {
        // Free reserved memory so that we have space to process OOM
        // errors
        self::$reservedMemory = null;

        if ( $level === null ) {
            // Called as a shutdown handler, get data from error_get_last()
            if ( static::$handledFatalCallback ) {
                // Already called once (probably as an error handler callback
                // under HHVM) so don't log again.
                return false;
            }

            $lastError = error_get_last();
            if ( $lastError !== null ) {
                $level = $lastError['type'];
                $message = $lastError['message'];
                $file = $lastError['file'];
                $line = $lastError['line'];
            } else {
                $level = 0;
                $message = '';
            }
        }

        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 = [
            '[{exception_id}] {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
        // HHVM: Class undefined: foo
        // PHP5: Class 'foo' not found
        if ( preg_match( "/Class (undefined: \w+|'\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
        }

        // We can't just create an exception and log it as it is likely that
        // the interpreter has unwound the stack already. If that is true the
        // stacktrace we would get would be functionally empty. If however we
        // have been called as an error handler callback *and* HHVM is in use
        // we will have been provided with a useful stacktrace that we can
        // log.
        $trace = $trace ?: debug_backtrace();
        $logger = LoggerFactory::getInstance( 'fatal' );
        $logger->error( $msg, [
            'fatal_exception' => [
                'class' => ErrorException::class,
                'message' => "PHP Fatal Error: {$message}",
                'code' => $level,
                'file' => $file,
                'line' => $line,
                'trace' => self::prettyPrintTrace( self::redactTrace( $trace ) ),
            ],
            'exception_id' => WebRequest::getRequestId(),
            'exception_url' => $url,
            'caught_by' => self::CAUGHT_BY_HANDLER
        ] );

        // Remember call so we don't double process via HHVM's fatal
        // notifications and the shutdown hook behavior
        static::$handledFatalCallback = true;
        return false;
    }

    public static function getRedactedTraceAsString( $e ) {
        return 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 via call_user_func
                // (T57634) This matches behaviour of
                // Exception::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 = $level + 1;
        $text .= "{$pad}#{$level} {main}";

        return $text;
    }

    public static function getRedactedTrace( $e ) {
        return static::redactTrace( $e->getTrace() );
    }

    public static function redactTrace( array $trace ) {
        return array_map( function ( $frame ) {
            if ( isset( $frame['args'] ) ) {
                $frame['args'] = array_map( 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( $e ) {
        $id = WebRequest::getRequestId();
        $type = get_class( $e );
        $file = $e->getFile();
        $line = $e->getLine();
        $message = $e->getMessage();
        $url = self::getURL() ?: '[no req]';

        return "[$id] $url   $type from line $line of $file: $message";
    }

    public static function getLogNormalMessage( $e ) {
        $type = get_class( $e );
        $file = $e->getFile();
        $line = $e->getLine();
        $message = $e->getMessage();

        return "[{exception_id}] {exception_url}   $type from line $line of $file: $message";
    }

    public static function getPublicLogMessage( $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( $e, $catcher = self::CAUGHT_BY_OTHER ) {
        return [
            'exception' => $e,
            'exception_id' => WebRequest::getRequestId(),
            'exception_url' => self::getURL() ?: '[no req]',
            'caught_by' => $catcher
        ];
    }

    public static function getStructuredExceptionData( $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(
        $e, $pretty = false, $escaping = 0, $catcher = self::CAUGHT_BY_OTHER
    ) {
        return FormatJson::encode(
            self::getStructuredExceptionData( $e, $catcher ),
            $pretty,
            $escaping
        );
    }

    public static function logException( $e, $catcher = self::CAUGHT_BY_OTHER ) {
        if ( !( $e instanceof MWException ) || $e->isLoggable() ) {
            $logger = LoggerFactory::getInstance( 'exception' );
            $logger->error(
                self::getLogNormalMessage( $e ),
                self::getLogContext( $e, $catcher )
            );

            $json = self::jsonSerializeException( $e, false, FormatJson::ALL_OK, $catcher );
            if ( $json !== false ) {
                $logger = LoggerFactory::getInstance( 'exception-json' );
                $logger->error( $json, [ 'private' => true ] );
            }

            Hooks::run( 'LogException', [ $e, false ] );
        }
    }

    protected static function logError(
        ErrorException $e, $channel, $level = LogLevel::ERROR
    ) {
        $catcher = self::CAUGHT_BY_HANDLER;
        // 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" );
            $logger->log( $level, $json, [ 'private' => true ] );
        }

        Hooks::run( 'LogException', [ $e, $suppressed ] );
    }
}