Comments

tim.plunkett created an issue. See original summary.

alexpott’s picture

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

mikeryan’s picture

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

penyaskito’s picture

lokapujya’s picture

Happens here consistently. #2719171 Never fails locally.

alexpott’s picture

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.

alexpott’s picture

Status: Active » Needs review
FileSize
542 bytes

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

alexpott’s picture

Status: Needs review » Needs work

The last submitted patch, 9: 2724871-9.patch, failed testing.

alexpott’s picture

Status: Needs work » Needs review
FileSize
1.18 KB

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

lokapujya’s picture

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.

Status: Needs review » Needs work

The last submitted patch, 11: 2724871-11.patch, failed testing.

lokapujya’s picture

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

mpdonadio’s picture

Version: 8.2.x-dev » 8.1.x-dev

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.

alexpott’s picture

Priority: Major » Critical

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

claudiu.cristea’s picture

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

tetranz’s picture

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

lokapujya’s picture

Status: Needs work » Needs review
FileSize
437 bytes

Try to log the HTML.

lokapujya’s picture

Try another way.

alexpott’s picture

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.

alexpott’s picture

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

alexpott’s picture

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

alexpott’s picture

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

mikeryan’s picture

  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.

xjm’s picture

Issue tags: +Random test failure
alexpott’s picture

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

Status: Needs review » Needs work

The last submitted patch, 28: 2724871-28.patch, failed testing.

alexpott’s picture

Status: Needs work » Needs review

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

mikeryan’s picture

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.

alexpott’s picture

mikeryan’s picture

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

heddn’s picture

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

alexpott’s picture

Status: Needs review » Fixed

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

Status: Fixed » Closed (fixed)

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