Problem/Motivation

From the eternal random failure gold mine that is the qa runs (https://www.drupal.org/node/3060/qa):

There was 1 error:

1) Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5AllowedTagsTest::testMediaElementAllowedTags
Behat\Mink\Exception\ElementNotFoundException: Form field with id|name|label|value "filters[media_embed][settings][allowed_view_modes][view_mode_2]" not found.

/var/www/html/vendor/behat/mink/src/Element/TraversableElement.php:207
/var/www/html/core/modules/ckeditor5/tests/src/FunctionalJavascript/CKEditor5AllowedTagsTest.php:386
/var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:728

https://www.drupal.org/pift-ci-job/2696423

Steps to reproduce

This one had me searching for a while...

Over here I took a screenshot and dumped the HTML when the ElementNotFoundException is thrown.

The screenshot shows that view_mode_2 is actually not present, there's no AJAXing going on, and the page looks (and turns out to be) completely loaded:
CLUNK
(HTML as txt-file is here)

As it turns out, we start the test by going to the 'admin/config/content/formats/add' page in \Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5TestBase::createNewTextFormat, do some stuff and then create two new EntityViewModes.

This can be appearantly to slow for the page to pick up on it, or at least sometimes to pick up on the last of the two, which then does not get displayed when we enable the embed media option.

Proposed resolution

Move the creation of the two new EntityViewModes to the front of the test.

Also, as already said in #7, the waitForField without checking its output is basically a convuloted way to add a sleep.

We remove it, replace it with a $assert_session->assertWaitOnAjaxRequest(), since the line before it ($page->clickLink('Embed media')) triggers an AJAX request.

Finally we remove the $assert_session->assertWaitOnAjaxRequest() below the two checkFields in line 387-388, since they don't trigger any AJAX request and waiting on that is useless.

Remaining tasks

User interface changes

API changes

Data model changes

Release notes snippet

Comments

Spokje created an issue. See original summary.

spokje’s picture

StatusFileSize
new22.51 KB

Let's first proof that running Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5AllowedTagsTest::testMediaElementAllowedTags and Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5AllowedTagsTest::testMediaElementAllowedTags alone produces the random test failure.

Here's a patch that runs only Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5AllowedTagsTest::testMediaElementAllowedTags 1500 times.

wim leers’s picture

Thank you, @Spokje! 🤩🙏

We spent so much time and effort making sure the tests were passing reliably. It's sad to see that there's still random failures :/ When we were iterating rapidly in https://www.drupal.org/project/ckeditor5, we chased every random JS test failure to ensure that this wouldn't be a problem once it was in core.

Then again … even a Chrome version update can change this, so I guess it's not too surprising that we're able to detect new random failures later? 😔

wim leers’s picture

Status: Active » Needs review
StatusFileSize
new997 bytes
new22.99 KB
1) Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5AllowedTagsTest::testMediaElementAllowedTags
Behat\Mink\Exception\ElementNotFoundException: Form field with id|name|label|value "filters[media_embed][settings][allowed_view_modes][view_mode_2]" not found.

seems to consistently be the failure.

This is the context:

    $page->clickLink('Embed media');
    $assert_session->waitForField('filters[media_embed][settings][allowed_view_modes][view_mode_2]');
    $page->checkField('filters[media_embed][settings][allowed_view_modes][view_mode_1]');
    $page->checkField('filters[media_embed][settings][allowed_view_modes][view_mode_2]');
    $assert_session->assertWaitOnAjaxRequest();
 

That's … fascinating. We're literally first waiting for the field to appear, and only then checking the fields.

My suspicion: the checking of the first field triggers a new AJAX request, which makes the checkbox briefly uncheckable. So we need to explicitly wait before each checkField().

needs-review-queue-bot’s picture

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

The Needs Review Queue Bot tested this issue. It fails the Drupal core commit checks. Therefore, this issue status is now "Needs work".

This does not mean that the patch needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide to find step-by-step guides for working with issues.

wim leers’s picture

Didn't work 😬

spokje’s picture

Then again … even a Chrome version update can change this, so I guess it's not too surprising that we're able to detect new random failures later? 😔

JS random test failures are the latest and the greatest, most commonly due to changes in the speed of the testrunners.
Surprisingly not because they got so much faster, but since they get way slower...

That's … fascinating. We're literally first waiting for the field to appear, and only then checking the fields.

Even more fascinating, when the wait doesn't find the element, it returns NULL, when that's not checked anywhere, like in this test, since there's no execption thrown, the test continues (and finds out 2 lines below the element we were waiting on isn't present.

My suspicion: the checking of the first field triggers a new AJAX request, which makes the checkbox briefly uncheckable. So we need to explicitly wait before each checkField().

Sadly it isn't, looking into it during today/tomorrow.

spokje’s picture

StatusFileSize
new22.51 KB
new24.65 KB

