[Random test failure] Random failure in CKEditor5AllowedTagsTest::testMediaElementAllowedTags

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.

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? 😔

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().

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.

Didn't work 😬

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.

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.

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

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

Never going to say no to improving the random failures.

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 👍

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.

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.

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

Thanks, @Spokje, including for the wonderful metaphor 😄

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