Enhance debug log output for stacktraces

Make MediaWiki\Logger\LegacyLogger and
MediaWiki\Logger\Monolog\LineFormatter better at outputting stacktrace
information and provide support for 'exception' data in the logging
context that is a structured array in addition to the default Exception
object support. This works with MWExceptionHandler::handleFatalError
generated data that is provided by an HHVM interpreter and cannot be
delivered as an Exception class.

With this patch, a good value for LineFormatter's format would be:
"%datetime% %extra.host% %extra.wiki% %channel% %level_name%: %message%
%context% %exception%\n"

Bug: T89169
Bug: T107440
Change-Id: Ida01ed51c573e1654346e716723e543a1be63090

diff --git a/includes/debug/logger/LegacyLogger.php b/includes/debug/logger/LegacyLogger.php
index b6439b8..0f4c648 100644 (file)
--- a/includes/debug/logger/LegacyLogger.php
+++ b/includes/debug/logger/LegacyLogger.php
@@ -21,6 +21,7 @@
 namespace MediaWiki\Logger;
 
 use DateTimeZone;
+use Exception;
 use MWDebug;
 use MWExceptionHandler;
 use Psr\Log\AbstractLogger;
@@ -217,13 +218,22 @@ class LegacyLogger extends AbstractLogger {
                }
 
                // Append stacktrace of exception if available