The normal routine to prove a random failure is fixed is to run the failing patch and the patch with the fix at the same time, whilst the latter has to have ~8000 - 10.000 failure free runs to prove it's credibility.

So let's do that here.

spokje’s picture

Issue summary: View changes
StatusFileSize
new185.25 KB
new166.16 KB
spokje’s picture

Turns out 5000x doesn't finish within about an hour, after which the results get "wonky".

Let's do it in 2500x runs.

spokje’s picture

StatusFileSize
new2.08 KB

That's 12 * 2500 = 30.000 failure free runs.

Good enough for me, here's the actual patch.

spokje’s picture

Assigned: spokje » Unassigned
Issue summary: View changes
Status: Needs work » Reviewed & tested by the community
spokje’s picture

Status: Reviewed & tested by the community » Needs review
smustgrave’s picture

Status: Needs review » Reviewed & tested by the community

Never going to say no to improving the random failures.

wim leers’s picture

  1. +++ b/core/modules/ckeditor5/tests/src/FunctionalJavascript/CKEditor5AllowedTagsTest.php
    @@ -350,8 +350,6 @@ public function testMediaElementAllowedTags() {
    -    $this->createNewTextFormat($page, $assert_session);
    -
         EntityViewMode::create([
           'id' => 'media.view_mode_1',
           'targetEntityType' => 'media',
    @@ -366,6 +364,9 @@ public function testMediaElementAllowedTags() {
    
    @@ -366,6 +364,9 @@ public function testMediaElementAllowedTags() {
           'enabled' => TRUE,
           'label' => 'View Mode 2',
         ])->save();
    +
    +    $this->createNewTextFormat($page, $assert_session);
    +
    

    This part I do not understand. 🤔 Why does this need to be moved? 🤯

    AFAICT this should not be necessary.

  2. +++ b/core/modules/ckeditor5/tests/src/FunctionalJavascript/CKEditor5AllowedTagsTest.php
    @@ -382,10 +383,9 @@ public function testMediaElementAllowedTags() {
    -    $assert_session->waitForField('filters[media_embed][settings][allowed_view_modes][view_mode_2]');
    +    $assert_session->assertWaitOnAjaxRequest();
         $page->checkField('filters[media_embed][settings][allowed_view_modes][view_mode_1]');
         $page->checkField('filters[media_embed][settings][allowed_view_modes][view_mode_2]');
    -    $assert_session->assertWaitOnAjaxRequest();
    

    This part I get: after enabling a filter, rather than just waiting for a field to appear via AJAX, wait for everything to have finished for said AJAX response 👍

spokje’s picture

This part I do not understand. 🤔 Why does this need to be moved? 🤯
AFAICT this should not be necessary.

Did you see this from the IS?

As it turns out, we start the test by going to the 'admin/config/content/formats/add' page in \Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5TestBase::createNewTextFormat, do some stuff and then create two new EntityViewModes.

This can be appearantly to slow for the page to pick up on it, or at least sometimes to pick up on the last of the two, which then does not get displayed when we enable the embed media option.

Was hoping that would explain things, if not, am happy to (try and) be more explicit.

The key here. IMHO. is the fact that in the current situation we're already on the 'admin/config/content/formats/add' page, before we create the EntityViewModes.
That somehow sometimes doesn't give us/the page enough time to "realize" it has two rather than one EntityViewMode to show when we click he embed media option.

This part I get: after enabling a filter, rather than just waiting for a field to appear via AJAX, wait for everything to have finished for said AJAX response 👍

Yep, I really dislike the use of waitFor[Stuff]($timePeriod).

For me it's like when you have to pick somebody up from the train station and you go there and wait for a certain amount of time, then no matter what, you continue with your other business. Even if the train arrives one second later.
So waitForPerson(20 minutes)

Whilst when you know _what_ you're waiting for, it's less random. In the above anology: If the person doesn't come out of the train which you expected them to be on, move on.
If the train's early or late, no problem, because you're not tied to a set amount of time.
So

waitForTrain($certainTrain)

is much less prone to random test failures when there's outside stuff messing with the trainschedule (or in our case, testrunners).

quietone’s picture

Doing RTBC triage.

@Spokje, thanks for working on this and finding a solution!

The IS uses the respective heading to explain the problem and the solution. Reading the comments all the question raised have been answered.

Leaving at RTBC.

  • lauriii committed 1b920b29 on 11.x
    Issue #3368509 by Spokje, Wim Leers, quietone: [Random test failure]...

  • lauriii committed 68f57554 on 10.1.x
    Issue #3368509 by Spokje, Wim Leers, quietone: [Random test failure]...
lauriii’s picture

Version: 11.x-dev » 10.1.x-dev
Status: Reviewed & tested by the community » Fixed

Committed 1b920b2 and pushed to 11.x. Also cherry-picked to 10.1.x as a test only change. Thanks!

wim leers’s picture

Thanks, @Spokje, including for the wonderful metaphor 😄

Status: Fixed » Closed (fixed)

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