From c64b38b24cdb90242a262a4320d63e5fe5497ad3 Mon Sep 17 00:00:00 2001 From: David Callizaya Date: Mon, 3 Aug 2026 20:42:22 -0400 Subject: [PATCH 1/2] debug tests --- phpunit.xml | 5 +- tests/Extensions/RealTimeOutputExtension.php | 60 ++++++++++++++++++++ 2 files changed, 64 insertions(+), 1 deletion(-) create mode 100644 tests/Extensions/RealTimeOutputExtension.php diff --git a/phpunit.xml b/phpunit.xml index 8c16d0ae0e..7cc898e9d0 100644 --- a/phpunit.xml +++ b/phpunit.xml @@ -7,7 +7,10 @@ extensionsDirectory="tests/Extensions" displayDetailsOnAllIssues="true" > - + + + + tests/Feature tests/Managers diff --git a/tests/Extensions/RealTimeOutputExtension.php b/tests/Extensions/RealTimeOutputExtension.php new file mode 100644 index 0000000000..2816f91988 --- /dev/null +++ b/tests/Extensions/RealTimeOutputExtension.php @@ -0,0 +1,60 @@ +registerSubscriber(new class implements PreparationStartedSubscriber { + public function notify(PreparationStarted $event): void + { + fwrite(STDERR, "\n\033[1;33m[START]\033[0m " . $event->test()->id() . "\n"); + } + }); + + $facade->registerSubscriber(new class implements PassedSubscriber { + public function notify(Passed $event): void + { + fwrite(STDERR, "\033[1;32m[PASS]\033[0m " . $event->test()->id() . "\n"); + } + }); + + $facade->registerSubscriber(new class implements FailedSubscriber { + public function notify(Failed $event): void + { + fwrite(STDERR, "\033[1;31m[FAIL]\033[0m " . $event->test()->id() . "\n"); + // TESTING_VERBOSE will handle the trace, but we can add a small marker here if needed. + } + }); + + $facade->registerSubscriber(new class implements ErroredSubscriber { + public function notify(Errored $event): void + { + fwrite(STDERR, "\033[1;31m[ERROR]\033[0m " . $event->test()->id() . "\n"); + } + }); + + $facade->registerSubscriber(new class implements SkippedSubscriber { + public function notify(Skipped $event): void + { + fwrite(STDERR, "\033[1;34m[SKIP]\033[0m " . $event->test()->id() . "\n"); + } + }); + } +} From b1bbb34f7e60447eaffc4817b0db77702cc7e857 Mon Sep 17 00:00:00 2001 From: David Callizaya Date: Tue, 4 Aug 2026 12:06:31 -0400 Subject: [PATCH 2/2] ci: debug tests --- phpunit.xml | 3 + tests/Extensions/RealTimeOutputExtension.php | 109 ++++++++++++++++--- tests/TestCase.php | 14 +++ 3 files changed, 110 insertions(+), 16 deletions(-) diff --git a/phpunit.xml b/phpunit.xml index 7cc898e9d0..6d8310e71c 100644 --- a/phpunit.xml +++ b/phpunit.xml @@ -27,6 +27,9 @@ + + + diff --git a/tests/Extensions/RealTimeOutputExtension.php b/tests/Extensions/RealTimeOutputExtension.php index 2816f91988..8a317305b7 100644 --- a/tests/Extensions/RealTimeOutputExtension.php +++ b/tests/Extensions/RealTimeOutputExtension.php @@ -2,59 +2,136 @@ namespace Tests\Extensions; -use PHPUnit\Runner\Extension\Extension; -use PHPUnit\Runner\Extension\Facade; -use PHPUnit\Runner\Extension\ParameterCollection; -use PHPUnit\TextUI\Configuration\Configuration; -use PHPUnit\Event\Test\PreparationStarted; -use PHPUnit\Event\Test\PreparationStartedSubscriber; -use PHPUnit\Event\Test\Passed; -use PHPUnit\Event\Test\PassedSubscriber; -use PHPUnit\Event\Test\Failed; -use PHPUnit\Event\Test\FailedSubscriber; use PHPUnit\Event\Test\Errored; use PHPUnit\Event\Test\ErroredSubscriber; +use PHPUnit\Event\Test\Failed; +use PHPUnit\Event\Test\FailedSubscriber; +use PHPUnit\Event\Test\Passed; +use PHPUnit\Event\Test\PassedSubscriber; +use PHPUnit\Event\Test\PreparationStarted; +use PHPUnit\Event\Test\PreparationStartedSubscriber; +use PHPUnit\Event\Test\Prepared; +use PHPUnit\Event\Test\PreparedSubscriber; use PHPUnit\Event\Test\Skipped; use PHPUnit\Event\Test\SkippedSubscriber; +use PHPUnit\Runner\Extension\Extension; +use PHPUnit\Runner\Extension\Facade; +use PHPUnit\Runner\Extension\ParameterCollection; +use PHPUnit\TextUI\Configuration\Configuration; class RealTimeOutputExtension implements Extension { + /** @var array */ + private static array $startedAt = []; + + /** @var array */ + private static array $preparedAt = []; + public function bootstrap(Configuration $configuration, Facade $facade, ParameterCollection $parameters): void { $facade->registerSubscriber(new class implements PreparationStartedSubscriber { public function notify(PreparationStarted $event): void { - fwrite(STDERR, "\n\033[1;33m[START]\033[0m " . $event->test()->id() . "\n"); + $id = $event->test()->id(); + RealTimeOutputExtension::markStarted($id); + RealTimeOutputExtension::write('START', $id, "\033[1;33m", true); + } + }); + + $facade->registerSubscriber(new class implements PreparedSubscriber { + public function notify(Prepared $event): void + { + $id = $event->test()->id(); + RealTimeOutputExtension::markPrepared($id); + $setupDuration = RealTimeOutputExtension::elapsedSinceStart($id); + RealTimeOutputExtension::write( + 'PREPARED', + $id, + "\033[1;36m", + false, + $setupDuration !== null ? sprintf('setup=%.2fs', $setupDuration) : null + ); } }); $facade->registerSubscriber(new class implements PassedSubscriber { public function notify(Passed $event): void { - fwrite(STDERR, "\033[1;32m[PASS]\033[0m " . $event->test()->id() . "\n"); + RealTimeOutputExtension::writeFinished('PASS', $event->test()->id(), "\033[1;32m"); } }); $facade->registerSubscriber(new class implements FailedSubscriber { public function notify(Failed $event): void { - fwrite(STDERR, "\033[1;31m[FAIL]\033[0m " . $event->test()->id() . "\n"); - // TESTING_VERBOSE will handle the trace, but we can add a small marker here if needed. + RealTimeOutputExtension::writeFinished('FAIL', $event->test()->id(), "\033[1;31m"); } }); $facade->registerSubscriber(new class implements ErroredSubscriber { public function notify(Errored $event): void { - fwrite(STDERR, "\033[1;31m[ERROR]\033[0m " . $event->test()->id() . "\n"); + RealTimeOutputExtension::writeFinished('ERROR', $event->test()->id(), "\033[1;31m"); } }); $facade->registerSubscriber(new class implements SkippedSubscriber { public function notify(Skipped $event): void { - fwrite(STDERR, "\033[1;34m[SKIP]\033[0m " . $event->test()->id() . "\n"); + RealTimeOutputExtension::writeFinished('SKIP', $event->test()->id(), "\033[1;34m"); } }); } + + public static function markStarted(string $id): void + { + self::$startedAt[$id] = microtime(true); + unset(self::$preparedAt[$id]); + } + + public static function markPrepared(string $id): void + { + self::$preparedAt[$id] = microtime(true); + } + + public static function elapsedSinceStart(string $id): ?float + { + if (!isset(self::$startedAt[$id])) { + return null; + } + + return microtime(true) - self::$startedAt[$id]; + } + + public static function writeFinished(string $label, string $id, string $color): void + { + $total = self::elapsedSinceStart($id); + $body = null; + if ($total !== null) { + $body = sprintf('total=%.2fs', $total); + if (isset(self::$preparedAt[$id])) { + $body .= sprintf(' body=%.2fs', microtime(true) - self::$preparedAt[$id]); + } + } + + self::write($label, $id, $color, false, $body); + unset(self::$startedAt[$id], self::$preparedAt[$id]); + } + + public static function write(string $label, string $id, string $color, bool $leadingNewline = false, ?string $extra = null): void + { + $timestamp = date('H:i:s'); + $prefix = $leadingNewline ? "\n" : ''; + $suffix = $extra ? " ({$extra})" : ''; + fwrite(STDERR, sprintf( + "%s%s[%s]%s [%s] %s%s\n", + $prefix, + $color, + $label, + "\033[0m", + $timestamp, + $id, + $suffix + )); + } } diff --git a/tests/TestCase.php b/tests/TestCase.php index fce7ee220d..587ba3b53f 100644 --- a/tests/TestCase.php +++ b/tests/TestCase.php @@ -72,7 +72,21 @@ protected function setUp(): void // Clear Redis cache before running tests foreach (['default', 'cache', 'cache_settings'] as $connection) { + if (env('TESTING_SETUP_TRACE')) { + fwrite(STDERR, sprintf( + "\033[1;35m[SETUP]\033[0m [%s] Redis flushDb(%s) start\n", + date('H:i:s'), + $connection + )); + } Redis::connection($connection)->flushDb(); + if (env('TESTING_SETUP_TRACE')) { + fwrite(STDERR, sprintf( + "\033[1;35m[SETUP]\033[0m [%s] Redis flushDb(%s) done\n", + date('H:i:s'), + $connection + )); + } } if (!self::$cacheCleared) {