From 77a397125fd1b901c3141cbfe7084a7534ff881b Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Sun, 24 May 2015 22:02:13 +0200 Subject: [PATCH] Convert MWExceptionHandler to use structured logging Replace wfDebugLog() calls in MWExceptionHandler with direct use of LoggerFactory and LoggerInterface. Logged exceptions are added to the log message context. LegacyLogger is also updated to append stack traces to any log event when $wgLogExceptionBacktrace is true and the PSR-3 recommendation of passing the exception as an 'exception' context item. Handling of context data in LegacyLogger is expanded to support arrays, exceptions and common object types. Bug: T88649 Change-Id: I71499d895582bdea033a2516c902e23e38084080 --- includes/debug/logger/LegacyLogger.php | 75 ++++++++- includes/exception/MWExceptionHandler.php | 142 ++++++++++++------ .../debug/logger/LegacyLoggerTest.php | 46 ++++++ 3 files changed, 215 insertions(+), 48 deletions(-) diff --git a/includes/debug/logger/LegacyLogger.php b/includes/debug/logger/LegacyLogger.php index 6bd6411872..80107908fc 100644 --- a/includes/debug/logger/LegacyLogger.php +++ b/includes/debug/logger/LegacyLogger.php @@ -22,6 +22,7 @@ namespace MediaWiki\Logger; use DateTimeZone; use MWDebug; +use MWExceptionHandler; use Psr\Log\AbstractLogger; use Psr\Log\LogLevel; use UDPTransport; @@ -167,7 +168,7 @@ class LegacyLogger extends AbstractLogger { * @return string */ public static function format( $channel, $message, $context ) { - global $wgDebugLogGroups; + global $wgDebugLogGroups, $wgLogExceptionBacktrace; if ( $channel === 'wfDebug' ) { $text = self::formatAsWfDebug( $channel, $message, $context ); @@ -215,6 +216,16 @@ class LegacyLogger extends AbstractLogger { $text = self::formatAsWfDebugLog( $channel, $message, $context ); } + // Append stacktrace of exception if available + if ( $wgLogExceptionBacktrace && + isset( $context['exception'] ) && + $context['exception'] instanceof Exception + ) { + $text .= MWExceptionHandler::getRedactedTraceAsString( + $context['exception']->getTraceAsString() + ) . "\n"; + } + return self::interpolate( $text, $context ); } @@ -301,7 +312,7 @@ class LegacyLogger extends AbstractLogger { if ( strpos( $message, '{' ) !== false ) { $replace = array(); foreach ( $context as $key => $val ) { - $replace['{' . $key . '}'] = $val; + $replace['{' . $key . '}'] = self::flatten( $val ); } $message = strtr( $message, $replace ); } @@ -309,6 +320,66 @@ class LegacyLogger extends AbstractLogger { } + /** + * Convert a logging context element to a string suitable for + * interpolation. + * + * @param mixed $item + * @return string + */ + protected static function flatten( $item ) { + if ( null === $item ) { + return '[Null]'; + } + + if ( is_bool( $item ) ) { + return $item ? 'true' : 'false'; + } + + if ( is_float( $item ) ) { + if ( is_infinite( $item ) ) { + return ( $item > 0 ? '' : '-' ) . 'INF'; + } + if ( is_nan( $item ) ) { + return 'NaN'; + } + return $data; + } + + if ( is_scalar( $item ) ) { + return (string) $item; + } + + if ( is_array( $item ) ) { + return '[Array(' . count( $item ) . ')]'; + } + + if ( $item instanceof \DateTime ) { + return $item->format( 'c' ); + } + + if ( $item instanceof \Exception ) { + return '[Exception ' . get_class( $item ) . '( ' . + $item->getFile() . ':' . $item->getLine() . ') ' . + $item->getMessage() . ']'; + } + + if ( is_object( $item ) ) { + if ( method_exists( $item, '__toString' ) ) { + return (string) $item; + } + + return '[Object ' . get_class( $item ) . ']'; + } + + if ( is_resource( $item ) ) { + return '[Resource ' . get_resource_type( $item ) . ']'; + } + + return '[Unknown ' . gettype( $item ) . ']'; + } + + /** * Select the appropriate log output destination for the given log event. * diff --git a/includes/exception/MWExceptionHandler.php b/includes/exception/MWExceptionHandler.php index 1681dc0895..3f25930f0d 100644 --- a/includes/exception/MWExceptionHandler.php +++ b/includes/exception/MWExceptionHandler.php @@ -18,6 +18,8 @@ * @file */ +use MediaWiki\Logger\LoggerFactory; + /** * Handler class for MWExceptions * @ingroup Exception @@ -86,7 +88,7 @@ class MWExceptionHandler { $message = "Exception encountered, of type \"" . get_class( $e ) . "\""; if ( $wgShowExceptionDetails ) { - $message .= "\n" . MWExceptionHandler::getLogMessage( $e ) . "\nBacktrace:\n" . + $message .= "\n" . self::getLogMessage( $e ) . "\nBacktrace:\n" . self::getRedactedTraceAsString( $e ) . "\n"; } @@ -127,10 +129,11 @@ class MWExceptionHandler { public static function rollbackMasterChangesAndLog( Exception $e ) { $factory = wfGetLBFactory(); if ( $factory->hasMasterChanges() ) { - wfDebugLog( 'Bug56269', + $logger = LoggerFactory::getInstance( 'Bug56269' ); + $logger->warning( 'Exception thrown with an uncommited database transaction: ' . - MWExceptionHandler::getLogMessage( $e ) . "\n" . - $e->getTraceAsString() + self::getLogMessage( $e ), + self::getLogContext( $e ) ); $factory->rollbackMasterChanges(); } @@ -276,9 +279,23 @@ TXT; * @return string */ public static function getRedactedTraceAsString( Exception $e ) { + return self::prettyPrintRedactedTrace( + self::getRedactedTrace( $e ) + ); + } + + /** + * Generate a string representation of a structured stack trace generated + * by getRedactedTrace(). + * + * @param array $trace + * @return string + * @since 1.26 + */ + public static function prettyPrintRedactedTrace( array $trace ) { $text = ''; - foreach ( self::getRedactedTrace( $e ) as $level => $frame ) { + foreach ( $trace as $level => $frame ) { if ( isset( $frame['file'] ) && isset( $frame['line'] ) ) { $text .= "#{$level} {$frame['file']}({$frame['line']}): "; } else { @@ -379,6 +396,64 @@ TXT; return "[$id] $url $type from line $line of $file: $message"; } + /** + * Get a PSR-3 log event context from an Exception. + * + * Creates a structured array containing information about the provided + * exception that can be used to augment a log message sent to a PSR-3 + * logger. + * + * @param Exception $e + * @return array + */ + public static function getLogContext( Exception $e ) { + return array( + 'exception' => $e, + ); + } + + /** + * Get a structured representation of an Exception. + * + * Returns an array of structured data (class, message, code, file, + * backtrace) derived from the given exception. The backtrace information + * will be redacted as per getRedactedTraceAsArray(). + * + * @param Exception $e + * @return array + * @since 1.26 + */ + public static function getStructuredExceptionData( Exception $e ) { + global $wgLogExceptionBacktrace; + $data = array( + 'id' => self::getLogId( $e ), + 'type' => get_class( $e ), + 'file' => $e->getFile(), + 'line' => $e->getLine(), + 'message' => $e->getMessage(), + 'code' => $e->getCode(), + 'url' => self::getURL() ?: null, + ); + + 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 ); + } + + return $data; + } + /** * Serialize an Exception object to JSON. * @@ -433,33 +508,8 @@ TXT; * @return string|false JSON string if successful; false upon failure */ public static function jsonSerializeException( Exception $e, $pretty = false, $escaping = 0 ) { - global $wgLogExceptionBacktrace; - - $exceptionData = array( - 'id' => self::getLogId( $e ), - 'type' => get_class( $e ), - 'file' => $e->getFile(), - 'line' => $e->getLine(), - 'message' => $e->getMessage(), - ); - - if ( $e instanceof ErrorException && ( error_reporting() & $e->getSeverity() ) === 0 ) { - // Flag surpressed errors - $exceptionData['suppressed'] = true; - } - - // Because MediaWiki is first and foremost a web application, we set a - // 'url' key unconditionally, but set it to null if the exception does - // not occur in the context of a web request, as a way of making that - // fact visible and explicit. - $exceptionData['url'] = self::getURL() ?: null; - - if ( $wgLogExceptionBacktrace ) { - // Argument values may not be serializable, so redact them. - $exceptionData['backtrace'] = self::getRedactedTrace( $e ); - } - - return FormatJson::encode( $exceptionData, $pretty, $escaping ); + $data = self::getStructuredExceptionData( $e ); + return FormatJson::encode( $data, $pretty, $escaping ); } /** @@ -475,16 +525,16 @@ TXT; global $wgLogExceptionBacktrace; if ( !( $e instanceof MWException ) || $e->isLoggable() ) { - $log = self::getLogMessage( $e ); - if ( $wgLogExceptionBacktrace ) { - wfDebugLog( 'exception', $log . "\n" . $e->getTraceAsString() ); - } else { - wfDebugLog( 'exception', $log ); - } + $logger = LoggerFactory::getInstance( 'exception' ); + $logger->error( + self::getLogMessage( $e ), + self::getLogContext( $e ) + ); $json = self::jsonSerializeException( $e, false, FormatJson::ALL_OK ); if ( $json !== false ) { - wfDebugLog( 'exception-json', $json, 'private' ); + $logger = LoggerFactory::getInstance( 'exception-json' ); + $logger->error( $json, array( 'private' => true ) ); } Hooks::run( 'LogException', array( $e, false ) ); @@ -505,18 +555,18 @@ TXT; // Filter out unwanted errors manually (e.g. when MediaWiki\suppressWarnings is active). $suppressed = ( error_reporting() & $e->getSeverity() ) === 0; if ( !$suppressed ) { - $log = self::getLogMessage( $e ); - if ( $wgLogExceptionBacktrace ) { - wfDebugLog( $channel, $log . "\n" . $e->getTraceAsString() ); - } else { - wfDebugLog( $channel, $log ); - } + $logger = LoggerFactory::getInstance( $channel ); + $logger->error( + self::getLogMessage( $e ), + self::getLogContext( $e ) + ); } // Include all errors in the json log (surpressed errors will be flagged) $json = self::jsonSerializeException( $e, false, FormatJson::ALL_OK ); if ( $json !== false ) { - wfDebugLog( "$channel-json", $json, 'private' ); + $logger = LoggerFactory::getInstance( "{$channel}-json" ); + $logger->error( $json, array( 'private' => true ) ); } Hooks::run( 'LogException', array( $e, $suppressed ) ); diff --git a/tests/phpunit/includes/debug/logger/LegacyLoggerTest.php b/tests/phpunit/includes/debug/logger/LegacyLoggerTest.php index 415fa0451b..c63ce66d49 100644 --- a/tests/phpunit/includes/debug/logger/LegacyLoggerTest.php +++ b/tests/phpunit/includes/debug/logger/LegacyLoggerTest.php @@ -35,6 +35,8 @@ class LegacyLoggerTest extends MediaWikiTestCase { } public function provideInterpolate() { + $e = new \Exception( 'boom!' ); + $d = new \DateTime(); return array( array( 'no-op', @@ -68,6 +70,50 @@ class LegacyLoggerTest extends MediaWikiTestCase { ), '{ not interpolated }', ), + array( + '{null}', + array( + 'null' => null, + ), + '[Null]', + ), + array( + '{bool}', + array( + 'bool' => true, + ), + 'true', + ), + array( + '{array}', + array( + 'array' => array( 1, 2, 3 ), + ), + '[Array(3)]', + ), + array( + '{exception}', + array( + 'exception' => $e, + ), + '[Exception ' . get_class( $e ) . '( ' . + $e->getFile() . ':' . $e->getLine() . ') ' . + $e->getMessage() . ']', + ), + array( + '{datetime}', + array( + 'datetime' => $d, + ), + $d->format( 'c' ), + ), + array( + '{object}', + array( + 'object' => new \stdClass, + ), + '[Object stdClass]', + ), ); } -- 2.20.1