[random test failure] Random failures building media library form after uploading image (WidgetUploadTest)

"It fails only on testbot"...this is a magic phrase that made me summon the sorcerer known as @Mixologic.

@bnjmnm, @oknate and I discussed this issue with him on Slack. TL;DR: the best lead we have, at the moment, points to this being a potential race condition. The major difference between running the tests on localhost with PHPUnit, and running them on testbot, is that testbot runs tests in parallel and PHPUnit doesn't. So, as @Mixologic said:

now, this particular test is definitely exercising some very weird not-like the real world at all [behavior].
essentially 15 people all using the same browser at the same time to upload a lot of the same filename.
and all going through some pachinko machine of webdriver abstractions to do it.
so the first thing I'd check is whether or not it still fails with just 1 concurrency.

I would suggest, as a next step, that this test be run locally with run-tests.sh, which is what runs the tests in parallel. If it fails locally with that, we can be even more sure that our upload woes are caused by a race condition.

More info from @Mixologic:

the other things I think to check on is make sure that there isnt any conflict in the filenames that are being uploaded.
or rather that they are all unique and not constantly trying to upload 'test.png' again and again.
Because I think that this whole pipeline can inadvertantly test things like "how does the browser handle renaming files on its own filesystem"

Reroll of #7

Oops, patch failed to attach last time. Here's the patch. It updates the test to use "Save" button and removes an unused variable.

Testing reloading the page between uploads. I'm curious if this will help. Given that this fails sometimes on Sqlite on the first iteration, I'm not sure if this will help. But if helps a little, perhaps it's part of a multifaceted solution.

Interesting: reloading the page between iterations doesn't help. So it's probably a back-end issue, not the media library JavaScript. Given that it works under 40 times more consistently, perhaps just breaking up the tests so we never hit more than forty uploads would help.

This time, instead of using the same container, I'm getting a new one. Also, I'm using $this->container->get('file_system')->copy instead of copy.

Trying longer wait time, replacing 10000 with 30000 to see if it makes any difference.

I noticed that $file_system->copy returns a filepath, so using that. Also, I added the timestamp as a prefix in uniqid(). Let's see if returning the actually file path from copy helps.

Seeing if deleting files makes a difference.

Also, I noticed there are duplicate files, perhaps there are finite limits on how many images can be uploaded on testbot? when you hit 80 uploads, it gives up.
https://www.drupal.org/files/issues/2019-10-31/duplicate-images.png

It uploads them in the files directory, then copies it to files/type-four-dir

Weird, it seems to have made a slight difference (Postgres failed on 47 instead of 45). This cleans up the temporary file at the end of each iteration.

redacted. I realize now my comment was not valid.

Adding a check on the file_managed table to see if it increments. I tested locally with sqlite and it worked up to 49, then I stopped the test. So this should give a little more info about how far along the process it goes before failing before the alt text failure we've been seeing.

Turning on db log and checking for any messages from file_managed_file_save_upload().

Dang, had a really dumb error on #24, updating.

The output from this test, where there are no log messages means that it's most likely failing before file_managed_file_save_upload(), or perhaps it's failing in that function where there is no logging.

Adding more logging to file_managed_file_save_upload, and a fallback error message if there are no logs.

Update, this tells us it's exiting at the beginning of file_managed_file_save_upload(), here, even when it works correctly, so we don't need to look at that function any more, so next, let's look at what calls it ManagedFile::valueCallback().

This is very interesting, because when I run this locally, it is not exiting at the beginning of file_managed_file_save_upload().

It gets passed this part:

if (empty($all_files[$upload_name])) {
    return FALSE;
  }

Clue:

More on #26, on my local, here's the output of $all_files[$upload_name] right at the beginning of file_managed_file_save_upload

This is very interesting because this is empty and exiting the function on testbot here:

if (empty($all_files[$upload_name])) {
    return FALSE;
  }

But on my local it is not empty. So this is a helpful clue as to what's different on testbot vs local. (Remember it doesn't fail locally.)

There must be an alternate way the images are attached that doesn't use file_managed_file_save_upload.

Adding more logging output to ManagedFile::valueCallback to try to figure out what's happening.

I get the same output on my local (in reverse cron order), see ManagedFile::valueCallback (in the patch)

message: fids empty, line 164 in ManagedFile
variables:  a:0:{}
message: $element['#extended'] FALSE
 variables:  a:0:{}
message: Input is FALSE in ManagedFile::valueCallback()

Clearing out messages when a run was successful and adding some spacing.

forgot execute() on truncate:

-      $database->truncate('watchdog');
+      $this->container->get('database')->truncate('watchdog')->execute();

Trying $this->resetAll() to see if cache clearing makes any difference. Also, I changed my mind about clearing out previous log messages. I think they're helpful.

Ok, here's another clue:

