Random failure in \Drupal\migrate_drupal_ui\Tests\d7\MigrateUpgrade7Test

I've run this 20 times locally and no fails :(

Are there any stats suggesting how often it fails (1% of the time, 10%, etc.)? Would suggest how many times one might need to run the tests and expect to see at least one failure...

The failing test is for the message displayed at the end of the process - locally, I've got the page content it's testing preserved in files like Drupal_migrate_drupal_ui_Tests_d6_MigrateUpgrade6Test-10-20.html, is this captured (or can we capture) that on the testbot and see what the actual page content is?

Here's a (very) recent failure: https://www.drupal.org/pift-ci-job/285501

Happened again at https://www.drupal.org/pift-ci-job/286121

Also #2225271: Migrate content type language settings from Drupal 6 & 7: https://www.drupal.org/pift-ci-job/285489

Happens here consistently. #2719171 Never fails locally.

Discussed this with @dawehner - he noted that one of the things that might be introduced randomness into the test is that the what runs each batch step is random depending on time and memory usage.

let's see it we can get it always to fail in 20 tests...

Maybe just 40 is enough and we don't need to do the other test.

#2682585: Rename MigrationCreationTrait as it no longer creates migrations - it configures them seems to fail consistently.

Do we have a way to do what @mikeryan requested?

Drupal_migrate_drupal_ui_Tests_d6_MigrateUpgrade6Test-10-20.html, is this captured (or can we capture) that on the testbot and see what the actual page content is?

I think we basically need the debug output that we are able to get when running locally.

Oh, I forgot: The problem is we can't consistently reproduce it, NM.

So, we CAN reproduce it on 8.1 easy. Now we need the debug so that we can see the HTML.

Moving this back to 8.1.x since that branch is showing random fails: https://www.drupal.org/pift-ci-job/289977

Defer to others whether that makes this a critical. It's easy now to ignore fails and work on other issues.

Given the frequency and disruptive nature this is most certainly a critical.

This test failed twice with this error https://www.drupal.org/pift-ci-job/295763. It doesn't seem very random.

In case this helps, my test that @claudiu.cristea linked to above works on 8.2.x

I don't know if it's random but it worked on 8.1.x until I changed core/modules/field/tests/src/Kernel/Migrate/d7/MigrateFieldFormatterSettingsTest.php which added 'target_entity_type_id' => 'node' when creating comment types.

https://www.drupal.org/files/issues/interdiff-2717673-16-20_0.txt

Try to log the HTML.

Try another way.

So on my test issue I've managed to view the html... #2729713: Investigation into random fails in \Drupal\migrate_drupal_ui\Tests\d7\MigrateUpgrade7Test and prove that the migration that is failing is the 'Comment field form display configuration' migration ie. d7_comment_entity_form_display. I'm guessing we have a missing dependency somewhere and the order when not working is different than when it is.

So the error that is being thrown is "Migration d7_comment_entity_form_display is busy with another operation: Importing" which is logged on MigrateExecutable::import() Line 172 or so...

According to @mikeryan:

That suggests that either A. that migrate failed in the middle so the status didn’t get reset, or B. a second migration started in parallel

|  55 |   1 | migrate_drupal_ui | Upgraded Comment type (processed 6 items total)                                    | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040407 |
|  56 |   1 | migrate_drupal_ui | Upgraded Comment field configuration (processed 6 items total)                     | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040409 |
|  57 |   1 | migrate_drupal_ui | Upgraded Comment field instance configuration (processed 6 items total)            | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040410 |
|  58 |   1 | migrate_drupal_ui | Upgraded Comment subject form display configuration (processed 6 items total)      | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040411 |
|  59 |   1 | migrate_drupal_ui | Upgraded Comment subject form display configuration (processed 0 items total)      | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040412 |
|  60 |   1 | migrate_drupal_ui | Operation on @migration failed                                                     | a:1:{s:10:"@migration";s:40:"Comment field form display configuration";} |        3 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040412 |
|  61 |   1 | migrate_drupal_ui | Migration d7_comment_entity_form_display is busy with another operation: Importing | a:0:{}                                                                   |        3 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040412 |
|  62 |   1 | migrate_drupal_ui | Upgraded Comment display configuration (processed 6 items total)                   | a:0:{}                                                                   |        5 |      | http://localhost/checkout/batch?id=2&op=do_nojs |                                  | ::1      | 1464040413 |

