[random test failure] Random fail in BuildTestTest::testPortMany

Corrected c/p fail in IS.

@lendude:

Looking at \Drupal\BuildTests\Framework\BuildTestBase::instantiateServer, the test waits for the server to be up for 1 second (1000 iterations of waiting 1000 microseconds).

I would expect that to be 1000 x 1000ms = 16.6666667 minutes, but that's insanely long.

Looking at the CI log:

00:09:37.605 Drupal\BuildTests\Framework\Tests\ExternalCommandRequirement   6 passes                                      
00:09:37.605 Drupal\BuildTests\Composer\ComposerValidateTest               34 passes                                      
00:09:45.656 Drupal\BuildTests\Framework\Tests\BuildTestTest                0 passes             1 exceptions             
00:09:52.985 FATAL Drupal\BuildTests\Framework\Tests\BuildTestTest: test runner returned a non-zero error code (2).
00:09:53.031 Drupal\BuildTests\Framework\Tests\BuildTestTest                0 passes   1 fails                            
00:09:53.031 Drupal\BuildTests\Framework\Tests\HtRouterTest                 1 passes                                      
00:10:03.120 Drupal\BuildTests\Composer\Template\ComposerProjectTemplates   3 passes        

It takes around 7 seconds for Drupal\BuildTests\Framework\Tests\BuildTestTest to give up hope and throw the exception after the loop:

    // Wait until the web server has started. It is started if the port is no
    // longer available.
    for ($i = 0; $i < 1000; $i++) {
      if (!$this->checkPortIsAvailable($port)) {
        return $ps;
      }
      usleep(1000);
    }
    throw new \RuntimeException(sprintf("Unable to start the web server.\nERROR OUTPUT:\n%s", $ps->getErrorOutput()));

So the obvious thing to try would be to wait a little longer? Maybe 2 seconds?

Anyway: Since this wait-loop returns with an answer when the port is no longer available ($ps) as soon as possible, I think a longer wait is OK here.

Created an MR for that.

Not really sure how to test/check this, the test-failure is (fairly) rare, found only 2 other documented occurrences so far. (See links in IS).

Running with the theory that this only occurs when TestBot is really busy.

It's in μs not ms (that threw me too the first time I looked at it :))

Life's too short to worry about μs IMHO, but you're absolutely right :P

Hit another occurrence: https://www.drupal.org/pift-ci-job/2069592

Another bites the dust, this time in the 9.3.x-dev test-on-commit: https://www.drupal.org/pift-ci-job/2069801

To me the number of iterations is too high and the wait is far too short. It feels like something like 200 iterations and waiting 10 ms / 10000 microseconds between each one would be plenty while avoiding hammering the port to check if it's open yet.

Thus spoketh @longwave in #9

Can't argue with that!
Updated MR.

• Added Needs followup tag for the suggested locking mechanism. (Not creating one right now since the improved Exception output might give us a clue to do something else instead).
• Reverted changes made until now.
• Updated MR with the suggested improved Exception output.

It's possible the exit code might also tell us something if there is no output? Wonder if we should just call assertCommandExitCode() instead which would print both output streams and the exit code.

Thus spoketh @longwave in #16.

Me like!
Changed MR accordingly

Another one: https://www.drupal.org/pift-ci-job/2073236

Sure, back to RuntimeException with errorOutput.

Added Needs followup tag for the suggested locking mechanism. (Not creating one right now since the improved Exception output might give us a clue to do something else instead).

@alexpott there is already a locking mechanism that is supposed to cover multiple processes in BuildTestBase::findAvailablePort(), what more do we need?

@longwave ah yeah I see we have a locking mechanism... so it's not a race or we've implemented it incorrectly.

Removed Needs followup tag accordingly.

> Let's see if we can trigger this with repeat. This might not work if it's a concurrency issue with other tests.

My money is on the concurrency, so no dice with the repeat-test, but would love to be wrong.

Updated the MR to include the exit-code.

EDIT: Right...beaten by 1 minute and a wrong prediction. Not much info sadly :/

There was 1 error:

1) Drupal\BuildTests\Framework\Tests\BuildTestTest::testPortMany
RuntimeException: Unable to start the web server.
CODE: 0
OUTPUT:


ERROR OUTPUT:


/var/www/html/core/tests/Drupal/BuildTests/Framework/BuildTestBase.php:435
/var/www/html/core/tests/Drupal/BuildTests/Framework/Tests/BuildTestTest.php:145
/var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:722
/var/www/html/vendor/phpunit/phpunit/src/Framework/TestSuite.php:677
/var/www/html/vendor/phpunit/phpunit/src/TextUI/TestRunner.php:667
/var/www/html/vendor/phpunit/phpunit/src/TextUI/Command.php:143
/var/www/html/vendor/phpunit/phpunit/src/TextUI/Command.php:96

If it ain't consistently broke: Break it consistently! 😈

(Slightly off-topic) I like this insight into the minds of The Big Brains, kinda like watching a live debug stream (which I never watched, no clue if it even exists). Putting it into the d.o queue format makes it easy to hop by every now and then and see where we stand.
Ponders turning this into a big-selling YouTube channel and finally become filthy rich...

- Patch makes TestBot happily green
- Moving usleep to go after the checkPortIsAvailable($port) check is explained in #37 in a way that even I understand.
- The increase of usleep-value and decrease of the loop-value is test-proven in #39.
- Improved logging in RuntimeException message per as (initially) requested by @alexpott in #13.

RTBC for me.