FileUploadForm::uploadButtonSubmit isn't hit when it fails, but is hit when it succeeds.

Adding more logging.

Adding a bit more logging. I want to see if updateFormCallback is called on the last iteration.

Oops, serialize was blowing up. Removing for now. Although it would be good to get some info about the upload.

Another clue:
::updateFormCallback is not called on the last iteration.

Removing the 'type' filter on the watchdog messages. Perhaps something else will come up. Hopefully it won't be too much output.

Adding more logging around the backtrace leading up to FileUploadForm::uploadButtonSubmit, since we know it's not called on the failed iteration, but that the BE is being hit as it calls ManagedFile::valueCallback.

fixing the failure I introduced in the last patch and adding file size output.

adding logging of form_state values near where it's failing.

Update:
At least based on the logging I've added, it seems to fail after FormBuilder calls $this->formSubmitter->doSubmitForm for the "Apply filters" button.

Last iteration before it fails:

$form_state->getValues(): @"name":"","submit":"Apply filters","sort_by":"created","form_build_id":"form-PsYu15H1LhnEfQUfKMQ0g9Krgq7qqNxMYlhEH7BSgCo","form_id":"views_exposed_form","":"Apply filters"
Renderer calling setCurrentRenderContext
FormBuilder calling $this->formSubmitter->doSubmitForm
$form_state->getValues(): @"show_view_elements":true,"submit":"Insert selected","media_library_select_form":["47",0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"media_library_select_form_selection":"47","form_build_id":"form-dV02yaBMkIm2MwPE9fLewxc-uNbsGm2UPyHhVAdm6Lg","form_token":"cmd2BIvTIC06ML_tDD9RsLXzCeJstkQ3Zvds1qIzy8w","form_id":"views_form_media_library_widget_type_four","op":"Insert selected"
Renderer calling setCurrentRenderContext
FormBuilder calling $this->formSubmitter->doSubmitForm
$form_state->getValues(): @"field_twin_media":{"media_library_update_widget":"Update widget","field_twin_media-media-library-update":"Update widget"}
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext
FormBuilder calling $this->formSubmitter->doSubmitForm
$form_state->getValues(): @"field_twin_media":{"selection":[{"preview":{"remove_button":"Remove","target_id":"47","weight":"0"}],"media_library_open_button":"Add media","media_library_selection":"","media_library_update_widget":"Update widget"},"field_twin_media-0-media-library-remove-button":"Remove"}
Renderer calling setCurrentRenderContext

Last failing iteration:

$form_state->getValues(): @"name":"","submit":"Apply filters","sort_by":"created","form_build_id":"form-YDfW8bHcEtdHgki_1N06SZwrg0ytDmkl7JhwBMw49MY","form_id":"views_exposed_form","":"Apply filters"
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext
Renderer calling setCurrentRenderContext

testing disabling the "Apply filters" button since it looks like it's submitting around where it's failing.

ignore this one, was missing the change I was trying to add.

removing the exposed filters to test if that makes a difference.

Adding logging info about the file in NegotiationMiddleware::handle

Update:

this seems to indicate that that when it fails it fails very early in the stack, because NegotiationMiddleware::handle isn't hit the second time, like the other iterations.

• Removing logging of 'Renderer calling setCurrentRenderContext' for now
• adding a few other log messages
• using temporary file directory.

Update: on my local the temporary file worked, but it doesn't here. So we should remove that change or figure out how to get it to work.

Marking #3103492: Random fail in WidgetUploadTest as duplicate.

This is failing very, very often. Should we mark the test as skipped until there's a viable patch here?

Per @bnjmnm, this is now also the cause of many, many random fails in CKEditor 5 tests, e.g.:
https://www.drupal.org/pift-ci-job/2238883

This has more than doubled our random fail rate following beta1.

I was actually monitoring this too, and was pleasantly surprised that we still don't have any random fails on MySQL: https://www.drupal.org/pift-ci-job/2238957. Never any random fails on the contrib project either!

It can’t be a concurrency problem either, because these are FunctionalJavascript tests, and they run with concurrency level 1 both in contrib and core. Aha, core runs these with concurrency 15! So that could be it … but only on PostgreSQL then. Could be some locking/conflict thing?

But … we didn’t have tests against PostgreSQL in the contrib module. So that is likely to be slower somehow? 🤔 The random fail does not seem to be random at all, but ALMOST consistent, on PostgreSQL, with the vast majority of test runs crashing like this:

Testing Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5Test
.....E..                                                            8 / 8 (100%)

Time: 2.91 minutes, Memory: 6.00 MB

There was 1 error:

1) Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5Test::testEditorFileReferenceIntegration
Behat\Mink\Exception\ElementNotFoundException: Element matching xpath "//img[@src="/subdirectory/sites/simpletest/16481256/files/inline-images/image-test.png" and @loading="lazy" and @width and @height and @data-entity-uuid="718d3b72-2867-490e-9e8c-c49801754718" and @data-entity-type="file"]" not found.

