Investigation into random fails in \Drupal\migrate_drupal_ui\Tests\d7\MigrateUpgrade7Test

How do you view the HTML? Just run this patch locally?

Botched the last patch, this one removes the trait name change.

Just one of those mornings...

OK, so the last patch was missing the instrumentation I meant to add, and it didn't work anyway, so now testing locally *this* one will actually log the start of each migration process to watchdog...

Queued with various PHP/db combos - maybe there's some combo that's more likely to hit the failure (or even one that's reproducible...).

  'message' => 'Beginning d7_comment_field_instance',
  'message' => 'Upgraded Comment field instance configuration (processed 6 items total)',
  'message' => 'Beginning d7_comment_entity_form_display_subject',
  'message' => 'Upgraded Comment subject form display configuration (processed 6 items total)',
  'message' => 'Beginning d7_comment_entity_form_display_subject',
  'message' => 'Upgraded Comment subject form display configuration (processed 0 items total)',
  'message' => 'Beginning d7_comment_entity_form_display',
  'message' => 'Operation on @migration failed',
  'message' => 'Migration d7_comment_entity_form_display is busy with another operation: Importing',
  'message' => 'Beginning d7_comment_entity_display',
  'message' => 'Upgraded Comment display configuration (processed 6 items total)',

So, somehow, d7_comment_entity_form_display is busy the first time it is attempted... The two runs of d7_comment_entity_form_display_subject must be related, but I don't see how we get in this state.

More instrumentation (capturing the setting of the status). Also, since we see d7_comment_entity_form_display_subject executing first in the failures, but in my local successes I see d7_comment_entity_form_display execute first, setting a dependency to see if that triggers more consistent failures.

Oops - using dblog (a requirement of migrate_drupal_ui but not of migrate) in migrate broke the other tests. And also making the migration dependency required broke a test, making that optional now...

Very interesting - now d6_upload is the busy one (in both the test failures). The sequence of events (where a status of 1 is IMPORTING and 0 is IDLE):

Immediately before d6_upload, this is what a normal migration looks like:

'message' => 'Beginning d6_upload_entity_display',
'message' => 'Setting d6_upload_entity_display status to 1',
'message' => 'Setting d6_upload_entity_display status to 0',
'message' => 'Upgraded Upload display configuration (processed 2 items total)',

Starting the upload migration:

'message' => 'Beginning d6_upload',
'message' => 'Setting d6_upload status to 1',

Here's where we break - d6_upload did not complete in a normal way, and we're picking up from d6_upload_entity_display again:

'message' => 'Beginning d6_upload_entity_display',
'message' => 'Setting d6_upload_entity_display status to 1',
'message' => 'Setting d6_upload_entity_display status to 0',
'message' => 'Upgraded Upload display configuration (processed 0 items total)',
'message' => 'Beginning d6_upload',
'message' => 'Operation on @migration failed',
'message' => 'Migration d6_upload is busy with another operation: Importing',

And onward without further event:

'message' => 'Beginning d6_node_setting_sticky',

So, it seems some non-catchable event occurs while d6_upload is running, and a new batch is started with $context['sandbox']['migration_ids'] set back to where it was before d6_upload_entity_display completed. I have to wonder how batch API works in the test environment - is there some timeout happening that forcefully aborts one page of the batch and restarts with the last recorded sandbox?

Betcha this one fails consistently - not even going to queue up 6 copies this time...

Heh, this very problem is blocking the test running...

Anyway, it's looking to me like the root problem isn't anything in migration code, it's simply the length of time the upgrade test takes.

Adding the sleep(10) got me my first local failure, thought it would be a slamdunk to reproduce here - queued up a few more tests, let's see what our hit ratio is.