Here's the watchdog table - it looks like the migrate has indeed been fired twice?!?!? Entry 58 looks like a successful migration and 59,60,61 is the second attempt going wrong.

1. Upgraded Comment subject form display configuration (processed 6 items total)
2. Upgraded Comment subject form display configuration (processed 0 items total)
3. Operation on @migration failed | a:1:{s:10:"@migration";s:40:"Comment field form display configuration";}
4. Migration d7_comment_entity_form_display is busy with another operation: Importing

So, we're seeing d7_comment_entity_form_display_subject run twice (doing nothing the second time, because it's already done its work). Following that, d7_comment_entity_form_display fails because somehow its status is IMPORTING, implying it previously started and had some catastrophic failure (or, there's some bug in resetting the status). Since the reporting is only done upon return from $executable->import(), we seem to be missing a failed attempt to start that import - I've added logging before the import() call to #2729713: Investigation into random fails in \Drupal\migrate_drupal_ui\Tests\d7\MigrateUpgrade7Test, let's see what that tells us about when each migration is kicked off.

This patch fixes the issue and brings MigrateUpgradeRunBatch into line with _batch_process() when dealing with progressive batches.

I don't know why #28 fixes the issue but I think the change is the right change to make anyway because:

• Making a user wait for a long time when the batch is progressive is wrong. That's why _batch_process() behaves the way it does.
• Fixing this random fail is important as it is affecting testing of every issue - we can continue to explore the root cause in #2737599: Remote git bisect for random failure in \Drupal\migrate_drupal_ui\Tests\d7\MigrateUpgrade7Test.

The one fail so far in #28 it unrelated... Views.Drupal\Tests\views\Kernel\Handler\FilterStringTest

Some IRC chatter on the performance implications of reducing the batch length to 1 second:

mikeryan1: alexpott: So, each batch will run for only 1 second? That’ll really slow things down (paying the overhead, particularly running the source query, so frequently)
alexpott: mikeryan1: well there's a tension - between the feedback of the progress bar and how much is done
mikeryan1: Ah well, no one in their right mind will run a big migration through the UI anyway
alexpott: mikeryan1: exactly!
mikeryan1: https://www.drupal.org/node/1806824
Druplicon: https://www.drupal.org/node/1806824 => Why you should run migrations in Drush rather than the UI => 0 comments, 1 IRC mention
alexpott: mikeryan1: That should be linked from the UI
alexpott: mikeryan1: otherwise how can someone new to the system know
mikeryan1: There is a risk with a short batch of the migration stalling (once you get well into a large source query, it may take that second just scrolling to look for an unimported row
mikeryan1: alexpott: Sure, updated for D8 of course

We should probably do at least some informal performance testing to see how much slower it is in practice, and if stalling occurs with moderately-sized sites (perhaps we could at least go to 5 seconds?). A D8 copy (basically, omitting the last two sections) of the drush/UI performance page should be added to the core migrate docs. Linking it from the UI should probably wait until https://github.com/drush-ops/drush/issues/2140 is in, though.

So it looks like this is caused by #2694391: Separate cache bin for migrations - we should revert it. The patch attached does that.

FWIW, I did some manual performance testing with the 1-second batch patch using my D6 personal blog (304 users, 86 nodes, 51 files, 1109 aliases for some reason...). Three trials each, without the patch the average time was 3:39 (for comparision, with drush migrate-upgrade the average was 2:48). With the patch, the average of successful completions was 6:10, and changing the batch length to 5 seconds the average of successful completions was 4:19. I say "successful completions" because each of those cases failed once with a 500 error - going to the "error page" (home page) showed the normal success messages ("Congratulations..." etc.), and dblog had no errors, just the last migration completed (vocabularies in one case, vocabulary display configuration in the other).

I can confirm that the cache backend does cause issues. See #2736789: Default of 'migration' database key is ONLY thing that works

Reverted the issue that caused this #2694391: Separate cache bin for migrations