/var/www/html/vendor/behat/mink/src/WebAssert.php:418
/var/www/html/core/tests/Drupal/Tests/WebAssert.php:968
/var/www/html/core/modules/ckeditor5/tests/src/FunctionalJavascript/CKEditor5Test.php:390
/var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:703

That is the last line of this chunk of code:

    $assert_session->assertWaitOnAjaxRequest();
    $page->pressButton('Save');

    $uploaded_image = File::load(1);
    $image_url = $this->container->get('file_url_generator')->generateString($uploaded_image->getFileUri());
    $image_uuid = $uploaded_image->uuid();
    $assert_session->elementExists('xpath', sprintf('//img[@src="%s" and @loading="lazy" and @width and @height and @data-entity-uuid="%s" and @data-entity-type="file"]', $image_url, $image_uuid));

… there's not even any JS/AJAX involved there! So let's add some debug output.

I downloaded the artifacts from the Postgres run at https://dispatcher.drupalci.org/job/drupal_patches/103942/artifact/jenki...

There are 45 files output with an <img> tag in them; of these 30 look correct (e.g. <img data-entity-uuid="4ee93afa-6380-47c1-89da-603a2915c88c" data-entity-type="file" src="/subdirectory/sites/simpletest/19350594/files/inline-images/image-test.png" alt="&lt;/em&gt; Kittens &amp; llamas are cute" />) but the other 15 are just empty <img /> tags with no attributes.

Example: https://dispatcher.drupalci.org/job/drupal_patches/103942/artifact/jenki...

Opened new issue for #52 since it was likely unrelated. Also reverting the title change.

#55: that is consistent with the findings in #3250587: \Drupal\Tests\ckeditor5\FunctionalJavascript\CKEditor5Test::testEditorFileReferenceIntegration fails on PostgreSQL!

Drupal\Tests\ckeditor5\FunctionalJavascript\MediaLibraryTest is failing pretty consistently on SQLite - see https://www.drupal.org/pift-ci-job/2268909 - given SQLite is the fastest test environment we have this suggests there's a timing issue in this test.

Hi @all here,

I am facing this Media Library Browser race condition issue in UI: #3174361: Media Library modal opens randomly on AJAX requests

TL;DR: Opening / Closing (paragraphs) modals very fast a few times leads to unexpected calls to MediaLibraryWidget::openMediaLibrary() from request parameters that should not exist. So the Media Library Modal is randomly opened on race conditions, if just the Media Library Widget is present on the page (but never clicked!).

There are strange things going on with the #ajax handling and the subsequent requests, when clicking fast, as I documented in the issue. As there are several similarities and both seem to be caused by a race condition, I thought the issues might be related or have the same cause. Perhaps finding one reason also fixes the other problem. Could someone with a deeper understanding of the AJAX / Commands handling in core have a look and give an opinion?

I'm sorry, if I'm wrong, and they're unrelated.

1500x is too much in one go, whenever a patch like this hits the 50+ minutes, "wonky" things happen.
Let's see if we can keep it below that in a 1000x patch

Fails on the test runs with and without #3350972: [random test failure] Drupal\Tests\layout_builder\FunctionalJavascript\LayoutBuilderUiTest::testReloadWithNoSections(), so that's not the solution for this one.

I believe this random test failure doesn't appear anymore.
To prove this, we need about 5000-8000 runs failure-free runs of the suspicious test.

Let's try that here. I use 500 runs in one patch, since any time the repeated runs of this test get's over 45 minutes, things get "wonky" and unreliable. The 500x run should finish within 30-35 minutes.

The fails are

upal\Core\Installer\Exception\InstallerException: Resolve all issues below to continue the installation. For help configuring your database server, see the installation handbook, or contact your hosting provider.Failed to connect to database. The database engine reports the following message: SQLSTATE[HY000]: General error: 5 database is locked.Does the database file exist?Does web server have permission to write to the database file?Does the web server have permission to write to the directory the database file should be created in?

we can just ignore that IMO, looks solid otherwise.

we can just ignore that IMO, looks solid otherwise.

Agreed, this "somehow" happens (randomly) when running single Functional(Javascript)Tests a lot of times.
Seen this happen on a lot of my fix-the-bloody-random-failure-and-run-it-500+-times patches and they are (at the very least) not related to the test that is the SUT.

As far as I'm concerned: This random test failure is gone (for now).

Unsure what should happen with this issue.
I've seen older similiar issues being closed as cannot reproduce. If needed they can be found in the search and reopened (See for example #2980750: [random test failure] Random failure in CommentStatisticsTest)

Yep, let's close as cannot reproduce, and this can be reopened if it starts appearing again.

Thanks for looking into this.