From: Bryan Davis Date: Mon, 24 Aug 2015 19:29:10 +0000 (-0600) Subject: Enhance debug log output for stacktraces X-Git-Tag: 1.31.0-rc.0~10101^2 X-Git-Url: https://git.cyclocoop.org/%7B%24www_url%7Dadmin/compta/banques/ajouter.php?a=commitdiff_plain;h=ba1835f159b2a6d988a2f82a9a53d4a7ab491382;p=lhc%2Fweb%2Fwiklou.git 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 b6439b8222..0f4c648406 100644 --- 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 e593d63bc4..2ba7a53cb5 100644 --- 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 @@ -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 bd7b29dd8a..d4a240ff20 100644 --- 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 f12cf5bd80..6ee54d3380 100644 --- 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 ); } }