JUnit XML logger may crash when test that is run in separate process exits unexpectedly #5771
Description
| Q | A |
|---|---|
| PHPUnit version | 10.5.15 |
| PHP version | 8.2.7 |
| Installation Method | Composer |
Summary
When a test run in a separate process caused the child process to ended unexpectedly, that is without serialized output, and JUnit logging is used, the main process will crash afterwards due to an assert or subsequent type error.
Current behavior
JunitXmlLogger works with the event system.
When it receives a PreparationStarted event, it will initialize its internal data for the current test case.
When it receives a Finished event, it will assert that the internal data has been initialized.
When the test is run in a separate process, this all happens in that child process, which thus has its own instance of JunitXmlLogger.
Should the child process end unexpectedly, AbstractPhpProcess::processChildResult will first emit an Errored event and then a Finished event.
These two are processed by the JunitXmlLogger instance of the main process that never received a PreparationStarted event.
While the handler for the Errored event is capable to deal with that by first initializing the internal data structures for the test case, it will also call the inner handler for a finished test which resets these internal data structures.
The handler for the Finished event does not handle initialization and thus runs into the assert.
How to reproduce
minimal test case
class PHPUnitEventBugTest extends \PHPUnit\Framework\TestCase
{
public function __construct(string $name)
{
parent::__construct($name);
$this->setRunTestInSeparateProcess(true);
}
#[\PHPUnit\Framework\Attributes\Test]
public function forceBug(): void
{
// exit is used as a simple means to end the process "unexpectedly"
exit;
}
}output without --log-junit
PHPUnit 10.5.15 by Sebastian Bergmann and contributors.
Runtime: PHP 8.2.7
E 1 / 1 (100%)
Time: 00:02.087, Memory: 10.00 MB
There was 1 error:
1) PHPUnitEventBugTest::forceBug
Test was run in child process and ended unexpectedly
ERRORS!
Tests: 1, Assertions: 0, Errors: 1.
output with --log-junit
PHPUnit 10.5.15 by Sebastian Bergmann and contributors.
Runtime: PHP 8.2.7
E 1 / 1 (100%)
An error occurred inside PHPUnit.
Message: assert($this->currentTestCase !== null)
Location: /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php:253
#0 /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php(253): assert(false, '...')
#1 /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php(209): PHPUnit\Logging\JUnit\JunitXmlLogger->handleFinish(Object(PHPUnit\Event\Telemetry\Info), 0)
#2 /app/vendor/phpunit/phpunit/src/Logging/JUnit/Subscriber/TestFinishedSubscriber.php(26): PHPUnit\Logging\JUnit\JunitXmlLogger->testFinished(Object(PHPUnit\Event\Test\Finished))
#3 /app/vendor/phpunit/phpunit/src/Event/Dispatcher/DirectDispatcher.php(102): PHPUnit\Logging\JUnit\TestFinishedSubscriber->notify(Object(PHPUnit\Event\Test\Finished))
#4 /app/vendor/phpunit/phpunit/src/Event/Dispatcher/DeferringDispatcher.php(45): PHPUnit\Event\DirectDispatcher->dispatch(Object(PHPUnit\Event\Test\Finished))
#5 /app/vendor/phpunit/phpunit/src/Event/Emitter/DispatchingEmitter.php(998): PHPUnit\Event\DeferringDispatcher->dispatch(Object(PHPUnit\Event\Test\Finished))
#6 /app/vendor/phpunit/phpunit/src/Util/PHP/AbstractPhpProcess.php(272): PHPUnit\Event\DispatchingEmitter->testFinished(Object(PHPUnit\Event\Code\TestMethod), 0)
#7 /app/vendor/phpunit/phpunit/src/Util/PHP/AbstractPhpProcess.php(150): PHPUnit\Util\PHP\AbstractPhpProcess->processChildResult(Object(PHPUnitEventBugTest), '', '')
#8 /app/vendor/phpunit/phpunit/src/Framework/TestRunner.php(351): PHPUnit\Util\PHP\AbstractPhpProcess->runTestJob('...', Object(PHPUnitEventBugTest), '...')
#9 /app/vendor/phpunit/phpunit/src/Framework/TestCase.php(490): PHPUnit\Framework\TestRunner->runInSeparateProcess(Object(PHPUnitEventBugTest), false, false)
#10 /app/vendor/phpunit/phpunit/src/Framework/TestSuite.php(341): PHPUnit\Framework\TestCase->run()
#11 /app/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(62): PHPUnit\Framework\TestSuite->run()
#12 /app/vendor/phpunit/phpunit/src/TextUI/Application.php(198): PHPUnit\TextUI\TestRunner->run(Object(PHPUnit\TextUI\Configuration\Configuration), Object(PHPUnit\Runner\ResultCache\DefaultResultCache), Object(PHPUnit\Framework\TestSuite))
#13 /app/vendor/phpunit/phpunit/phpunit(104): PHPUnit\TextUI\Application->run(Array)
#14 /app/vendor/bin/phpunit(122): include('...')
#15 {main}
output with --log-junit and asserts disabled
PHPUnit 10.5.15 by Sebastian Bergmann and contributors.
Runtime: PHP 8.2.7
E 1 / 1 (100%)
An error occurred inside PHPUnit.
Message: PHPUnit\Event\Telemetry\HRTime::duration(): Argument #1 ($start) must be of type PHPUnit\Event\Telemetry\HRTime, null given, called in /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php on line 256
Location: /app/vendor/phpunit/phpunit/src/Event/Value/Telemetry/HRTime.php:59
#0 /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php(256): PHPUnit\Event\Telemetry\HRTime->duration(NULL)
#1 /app/vendor/phpunit/phpunit/src/Logging/JUnit/JunitXmlLogger.php(209): PHPUnit\Logging\JUnit\JunitXmlLogger->handleFinish(Object(PHPUnit\Event\Telemetry\Info), 0)
#2 /app/vendor/phpunit/phpunit/src/Logging/JUnit/Subscriber/TestFinishedSubscriber.php(26): PHPUnit\Logging\JUnit\JunitXmlLogger->testFinished(Object(PHPUnit\Event\Test\Finished))
#3 /app/vendor/phpunit/phpunit/src/Event/Dispatcher/DirectDispatcher.php(102): PHPUnit\Logging\JUnit\TestFinishedSubscriber->notify(Object(PHPUnit\Event\Test\Finished))
#4 /app/vendor/phpunit/phpunit/src/Event/Dispatcher/DeferringDispatcher.php(45): PHPUnit\Event\DirectDispatcher->dispatch(Object(PHPUnit\Event\Test\Finished))
#5 /app/vendor/phpunit/phpunit/src/Event/Emitter/DispatchingEmitter.php(998): PHPUnit\Event\DeferringDispatcher->dispatch(Object(PHPUnit\Event\Test\Finished))
#6 /app/vendor/phpunit/phpunit/src/Util/PHP/AbstractPhpProcess.php(272): PHPUnit\Event\DispatchingEmitter->testFinished(Object(PHPUnit\Event\Code\TestMethod), 0)
#7 /app/vendor/phpunit/phpunit/src/Util/PHP/AbstractPhpProcess.php(150): PHPUnit\Util\PHP\AbstractPhpProcess->processChildResult(Object(PHPUnitEventBugTest), '', '')
#8 /app/vendor/phpunit/phpunit/src/Framework/TestRunner.php(351): PHPUnit\Util\PHP\AbstractPhpProcess->runTestJob('...', Object(PHPUnitEventBugTest), '...')
#9 /app/vendor/phpunit/phpunit/src/Framework/TestCase.php(490): PHPUnit\Framework\TestRunner->runInSeparateProcess(Object(PHPUnitEventBugTest), false, false)
#10 /app/vendor/phpunit/phpunit/src/Framework/TestSuite.php(341): PHPUnit\Framework\TestCase->run()
#11 /app/vendor/phpunit/phpunit/src/TextUI/TestRunner.php(62): PHPUnit\Framework\TestSuite->run()
#12 /app/vendor/phpunit/phpunit/src/TextUI/Application.php(198): PHPUnit\TextUI\TestRunner->run(Object(PHPUnit\TextUI\Configuration\Configuration), Object(PHPUnit\Runner\ResultCache\DefaultResultCache), Object(PHPUnit\Framework\TestSuite))
#13 /app/vendor/phpunit/phpunit/phpunit(104): PHPUnit\TextUI\Application->run(Array)
#14 /app/vendor/bin/phpunit(122): include('...')
#15 {main}
Expected behavior
The assert should not fail and output stay the same even when using JUnit logging.
The fix for #5561 (which had similar symptoms) introduced a preparationFailed flag (which is never cleared once set; another potential bug?) which is used to skip the inner handler for the Finished event (in JunitXmlLogger::testFinished).
I'm not sure why this flag was introduced instead of just checking the prepared flag, however checking the latter in that place seems to solve the issue.