MigrateExecutable should add details for the migration & destination property to exceptions that cause a row failure

This is absolutely still an issue. I've been looking into the migration system for about a week, and I already lost count how many times I set a breakpoint in that place and then had to wait patiently for the migration to finally reach that point. Better logging could be a massive productivity boost.

I think we should bump #2959444: [Meta] Improve exception messages in process plugins to major instead of this. I only found that meta now.

+1 for adding information when the exception is caught, not when it is thrown.

I am making some minor edits to the issue summary.

A possible solution. Here is an example of the message, the result of testing with the extract process plugin
Migration 'default_language', destination 'default_langcode' Array index missing, extraction failed.

This will be better.

Adjust the tests that make assertions on the migrate message.

Patch attached tries to fix the last test error.

@DevJoJodae, thanks for making a patch. Sadly, we have duplicated work, that is I have made the same patch when I returned from dinner. Please have a look at the recent comments to figure out if someone is actively working on it so we can avoid this in the future. Thx.

Does this patch play well with #2969551: Migrate messages from caught exceptions need file and line details?

Surprisingly, the patch in #17 does not conflict with the current patch on #2969551: Migrate messages from caught exceptions need file and line details. (That issue has the same patch attached in #12 and #18.)

I will review this issue today, as part of DrupalCon Global.

