Page MenuHomePhabricator

See default timeout for phpunit tests
Open, MediumPublic

Description

I am running CI for new extension () and it get stuck around 66% of extensions phpunit test and times out. See: https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/32583/

Several problem I see here:

  • Some test is allowed to take a very long time (until whole job times out) - it should have been interrupted long before
  • When the above happens, it is impossible to know which test does this
  • There are a bunch of other errors in the test run, but it's impossible to see what happened to them - the log is empty and seemingly no other output is provided that can be used to see what's going on

I think we need some ways to investigate such failures and have more information about what's going on.

Event Timeline

The patch was PS25 of https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/WikibaseCirrusSearch/+/447954/ the job timed out after an hour while running PHPUnit extensions suite without Database group (phpunit --testsuite extensions --exclude-group Database).

I think the running process are being send a SIGTERM, not sure it is relayed properly to the Docker container though.

Mediawiki is configured to write logs and that is capture by the build. We use tests/phpunit/phpunit.php --debug-tests the start/end of tests is logged in Mediawiki PHPUnitCommand log buckets. Hence at the end of mw-debug-cli.log we have:

[PHPUnitCommand] Start test CirrusSearch\Tests\Maintenance\AnalysisConfigBuilderTest::testAnalysisConfig with data set "en-zh-sv"
[Wikibase] Wikibase\SettingsArray::getSetting: setting conceptBaseUri was given as a closure, resolve it to 'http://7bd6e954eb82/entity/'

I think that addresses your point about figuring which test times out?

PHPUnit can be configured to add a timeout to tests via tests/phpunit/suite.xml but I think tests have to be explicitly marked as such via @small, @medium or @large:

<phpunit
    timeoutForSmallTests="10"
    timeoutForMediumTests="30"
    timeoutForLargeTests="60"

https://github.com/sebastianbergmann/phpunit-documentation/issues/461 seems to indicate that there is no default enforced by default. See also https://github.com/sebastianbergmann/phpunit/commit/32feefd37c820d122acac70fff0ee25cf0764612 :

PHPUnit 4.7.0

  • Tests not annotated with @small, @medium, or @large are no longer treated as being annotated with @small

:-(

Hence at the end of mw-debug-cli.log we have:

Ah, that solves it I guess. Thanks! Though I wish there was an easier way to do it that downloading 10M file...

seems to indicate that there is no default enforced by default.

Ugh :(. I wonder if there's some option to re-enable this for all tests. I really don't need a test running for an hour, neither I assume does anybody else.

At one point I tried having a debug log file per testsuite but that produced way too many files :-/ We might end up emitting the debug logs to some central logstash system but work has not started on that front yet. We merely have some ideas/discussions about capturing all CI artifacts. Hopefully we will achieve something over the next few months.

A leftover task would be to figure out how to have PHPUnit to enforce a default timeout when tests are not marked with @small, @medium, @large. PHPUnit 4.7.0 dropped the default timeout. mediawiki/core ships with PHPUnit 6.5.14 which has:

--enforce-time-limit Enforce time limit based on test size.

(xml is enforceTimeLimit=True). The related code seems to be:

Framework/TestResult.php
try {
    if (!$test instanceof WarningTestCase &&
        $test->getSize() != \PHPUnit\Util\Test::UNKNOWN &&
        $this->enforceTimeLimit &&
        \extension_loaded('pcntl') && \class_exists('PHP_Invoker')) {
        switch ($test->getSize()) {
            case \PHPUnit\Util\Test::SMALL:
                $_timeout = $this->timeoutForSmallTests;

                break;

            case \PHPUnit\Util\Test::MEDIUM:
                $_timeout = $this->timeoutForMediumTests;

                break;

            case \PHPUnit\Util\Test::LARGE:
                $_timeout = $this->timeoutForLargeTests;

                break;
        }

        $invoker = new PHP_Invoker;
        $invoker->invoke([$test, 'runBare'], [], $_timeout);
    } else {
        $test->runBare();
    }
} catch (PHP_Invoker_TimeoutException $e) {
    $this->addFailure(
        $test,
        new RiskyTestError(
            $e->getMessage()
        ),
        $_timeout
    );

    $risky = true;

Though it seems to me that only forces the timeout when the test is already flagged ($test->getSize() != \PHPUnit\Util\Test::UNKNOWN).


As part of my journey I then found https://github.com/sebastianbergmann/phpunit/pull/3224 which adds:

--default-time-limit Maximum running time in seconds for unsized tests

It has available since PHPUnit 7.4.0 but that version requires PHP 7.1 and we run tests with PHP 7.0 :-(

greg renamed this task from extensions phpunit tests time out to See default timeout for phpunit tests.Jul 26 2019, 12:29 AM
greg triaged this task as Medium priority.
greg removed a subscriber: Funnyjokes2019.
greg subscribed.

Refocusing this task as this seems to (now) be more about setting a default timeout for phpunit tests that aren't @small, @medium, or @large.

Adding Code-Health for their input