Convert MWExceptionHandler to use structured logging
authorBryan Davis <bd808@wikimedia.org>
Sun, 24 May 2015 20:02:13 +0000 (22:02 +0200)
committerBryan Davis <bd808@wikimedia.org>
Thu, 16 Jul 2015 02:03:46 +0000 (21:03 -0500)
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
includes/exception/MWExceptionHandler.php
tests/phpunit/includes/debug/logger/LegacyLoggerTest.php

index 6bd6411..8010790 100644 (file)
@@ -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.
         *
index 1681dc0..3f25930 100644 (file)
@@ -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 ) );
index 415fa04..c63ce66 100644 (file)
@@ -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]',
+                       ),
                );
        }