1. This new property needs an @var comment.

    +++ b/core/modules/migrate/src/MigrateExecutable.php
    @@ -90,6 +90,8 @@ class MigrateExecutable implements MigrateExecutableInterface {
        */
       public $message;
   
    +  protected $destination;

2. Can we be more consistent here?

    @@ -205,7 +207,9 @@ public function import() {
           }
           catch (MigrateException $e) {
             $this->getIdMap()->saveIdMapping($row, [], $e->getStatus());
    -        $this->saveMessage($e->getMessage(), $e->getLevel());
    +        $migration_id = $this->migration->getPluginId();
    +        $msg = "$migration_id:$this->destination: " . $e->getMessage();
    +        $this->saveMessage($msg, $e->getLevel());
             $save = FALSE;
           }
           catch (MigrateSkipRowException $e) {
    @@ -213,7 +217,9 @@ public function import() {
               $id_map->saveIdMapping($row, [], MigrateIdMapInterface::STATUS_IGNORED);
             }
             if ($message = trim($e->getMessage())) {
    -          $this->saveMessage($message, MigrationInterface::MESSAGE_INFORMATIONAL);
    +          $migration_id = $this->migration->getPluginId();
    +          $msg = "$migration_id:$this->destination: " . $e->getMessage();
    +          $this->saveMessage($msg, MigrationInterface::MESSAGE_INFORMATIONAL);
             }

   If it were a few more lines, or if we did the same thing a third time, then I would want to add a helper function to be more DRY. Either of those might happen in the future. If we can be a little more consistent now, it will help when we decide to add that helper function.

   We should also get rid of the test for an empty message. Since we have useful information (the destination property and the current migration) we should save a message even if $e->getMessage() is empty.

   I wonder if we should use sprintf() instead of variables in double quotes. We are playing with messages from exception messages, and sprintf() is recommended there. But maybe this counts as a "foolish consistency". (As in the often misquoted "A foolish consistency is the hobgoblin of little minds.")

3. The updates to the tests are all straightforward. I think this means that our test coverage was already pretty good, and we just need to make the necessary adjustments when changing the messages.

4. We do not need redundant information. Most process plugins do not include $destination_property when they throw a MigrateException, but FormatDate, ImageStyleMappings, and StaticMap do. We can handle this in a follow-up issue if you prefer, but I think it is not too hard to do it as part of this issue. Curiously, BlockVisibility passes destination_property to sprintf(), but there is no matching %s. We should clean that up at the same time.

I also did some manual testing. I applied the patch to a recent project (Drupal 8.9.2) and tested drush mim d7_file --upgrade. As expected, drush mmsg d7_file shows a lot of messages like this:

d7_file:uri: File '...' does not exist

#21
1. Fixed
2. Improved and using sprintf
3. Nice
4. Fixed.

Good to know that manual testing shows this works.

I was wondering if removing the test for empty messages was going to cause an error (#21.2) and it does. Restoring that test.

I do not have time to look at it now, but this might be a case where we should fix the test instead fixing the "bug".

I've only got a moment...

If we change this then every MigrateSkipRowException will generate messages causing a lot of noise in the message tables. I think that is out of scope and we should discuss in another issue.

@quietone:

You convinced me! That part of #21.2 was at best out of scope. Probably it was simply a bad idea.

The rest of the changes look great. The additional changes to the tests after implementing #21.4 look good. Once again, it looks as though our test coverage is in pretty good shape.

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -213,7 +221,8 @@ public function import() {
@@ -361,6 +370,7 @@ protected function getIdMap() {

@@ -361,6 +370,7 @@ protected function getIdMap() {
    */
   public function processRow(Row $row, array $process = NULL, $value = NULL) {
     foreach ($this->migration->getProcessPlugins($process) as $destination => $plugins) {
+      $this->destination = $destination;
       $multiple = FALSE;
       /** @var $plugin \Drupal\migrate\Plugin\MigrateProcessInterface */

Is it really OK/necessary to keep overwriting $this->destination here in the foreach loop? I think it needs a comment if it is.

Following up @catch's question...

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -205,7 +212,8 @@ public function import() {
-        $this->saveMessage($e->getMessage(), $e->getLevel());
+        $msg = sprintf("%s:%s: %s", $this->migration->getPluginId(), $this->destination, $e->getMessage());
+        $this->saveMessage($msg, $e->getLevel());

@@ -213,7 +221,8 @@ public function import() {
-          $this->saveMessage($message, MigrationInterface::MESSAGE_INFORMATIONAL);
+          $msg = sprintf("%s:%s: %s", $this->migration->getPluginId(), $this->destination, $e->getMessage());
+          $this->saveMessage($msg, MigrationInterface::MESSAGE_INFORMATIONAL);

Get we use $destination->getPluginId() here instead of $this->destination and not add the property?

29. Changed the foreach to set $this->destination.
30. No, can't do that, sorry. Here $destination is the current destination property name on the process pipeline not a destination plugin.

Ignore previous patch, bad patch and numbered wrong too!

29. Changed the foreach to set $this->destination.
30. No, can't do that, sorry. Here $destination is the current destination property name on the process pipeline not a destination plugin.

Seems my cold is affecting me in more ways than I thought.

Restarting from reroll of patch #25.

Can this get any worse?

This is just a reroll

Now add the changes I tried to do way back in #31.

#29. Changed the foreach to set $this->destination.
#30. No, can't do that, sorry. Here $destination is the current destination property name on the process pipeline not a destination plugin.

Right, that won't work with the sub_process process plugin. How about adding a catch, saving the destination and throwing the exception.

oops x-post with #37 - I still think this approach is preferable.

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -90,6 +90,13 @@ class MigrateExecutable implements MigrateExecutableInterface {
+  /**
+   * The destination property name.
+   *
+   * @var string
+   */
+  protected $destination;

@@ -360,7 +369,7 @@ protected function getIdMap() {
-    foreach ($this->migration->getProcessPlugins($process) as $destination => $plugins) {

I don't think assignment like this works.

Plus there are way too many things called $destination here it's confusing. And adding it as a class property makes it stateful and look more useful than it is.

Here's an alternate solution that allows us to do this without the class property with a small amount of refactoring that also makes the code a bit simpler to read. Also it makes it obvious that at the earliest point an exception might thrown in $this->migration->getProcessPlugins($process) we might not get have a destination property name.

Interdiff is back to #34 since that is the last working version.

Lol forgot to remove the destination class property which was one of the aims - oops.

@alexpott, Yes, that is better. Thanks.

This is some changes to comments.

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -361,56 +366,77 @@ protected function getIdMap() {
+   *   (optional) Initial value of the pipeline for the first destination.
+   *   Usually setting this is not necessary as $process typically starts with
+   *   a 'get'. This is useful only when the $process contains a single
+   *   destination and needs to access a value outside of the source. See
+   *   \Drupal\migrate\Plugin\migrate\process\SubProcess::transformKey for an
+   *   example.

This needs to be modified as well but maybe tomorrow. $process isn't used here. It is from the doc block for proccesRow in MigrateExecutableInterface and references $process which isn't used here.

Simplify the documentation for the $value parameter, that is, don't repeat what is elsewhere, and add an @see.

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -199,13 +199,17 @@ public function import() {
+        $msg = sprintf("%s:%s: %s", $this->migration->getPluginId(), $destination_property_name, $e->getMessage());
+        $this->saveMessage($msg, $e->getLevel());

Instead, MigrateExecutable should prepend these messages with extra detail.

Why prepend structured information to an unstructured string/blob?

This is structured data. If this were saved as separate fields (migration_plugin_id and destination_property_name) in the migrate_message_* DB tables, then this would be much easier to search.

It'd also open the door for a single migrate_messages table, to allow searching all migration messages with a single query, rather than dozens (or even hundreds) of migration_message_* tables.

So IMHO this is doing the right thing, but in the wrong way.

AFAICT this is even literally repeating a subset of the table name (the asterisk in migration_message_*) for every row in that table? 🤭

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -199,13 +206,17 @@ public function import() {
       try {
...
+        foreach ($this->migration->getProcessPlugins() as $destination_property_names => $plugins) {
+          $this->processPipeline($row, $destination_property_names, $plugins, NULL);
+        }
         $save = TRUE;
       }
       catch (MigrateException $e) {
         $this->getIdMap()->saveIdMapping($row, [], $e->getStatus());
-        $this->saveMessage($e->getMessage(), $e->getLevel());
+        $msg = sprintf("%s:%s: %s", $this->migration->getPluginId(), $destination_property_names, $e->getMessage());
+        $this->saveMessage($msg, $e->getLevel());
         $save = FALSE;
       }

I don't know that we should include the potential exceptions thrown by ->getProcessPlugins() here with other migrate exceptions thrown when processing a row. That method doesn't depend on $row at all, so if it throws an exception (MigrateException or PluginException) it's going to continue to throw that exception for every row. I think if we catch an exception in that method, we should handle it separately and bow out of the migration.

In lieu of a response suggesting otherwise, back to NW for #43

Addressing #43. Looks to me like the current behavior is that if $this->migration->getProcessPlugins() throws an exception one will be thrown for every row. So, this changes that, for the better.

I meant to remove those lines. This should be better.

That leaves failing tests of MigrateExecutable. The unit test needed lots of method calls removed and the Kernel test found errors in the $return value. Should be sorted now.

Remove use of deprecated method,

I stray 'x' got into the file after I tested and while I was making the patch.

Just a reroll

Rerolling the latest patch. And add some details to the IS>

I wasn't on HEAD. Fix the coding standard error.

#55. When I rerolled the patch the change required was to add a use statement for Drupal\migrate\Plugin\MigrateSourceInterface in MigrateExecutable.

I am getting the same error described in #55 in a Drupal 9.1 installation. Migrate Tools 8.x-5.0 is installed which overrides the getSource method in its MigrateExecutable class. The method returns SourceFilter indeed.

Core's MigrateExecutable returns MigrateSourceInterface in its getSource implementation. This goes in line with the type hint in the doImport introduced by this patch.

AFAIKT, the return value from \Drupal\migrate_tools\MigrateExecutable::getSource is not in agreement with the parent class \Drupal\migrate\MigrateExecutable::getSource. How do we sort that out?

It could be the version of PHP

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -196,18 +195,56 @@ public function import() {
+  protected function doImport(MigrateSourceInterface $source, array $pipeline) {

For the purposes of this method, can we typehint on an iterator instead of the source interface? Probably not wise. See comments below.

The real solution is for the filter in migrate tools to get repaired. And maybe even in drush's new tooling? Looking at https://github.com/drush-ops/drush/blob/10.x/src/Drupal/Migrate/MigrateI..., it isn't quite the same thing. But it could suffer similar issues as we add typehinting. But that's another issue.

Suggested fix for Migrate Tools below:

<?php

namespace Drupal\migrate_tools;

use Drupal\migrate\Plugin\migrate\source\SourcePluginBase;
use Drupal\migrate\Plugin\MigrateSourceInterface;
use Drupal\migrate\Row;

/**
 * Class to filter source by an ID list.
 */
class SourceFilter extends \FilterIterator implements MigrateSourceInterface{

  /**
   * List of specific source IDs to import.
   *
   * @var array
   */
  protected $idList;

  /**
   * SourceFilter constructor.
   *
   * @param \Drupal\migrate\Plugin\MigrateSourceInterface $source
   *   The ID map.
   * @param array $id_list
   *   The id list to use in the filter.
   */
  public function __construct(MigrateSourceInterface $source, array $id_list) {
    parent::__construct($source);
    $this->idList = $id_list;
  }

  /**
   * {@inheritdoc}
   */
  public function accept() {
    // No idlist filtering, don't filter.
    if (empty($this->idList)) {
      return TRUE;
    }
    // Some source plugins do not extend SourcePluginBase. These cannot be
    // filtered so warn and return all values.
    if (!$this->getInnerIterator() instanceof SourcePluginBase) {
      trigger_error(sprintf('The source plugin %s is not an instance of %s. Extend from %s to support idlist filtering.', $this->getInnerIterator()->getPluginId(), SourcePluginBase::class, SourcePluginBase::class));
      return TRUE;
    }
    // Row is included.
    if (in_array(array_values($this->getInnerIterator()->getCurrentIds()), $this->idList)) {
      return TRUE;
    }
  }

  public function fields() {
    return $this->getInnerIterator()->field();
  }

  public function prepareRow(Row $row) {
    return $this->getInnerIterator()->prepareRow($row);
  }

  public function __toString() {
    return $this->getInnerIterator()->__toString();
  }

  public function getIds() {
    return $this->getInnerIterator()->getIds();
  }

  public function getSourceModule() {
    return $this->getInnerIterator()->getSourceModule();
  }

  public function count() {
    return $this->getInnerIterator()->count();
  }

  public function getPluginId() {
    return $this->getInnerIterator()->getPluginId();
  }

  public function getPluginDefinition() {
    return $this->getInnerIterator()->getPluginDefinition();
  }

}

Created an issue in Migrate Tools, #3212495: Change SourceFilter to implement MigrateSourceInterface and made a patch from #61.

A reroll.

Simple reroll to change order of parameters in assertEquals.

I haven't nailed down the "why" behind this, just reporting. I wanted some more details from the migrate_message tables, came across and applied this patch (which applies cleanly to 9.2.3, btw). After applying, a migration that had been running smoothly started throwing the following:

TypeError: Drupal\migrate\MigrateExecutable::doImport(): Argument #1 ($source) must be of type Drupal\migrate\Plugin\MigrateSourceInterface, Drupal\migrate_tools\SourceFilter given, called in /var/www/html/web/core/modules/migrate/src/MigrateExecutable.php on line 214 in Drupal\migrate\MigrateExecutable->doImport() (line 230 of /var/www/html/web/core/modules/migrate/src/MigrateExecutable.php).

The quick fix for me was to simply remove the type-hinting for the $source from this new function from the patch
protected function doImport(MigrateSourceInterface $source, array $pipeline)

The source, thanks to the new and improved debugging :) seems to be a section in the migration's process section like this

  field_info_links:
    -
      plugin: callback
      callable: array_filter
      source:
        - field_custom_info_block_1
        - field_custom_info_block_2
        - field_custom_info_block_3
        - field_custom_link_block
    -
      plugin: callback
      unpack_source: true
      callable: array_merge
    -
      plugin: skip_on_empty
      method: process
    -
      plugin: sub_process
      process:
        temporary_ids:
          plugin: migration_lookup
          migration: mymigration_info_links
          source: value
          no_stub: TRUE
        target_id:
          plugin: extract
          source: '@temporary_ids'
          index:
            - 0
        target_revision_id:
          plugin: extract
          source: '@temporary_ids'
          index:
            - 1

I think, based on the feedback in the error, that it just doesn't handle the possibly empty value being passed around by something like array_fiilter? Or is there something inherently wrong with the way I've assembled the pipeline for this field and it's just rearing its head because this code is an improvement? All in all, though it caused this error (or caused mine to surface?), the improved logging was both super-helpful while simultaneously enabling me to track down why this new issue was arising. :)

+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -196,18 +195,56 @@ public function import() {
+   * Imports all rows for the give n pipeline.

typo
s/give n/given

It is not as nice but this can be rearranged to not cause problems for MigrateTools.

I was sure I had run commit-code-check.

1. +++ b/core/modules/migrate/src/MigrateExecutable.php
   @@ -196,88 +194,113 @@ public function import() {
   +    if ($pipeline) {
   

   I think this if is not necessary. And if it is necessary how come? Is a migration with no pipeline valid?

2. +++ b/core/modules/migrate/tests/src/Kernel/MigrateMessageTest.php
   @@ -94,7 +94,8 @@ public function testMessagesTeed() {
   -    $this->assertSame("source_message: 'a message' is not an array", reset($this->messages));
   +    $id = $this->migration->getPluginId();
   +    $this->assertSame(reset($this->messages), "source_message: $id:message: 'a message' is not an array");
   

   The first param of assertSame() should be the expected message. So this swapping around is incorrect.

1. A migration with an empty process pipeline can be created, the process just needs to be an array. For example,

id: test
label: test migration
source:
  plugin: embedded_data
  data_rows:
    -
      id: 1
      slogan: My site
  ids:
    id:
      type: string
  source_module: system
process: []
destination:
  plugin: config
  config_name: system.site

(9.3.x)$ ddev drush ms test
 ------------------- -------------- -------- ------- ---------- ------------- --------------------- 
  Group               Migration ID   Status   Total   Imported   Unprocessed   Last Imported        
 ------------------- -------------- -------- ------- ---------- ------------- --------------------- 
  Default (default)   test           Idle     1       0          1             2021-10-11 10:14:20  
 ------------------- -------------- -------- ------- ---------- ------------- --------------------- 
(9.3.x)$ ddev drush mim test
 [notice] Processed 0 items (0 created, 0 updated, 0 failed, 0 ignored) - done with 'test'

2. Fixed.

I was doing a self review here when I noticed an unused variable.
+++ b/core/modules/migrate/src/MigrateExecutable.php
@@ -196,88 +194,113 @@ public function import() {
+ if ($message = trim($e->getMessage())) {

$message is not used. And further, I could not find a test of the catch block this is in. So, I wrote a test, actually just tagged a bit on to an existing kernel test.

Committed 8616edd and pushed to 9.3.x. Thanks!