-               if ( $wgLogExceptionBacktrace &&
-                       isset( $context['exception'] ) &&
-                       $context['exception'] instanceof Exception
-               ) {
-                       $text .= MWExceptionHandler::getRedactedTraceAsString(
-                               $context['exception']
-                       ) . "\n";
+               if ( $wgLogExceptionBacktrace && isset( $context['exception'] ) ) {
+                       $e = $context['exception'];
+                       $backtrace = false;
+
+                       if ( $e instanceof Exception ) {
+                               $backtrace = MWExceptionHandler::getRedactedTrace( $e );
+
+                       } elseif ( is_array( $e ) && isset( $e['trace'] ) ) {
+                               // Exception has already been unpacked as structured data
+                               $backtrace = $e['trace'];
+                       }
+
+                       if ( $backtrace ) {
+                               $text .= MWExceptionHandler::prettyPrintTrace( $backtrace ) .
+                                       "\n";
+                       }
                }
 
                return self::interpolate( $text, $context );
@@ -358,7 +368,7 @@ class LegacyLogger extends AbstractLogger {
                        return $item->format( 'c' );
                }
 
-               if ( $item instanceof \Exception ) {
+               if ( $item instanceof Exception ) {
                        return '[Exception ' . get_class( $item ) . '( ' .
                                $item->getFile() . ':' . $item->getLine() . ') ' .
                                $item->getMessage() . ']';

diff --git a/includes/debug/logger/monolog/LineFormatter.php b/includes/debug/logger/monolog/LineFormatter.php
index e593d63..2ba7a53 100644 (file)
--- a/includes/debug/logger/monolog/LineFormatter.php
+++ b/includes/debug/logger/monolog/LineFormatter.php
@@ -27,10 +27,14 @@ use MWExceptionHandler;
 /**
  * Formats incoming records into a one-line string.
  *
+ * An 'exeception' in the log record's context will be treated specially.
+ * It will be output for an '%exception%' placeholder in the format and
+ * excluded from '%context%' output if the '%exception%' placeholder is
+ * present.
+ *
  * Exceptions that are logged with this formatter will optional have their
- * stack traces appended. If that is done,
- * MWExceptionHandler::getRedactedTraceAsString() will be used to redact the
- * trace information.
+ * stack traces appended. If that is done, MWExceptionHandler::redactedTrace()
+ * will be used to redact the trace information.
  *
  * @since 1.26
  * @author Bryan Davis <bd808@wikimedia.org>
@@ -57,6 +61,40 @@ class LineFormatter extends MonologLineFormatter {
        }
 
 
+       /**
+        * {@inheritdoc}
+        */
+       public function format( array $record ) {
+               // Drop the 'private' flag from the context
+               unset( $record['context']['private'] );
+
+               // Handle exceptions specially: pretty format and remove from context
+               // Will be output for a '%exception%' placeholder in format
+               $prettyException = '';
+               if ( isset( $record['context']['exception'] ) &&
+                       strpos( $this->format, '%exception%' ) !== false
+               ) {
+                       $e = $record['context']['exception'];
+                       unset( $record['context']['exception'] );
+
+                       if ( $e instanceof Exception ) {
+                               $prettyException = $this->normalizeException( $e );
+                       } elseif ( is_array( $e ) ) {
+                               $prettyException = $this->normalizeExceptionArray( $e );
+                       } else {
+                               $prettyException = $this->stringify( $e );
+                       }
+               }
+
+               $output = parent::format( $record );
+
+               if ( strpos( $output, '%exception%' ) !== false ) {
+                       $output = str_replace( '%exception%', $prettyException, $output );
+               }
+               return $output;
+       }
+
+
        /**
         * Convert an Exception to a string.
         *
@@ -64,24 +102,76 @@ class LineFormatter extends MonologLineFormatter {
         * @return string
         */
        protected function normalizeException( Exception $e ) {
-               $str = '[Exception ' . get_class( $e ) . '] (' .
-                       $e->getFile() . ':' . $e->getLine() . ') ' .
-                       $e->getMessage();
+               return $this->normalizeExceptionArray( $this->exceptionAsArray( $e ) );
+       }
+
+
+       /**
+        * Convert an exception to an array of structured data.
+        *
+        * @param Exception $e
+        * @return array
+        */
+       protected function exceptionAsArray( Exception $e ) {
+               $out = array(
+                       'class' => get_class( $e ),
+                       'message' => $e->getMessage(),
+                       'code' => $e->getCode(),
+                       'file' => $e->getFile(),
+                       'line' => $e->getLine(),
+                       'trace' => MWExceptionHandler::redactTrace( $e->getTrace() ),
+               );
 
                $prev = $e->getPrevious();
-               while ( $prev ) {
-                       $str .= ', [Exception ' . get_class( $prev ) . '] (' .
-                               $prev->getFile() . ':' . $prev->getLine() . ') ' .
-                               $prev->getMessage();
-                       $prev = $prev->getPrevious();
+               if ( $prev ) {
+                       $out['previous'] = $this->exceptionAsArray( $prev );
                }
 
-               if ( $this->includeStacktraces ) {
-                       $str .= "\n[stacktrace]\n" .
-                               MWExceptionHandler::getRedactedTraceAsString( $e ) .
-                               "\n";
+               return $out;
+       }
+
+
+       /**
+        * Convert an array of Exception data to a string.
+        *
+        * @param array $e
+        * @return string
+        */
+       protected function normalizeExceptionArray( array $e ) {
+               $defaults = array(
+                       'class' => 'Unknown',
+                       'file' => 'unknown',
+                       'line' => null,
+                       'message' => 'unknown',
+                       'trace' => array(),
+               );
+               $e = array_merge( $defaults, $e );
+
+               $str = "\n[Exception {$e['class']}] (" .
+                       "{$e['file']}:{$e['line']}) {$e['message']}";
+
+               if ( $this->includeStacktraces && $e['trace'] ) {
+                       $str .= "\n" .
+                               MWExceptionHandler::prettyPrintTrace( $e['trace'], '  ' );
                }
 
+               if ( isset( $e['previous'] ) ) {
+                       $prev = $e['previous'];
+                       while ( $prev ) {
+                               $prev = array_merge( $defaults, $prev );
+                               $str .= "\nCaused by: [Exception {$prev['class']}] (" .
+                                       "{$prev['file']}:{$prev['line']}) {$prev['message']}";
+
+                               if ( $this->includeStacktraces && $prev['trace'] ) {
+                                       $str .= "\n" .
+                                               MWExceptionHandler::prettyPrintTrace(
+                                                       $prev['trace'], '  '
+                                               );
+                               }
+
+                               $prev = isset( $prev['previous'] ) ? $prev['previous'] : null;
+                       }
+               }
                return $str;
        }
 }

diff --git a/includes/exception/MWExceptionHandler.php b/includes/exception/MWExceptionHandler.php
index bd7b29d..d4a240f 100644 (file)
--- a/includes/exception/MWExceptionHandler.php
+++ b/includes/exception/MWExceptionHandler.php
@@ -352,32 +352,32 @@ TXT;
         *
         * @param Exception $e
         * @return string
+        * @see prettyPrintTrace()
         */
        public static function getRedactedTraceAsString( Exception $e ) {
-               return self::prettyPrintRedactedTrace(
-                       self::getRedactedTrace( $e )
-               );
+               return self::prettyPrintTrace( self::getRedactedTrace( $e ) );
        }
 
        /**
-        * Generate a string representation of a structured stack trace generated
-        * by getRedactedTrace().
+        * Generate a string representation of a stacktrace.
         *
         * @param array $trace
+        * @param string $pad Constant padding to add to each line of trace
         * @return string
         * @since 1.26
         */
-       public static function prettyPrintRedactedTrace( array $trace ) {
+       public static function prettyPrintTrace( array $trace, $pad = '' ) {
                $text = '';
 
                foreach ( $trace as $level => $frame ) {
                        if ( isset( $frame['file'] ) && isset( $frame['line'] ) ) {
-                               $text .= "#{$level} {$frame['file']}({$frame['line']}): ";
+                               $text .= "{$pad}#{$level} {$frame['file']}({$frame['line']}): ";
                        } else {
-                               // 'file' and 'line' are unset for calls via call_user_func (bug 55634)
-                               // This matches behaviour of Exception::getTraceAsString to instead
-                               // display "[internal function]".
-                               $text .= "#{$level} [internal function]: ";
+                               // 'file' and 'line' are unset for calls via call_user_func
+                               // (bug 55634) This matches behaviour of
+                               // Exception::getTraceAsString to instead display "[internal
+                               // function]".
+                               $text .= "{$pad}#{$level} [internal function]: ";
                        }
 
                        if ( isset( $frame['class'] ) ) {
@@ -394,7 +394,7 @@ TXT;
                }
 
                $level = $level + 1;
-               $text .= "#{$level} {main}";
+               $text .= "{$pad}#{$level} {main}";
 
                return $text;
        }

diff --git a/tests/phpunit/includes/debug/logger/monolog/LineFormatterTest.php b/tests/phpunit/includes/debug/logger/monolog/LineFormatterTest.php
index f12cf5b..6ee54d3 100644 (file)
--- a/tests/phpunit/includes/debug/logger/monolog/LineFormatterTest.php
+++ b/tests/phpunit/includes/debug/logger/monolog/LineFormatterTest.php
@@ -48,10 +48,10 @@ class LineFormatterTest extends MediaWikiTestCase {
                        )
                );
                $out = $fixture->normalizeException( $boom );
-               $this->assertContains( '[Exception InvalidArgumentException]', $out );
-               $this->assertContains( ', [Exception LengthException]', $out );
-               $this->assertContains( ', [Exception LogicException]', $out );
-               $this->assertNotContains( '[stacktrace]', $out );
+               $this->assertContains( "\n[Exception InvalidArgumentException]", $out );
+               $this->assertContains( "\nCaused by: [Exception LengthException]", $out );
+               $this->assertContains( "\nCaused by: [Exception LogicException]", $out );
+               $this->assertNotContains( "\n  #0", $out );
        }
 
        /**
@@ -67,9 +67,9 @@ class LineFormatterTest extends MediaWikiTestCase {
                        )
                );
                $out = $fixture->normalizeException( $boom );
-               $this->assertContains( '[Exception InvalidArgumentException', $out );
-               $this->assertContains( ', [Exception LengthException]', $out );
-               $this->assertContains( ', [Exception LogicException]', $out );
-               $this->assertContains( '[stacktrace]', $out );
+               $this->assertContains( "\n[Exception InvalidArgumentException]", $out );
+               $this->assertContains( "\nCaused by: [Exception LengthException]", $out );
+               $this->assertContains( "\nCaused by: [Exception LogicException]", $out );
+               $this->assertContains( "\n  #0", $out );
        }
 }