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
This commit is contained in:
Bryan Davis
parent
2fff57e8a1
commit
77a397125f
3 changed files with 215 additions and 48 deletions
|
|
@ -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.
|
||||
*
|
||||
|
|
|
|||
|
|
@ -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 ) );
|
||||
|
|
|
|||
|
|
@ -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]',
|
||||
),
|
||||
);
|
||||
}
|
||||
|
||||
|
|
|
|||
Loading…
Reference in a new issue