Print logs generated during unit test when test fails

When a unit test fails it is possible, perhaps even likely in some
cases, that some code that was run logged useful information about
how that failure came to be.

Help people out, tell them what happened!

Change-Id: I30bbc31799a65024868678d052fec9aafacc1aff

diff --git a/autoload.php b/autoload.php
index 61b8177..4acccfc 100644 (file)
--- a/autoload.php
+++ b/autoload.php
@@ -958,6 +958,7 @@ $wgAutoloadLocalClasses = [
        'MediaWiki\\Widget\\TitlesMultiselectWidget' => __DIR__ . '/includes/widget/TitlesMultiselectWidget.php',
        'MediaWiki\\Widget\\UserInputWidget' => __DIR__ . '/includes/widget/UserInputWidget.php',
        'MediaWiki\\Widget\\UsersMultiselectWidget' => __DIR__ . '/includes/widget/UsersMultiselectWidget.php',
+       'Mediawiki\\Logger\\LogCapturingSpi' => __DIR__ . '/includes/debug/logger/LogCapturingSpi.php',
        'MemcLockManager' => __DIR__ . '/includes/libs/lockmanager/MemcLockManager.php',
        'MemcachedBagOStuff' => __DIR__ . '/includes/libs/objectcache/MemcachedBagOStuff.php',
        'MemcachedClient' => __DIR__ . '/includes/libs/objectcache/MemcachedClient.php',

diff --git a/includes/debug/logger/LogCapturingSpi.php b/includes/debug/logger/LogCapturingSpi.php
new file mode 100644 (file)
index 0000000..64d5563
--- /dev/null
+++ b/includes/debug/logger/LogCapturingSpi.php
@@ -0,0 +1,83 @@
+<?php
+
+namespace Mediawiki\Logger;
+
+use Psr\Log\AbstractLogger;
+use Psr\Log\LoggerInterface;
+
+/**
+ * Wraps another spi to capture all logs generated. This can be
+ * used, for example, to collect all logs generated during a
+ * unit test and report them when the test fails.
+ */
+class LogCapturingSpi implements Spi {
+       /** @var LoggerInterface[] */
+       private $singletons;
+       /** @var Spi */
+       private $inner;
+       /** @var array */
+       private $logs = [];
+
+       public function __construct( Spi $inner ) {
+               $this->inner = $inner;
+       }
+
+       /**
+        * @return array
+        */
+       public function getLogs() {
+               return $this->logs;
+       }
+
+       /**
+        * @param string $channel
+        * @return LoggerInterface
+        */
+       public function getLogger( $channel ) {
+               if ( !isset( $this->singletons[$channel] ) ) {
+                       $this->singletons[$channel] = $this->createLogger( $channel );
+               }
+               return $this->singletons[$channel];
+       }
+
+       /**
+        * @param array $log
+        */
+       public function capture( $log ) {
+               $this->logs[] = $log;
+       }
+
+       /**
+        * @param string $channel
+        * @return LoggerInterface
+        */
+       private function createLogger( $channel ) {
+               $inner = $this->inner->getLogger( $channel );
+               return new class( $channel, $inner, $this ) extends AbstractLogger {
+                       /** @var string */
+                       private $channel;
+                       /** @var LoggerInterface */
+                       private $logger;
+                       /** @var LogCapturingSpi */
+                       private $parent;
+
+                       // phpcs:ignore MediaWiki.Usage.NestedFunctions.NestedFunction
+                       public function __construct( $channel, LoggerInterface $logger, LogCapturingSpi $parent ) {
+                               $this->channel = $channel;
+                               $this->logger = $logger;
+                               $this->parent = $parent;
+                       }
+
+                       // phpcs:ignore MediaWiki.Usage.NestedFunctions.NestedFunction
+                       public function log( $level, $message, array $context = [] ) {
+                               $this->parent->capture( [
+                                       'channel' => $this->channel,
+                                       'level' => $level,
+                                       'message' => $message,
+                                       'context' => $context
+                               ] );
+                               $this->logger->log( $level, $message, $context );
+                       }
+               };
+       }
+}

diff --git a/tests/common/TestsAutoLoader.php b/tests/common/TestsAutoLoader.php
index 0245572..f742a1b 100644 (file)
--- a/tests/common/TestsAutoLoader.php
+++ b/tests/common/TestsAutoLoader.php
@@ -55,7 +55,9 @@ $wgAutoloadClasses += [
        'LessFileCompilationTest' => "$testDir/phpunit/LessFileCompilationTest.php",
        'MediaWikiCoversValidator' => "$testDir/phpunit/MediaWikiCoversValidator.php",
        'MediaWikiLangTestCase' => "$testDir/phpunit/MediaWikiLangTestCase.php",
+       'MediaWikiLoggerPHPUnitTestListener' => "$testDir/phpunit/MediaWikiLoggerPHPUnitTestListener.php",
        'MediaWikiPHPUnitCommand' => "$testDir/phpunit/MediaWikiPHPUnitCommand.php",
+       'MediaWikiPHPUnitResultPrinter' => "$testDir/phpunit/MediaWikiPHPUnitResultPrinter.php",
        'MediaWikiPHPUnitTestListener' => "$testDir/phpunit/MediaWikiPHPUnitTestListener.php",
        'MediaWikiTestCase' => "$testDir/phpunit/MediaWikiTestCase.php",
        'MediaWikiTestResult' => "$testDir/phpunit/MediaWikiTestResult.php",

diff --git a/tests/phpunit/MediaWikiLoggerPHPUnitTestListener.php b/tests/phpunit/MediaWikiLoggerPHPUnitTestListener.php
new file mode 100644 (file)
index 0000000..502685d
--- /dev/null
+++ b/tests/phpunit/MediaWikiLoggerPHPUnitTestListener.php
@@ -0,0 +1,68 @@
+<?php
+
+use Mediawiki\Logger\LoggerFactory;
+use Mediawiki\Logger\Spi;
+use Mediawiki\Logger\LogCapturingSpi;
+
+/**
+ * Replaces the logging SPI on each test run. This allows
+ * another component (the printer) to fetch the logs when
+ * reporting why a test failed.
+ */
+class MediaWikiLoggerPHPUnitTestListener extends PHPUnit_Framework_BaseTestListener {
+       /** @var Spi|null */
+       private $originalSpi;
+       /** @var Spi|null */
+       private $spi;
+       /** @var array|null */
+       private $lastTestLogs;
+
+       /**
+        * A test started.
+        *
+        * @param PHPUnit_Framework_Test $test
+        */
+       public function startTest( PHPUnit_Framework_Test $test ) {
+               $this->lastTestLogs = null;
+               $this->originalSpi = LoggerFactory::getProvider();
+               $this->spi = new LogCapturingSpi( $this->originalSpi );
+               LoggerFactory::registerProvider( $this->spi );
+       }
+
+       /**
+        * A test ended.
+        *
+        * @param PHPUnit_Framework_Test $test
+        * @param float $time
+        */
+       public function endTest( PHPUnit_Framework_Test $test, $time ) {
+               $this->lastTestLogs = $this->spi->getLogs();
+               LoggerFactory::registerProvider( $this->originalSpi );
+               $this->originalSpi = null;
+               $this->spi = null;
+       }
+
+       /**
+        * Get string formatted logs generated during the last
+        * test to execute.
+        *
+        * @return string
+        */
+       public function getLog() {
+               $logs = $this->lastTestLogs;
+               if ( !$logs ) {
+                       return '';
+               }
+               $message = [];
+               foreach ( $logs as $log ) {
+                       $message[] = sprintf(
+                               '[%s] [%s] %s %s',
+                               $log['channel'],
+                               $log['level'],
+                               $log['message'],
+                               json_encode( $log['context'] )
+                       );
+               }
+               return implode( "\n", $message );
+       }
+}

diff --git a/tests/phpunit/MediaWikiPHPUnitCommand.php b/tests/phpunit/MediaWikiPHPUnitCommand.php
index 8979195..5d139ff 100644 (file)
--- a/tests/phpunit/MediaWikiPHPUnitCommand.php
+++ b/tests/phpunit/MediaWikiPHPUnitCommand.php
@@ -2,6 +2,7 @@
 
 class MediaWikiPHPUnitCommand extends PHPUnit_TextUI_Command {
        private $cliArgs;
+       private $logListener;
 
        public function __construct( $ignorableOptions, $cliArgs ) {
                $ignore = function ( $arg ) {
@@ -18,14 +19,24 @@ class MediaWikiPHPUnitCommand extends PHPUnit_TextUI_Command {
                        $this->arguments['configuration'] = __DIR__ . '/suite.xml';
                }
 
-               // Add our own listener
+               // Add our own listeners
                $this->arguments['listeners'][] = new MediaWikiPHPUnitTestListener;
+               $this->logListener = new MediaWikiLoggerPHPUnitTestListener;
+               $this->arguments['listeners'][] = $this->logListener;
 
                // Output only to stderr to avoid "Headers already sent" problems
                $this->arguments['stderr'] = true;
+
+               // We could create a printer instance and avoid passing the
+               // listener statically, but then we have to recreate the
+               // appropriate arguments handling + defaults.
+               if ( !isset( $this->arguments['printer'] ) ) {
+                       $this->arguments['printer'] = MediaWikiPHPUnitResultPrinter::class;
+               }
        }
 
        protected function createRunner() {
+               MediaWikiPHPUnitResultPrinter::setLogListener( $this->logListener );
                $runner = new MediaWikiTestRunner;
                $runner->setMwCliArgs( $this->cliArgs );
                return $runner;

diff --git a/tests/phpunit/MediaWikiPHPUnitResultPrinter.php b/tests/phpunit/MediaWikiPHPUnitResultPrinter.php
new file mode 100644 (file)
index 0000000..e796752
--- /dev/null
+++ b/tests/phpunit/MediaWikiPHPUnitResultPrinter.php
@@ -0,0 +1,18 @@
+<?php
+
+class MediaWikiPHPUnitResultPrinter extends PHPUnit_TextUI_ResultPrinter {
+       /** @var MediaWikiLoggerPHPUnitTestListener */
+       private static $logListener;
+
+       public static function setLogListener( MediaWikiLoggerPHPUnitTestListener $logListener ) {
+               self::$logListener = $logListener;
+       }
+
+       protected function printDefectTrace( PHPUnit_Framework_TestFailure $defect ) {
+               $log = self::$logListener->getLog();
+               if ( $log ) {
+                       $this->write( "=== Logs generated by test case\n{$log}\n===\n" );
+               }
+               parent::printDefectTrace( $defect );
+       }
+}

diff --git a/tests/phpunit/MediaWikiTestCase.php b/tests/phpunit/MediaWikiTestCase.php
index 287d28c..35f396e 100644 (file)
--- a/tests/phpunit/MediaWikiTestCase.php
+++ b/tests/phpunit/MediaWikiTestCase.php
@@ -3,6 +3,7 @@
 use MediaWiki\Logger\LegacySpi;
 use MediaWiki\Logger\LoggerFactory;
 use MediaWiki\Logger\MonologSpi;
+use MediaWiki\Logger\LogCapturingSpi;
 use MediaWiki\MediaWikiServices;
 use Psr\Log\LoggerInterface;
 use Wikimedia\Rdbms\IDatabase;
@@ -1124,7 +1125,7 @@ abstract class MediaWikiTestCase extends PHPUnit\Framework\TestCase {
                                $this->loggers[$channel] = $singletons['loggers'][$channel] ?? null;
                        }
                        $singletons['loggers'][$channel] = $logger;
-               } elseif ( $provider instanceof LegacySpi ) {
+               } elseif ( $provider instanceof LegacySpi || $provider instanceof LogCapturingSpi ) {
                        if ( !isset( $this->loggers[$channel] ) ) {
                                $this->loggers[$channel] = $singletons[$channel] ?? null;
                        }
@@ -1151,7 +1152,7 @@ abstract class MediaWikiTestCase extends PHPUnit\Framework\TestCase {
                                } else {
                                        $singletons['loggers'][$channel] = $logger;
                                }
-                       } elseif ( $provider instanceof LegacySpi ) {
+                       } elseif ( $provider instanceof LegacySpi || $provider instanceof LogCapturingSpi ) {
                                if ( $logger === null ) {
                                        unset( $singletons[$channel] );
                                } else {