From: Erik Bernhardson <ebernhardson@wikimedia.org>
Date: Fri, 18 Jan 2019 23:28:26 +0000 (-0800)
Subject: Print logs generated during unit test when test fails
X-Git-Tag: 1.34.0-rc.0~2749^2
X-Git-Url: http://git.cyclocoop.org/%22%20.%20generer_url_aide%28?a=commitdiff_plain;h=56ffbc2a4e3ade907b050119d03c2d527f860868;p=lhc%2Fweb%2Fwiklou.git

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 61b8177891..4acccfc02a 100644
--- 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
index 0000000000..64d5563240
--- /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 024557248d..f742a1bae8 100644
--- 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
index 0000000000..502685d346
--- /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 897919541d..5d139ff7e6 100644
--- 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
index 0000000000..e796752143
--- /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 287d28c3b9..35f396ef78 100644
--- 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 {