Problem/Motivation

https://www.drupal.org/pift-ci-job/632446 is failing intermittently.

https://www.drupal.org/pift-ci-job/597238
https://www.drupal.org/pift-ci-job/615344
Etc.

exception: [Other] Line 0 of sites/default/files/simpletest/phpunit-6.xml:
PHPunit Test failed to complete; Error: PHPUnit 4.8.35 by Sebastian Bergmann and contributors.

E

Time: 9.83 seconds, Memory: 3.25MB

There was 1 error:

1) Drupal\Tests\inline_form_errors\FunctionalJavascript\FormErrorHandlerCKEditorTest::testFragmentLink
PHPUnit_Framework_Exception: Fatal error: Call to a member function isVisible() on null in /var/www/html/core/modules/inline_form_errors/tests/src/FunctionalJavascript/FormErrorHandlerCKEditorTest.php on line 103

Caused by
exception 'ErrorException' with message 'unserialize(): Error at offset 0 of 185 bytes' in /var/www/html/vendor/phpunit/phpunit/src/Util/PHP.php:114
Stack trace:
#0 [internal function]: PHPUnit_Util_PHP->{closure}(8, 'unserialize(): ...', '/var/www/html/v...', 114, Array)
#1 /var/www/html/vendor/phpunit/phpunit/src/Util/PHP.php(114): unserialize('\nFatal error: C...')
#2 /var/www/html/vendor/phpunit/phpunit/src/Util/PHP.php(52): PHPUnit_Util_PHP->processChildResult(Object(Drupal\Tests\inline_form_errors\FunctionalJavascript\FormErrorHandlerCKEditorTest), Object(PHPUnit_Framework_TestResult), '\nFatal error: C...', '')
#3 /var/www/html/vendor/phpunit/phpunit/src/Framework/TestCase.php(722): PHPUnit_Util_PHP->runTestJob('

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Comments

drpal created an issue. See original summary.

xjm’s picture

Looks like this test has failed more than 10 times in HEAD over the past month in both branches, starting as far back as Feb. 12 at least:
https://www.drupal.org/pift-ci-job/597238
https://www.drupal.org/pift-ci-job/615344
etc.

droplet’s picture

Status: Active » Needs review
StatusFileSize
new1.96 KB

Quick patch to see if it works.

Status: Needs review » Needs work

The last submitted patch, 3: test-2864177.patch, failed testing.

droplet’s picture

Status: Needs work » Needs review
StatusFileSize
new1.9 KB

Status: Needs review » Needs work

The last submitted patch, 5: test-2864177.patch, failed testing.

droplet’s picture

Status: Needs work » Needs review
StatusFileSize
new1.92 KB

Ouch. I made a simple stupid mistake

droplet’s picture

StatusFileSize
new1.28 KB

Cool. It works. Full patch.

lendude’s picture

+++ b/core/scripts/run-tests.sh
@@ -142,6 +142,14 @@
+  // Do the test 25 times.

The failure rate doesn't seem to be very high so is running this 25 times enough to make us confident we have a fix?

Fix is a little surprising, since the error link is rendered on page load, why would you ever need to wait for it? Am I missing something?

wim leers’s picture

I've seen this random fail quite often lately.

droplet’s picture

@Lendude,

The failure rate doesn't seem to be very high so is running this 25 times enough to make us confident we have a fix?

this is enough. I triggered more tests.

    $this->submitForm($edit, 'Save and publish');

I guess there's a hidden problem on this line.

I'd suggest to commit #8 first and do further debugging soon.

Status: Needs review » Needs work

The last submitted patch, 8: random_failure_in-2864177-8.patch, failed testing.

droplet’s picture

Status: Needs work » Needs review
xjm’s picture

StatusFileSize
new628 bytes
new628 bytes

That's not enough test runs, actually. That's only 325 test runs and this is probably on the order of 1/1000 fail. (Even if it were 1/100, 325 runs is not enough to conclusively demonstrate a fix.)

What we need to do is have a patch that has only the repeated test runs, to try to prove the number of test runs is high enough to catch the random fail when combined with the fix. I know the JS tests take a long time so there's a risk of timing out. These patches are just a starter to see if 100 or 200 test runs will complete. Based on that, we can then queue enough runs to prove it will fail for the patch that completes, and then combine that with @droplet's fix to demonstrate the fix is actually fixing.

xjm’s picture

StatusFileSize
new628 bytes

200 ran in 30 mins on PHP 5.6, so looks like we can dial that up. If this one completes, then we run it against PHP7/MySQL 5.5 lots of times. (Running against other DBs is not necessary here.)

xjm’s picture

So the fact that the 400-run test passed demonstrated that 325 runs is not enough to demonstrate a fix.

I've queued the 400-run test-only patch many times. If none of them fail, then there are other factors influencing the fail rate (i.e. it's not just random) and so having multiple runs does not demonstrate coverage by itself anyway.

xjm’s picture

StatusFileSize
new1.9 KB

Okay, there we go. So now we combine that count with @droplet's fix to demonstrate whether it's fixing it.

xjm’s picture

Status: Needs review » Reviewed & tested by the community
StatusFileSize
new1.28 KB

Hooray, looking good so far. So here's @droplet's full patch again, and RTBC assuming none of the remaining runs in #17 show the fail.

droplet’s picture

StatusFileSize
new74.13 KB

I've checked the latest error log and I can't identify what problem that is.

Page seems loaded but there's a different log:

However, the next line is executed and no errors:

    $session->executeScript("document.getElementById('edit-title-0-value').style.marginBottom = '800px';");

the error message HTML is rendered before title field.

and the next different part is:

// Check that the CKEditor-enabled body field is currently not visible in
    // the viewport.
    $web_assert->assertNotVisibleInViewport('css', $ckeditor_id, 'topLeft', 'CKEditor-enabled body field is not visible.');

I guess that the CKEDITOR is not fully initialized. It's similar to #2843693: Random test failure in CKEditor AjaxCss. But, it can't explain why it will blocking the message checking.

So far, unless there's a hidden bug. The patch provided by me still the way to fix above 2 loading issues.

Thanks All.

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Committed and pushed 9a63547 to 8.4.x and 7e39aca to 8.3.x. Thanks!

  • alexpott committed 9a63547 on 8.4.x
    Issue #2864177 by xjm, droplet: Random failure in...

  • alexpott committed 7e39aca on 8.3.x
    Issue #2864177 by xjm, droplet: Random failure in...
lendude’s picture

But, it can't explain why it will blocking the message checking.

I'm happy to see this in, but I'm not happy that we haven't figured out why this is necessary. The need for waiting for a non-dynamic element to appear on page load feels weird, and I'd like to know when we would need to do this in other/future tests so we don't run into this again and again.

Or am I missing something obvious?

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.

xjm’s picture

@Lendude, best to file a followup issue? I know there was a discussion in Baltimore that I missed.

Moving the parent and fix issues to keep the list clean. Thanks!