Fix harvest migration message logging for batched migrations

[rhabbachi]

Message (including various types like info, warning, error) logging during harvest migrations broke after the introduction of the "batched" migrations #2075. The logID is generated too late during the process and the messages were not being assigned to the migration being ran. This affected the "Errors" tab for the Harvest Source as all the errors gathered for a said source are stacked and displayed without any association with the Harvest Migration event.

(fig. 1)

This PR updates the HarvestMigration class and the harvest batch function to restore the migration logID generation and presist the migration object during batch calls.

(fig. 2)

How to reproduce

1. Create a Harvest Source with a source known to generate errors.
2. From the DKAN Harvest Dashboard, trigger the batch cache and migrate of the added source multiple times
3. Check "Errors" tab on the Harvest Source page.

Expected:
Errors grouped per harvest event (listed on the "Events" tab). See fig. 2.

Actual
Errors stacked under the same 01/01/1970 entry. regardless of the Harvest Migration events. See fig. 1.

Merge process

• N/A.

Reminders

• There is test for the issue.
• Coding standards checked.
• Review docs.getdkan.com (or in /docs) to see if it still covers the scope of the PR and update if needed.

[rhabbachi]

@janette Had another go at this and caught some cases where it did not really fix the problem. The
5477079 commit should work much better.

The trick is to add the mlid (Migration log ID, $logID property of the HarvestMigration class) of the first batch run to the context and set it on the next Migrations. This will keep all the errors encountered during a migration linked to the same mlid.

[rhabbachi]

@janette commit c44ef54 is my take on #2819 that I mentioned on Slack. I had to update the *Helper function signature to return the message to the caller method and report it. There is also the messages queue mechanism implemented by the migrate module (but not used that much) that we can use to defer the saving of messages reported too early in the process until we have a valid logID.

I used the https://open.fda.gov/data.json source to test, and all the messages reported by the migration process are saved to the log table instead of being rendered on on the UI.

The remaining messages are not from dkan_harvest but from dkan_datastore if I'm not mistaken, I would be much harder to intercept those messages and maybe we don't need to do it? What do you think?

[janette]

@rhabbachi this is great stuff here, and I think you are right let's not deal with the datastore messages on this one, we can make some adjustments on the datastore separately. I'm concerned that the harvest status says 'ERROR', because the harvest does complete, but has errors on the resources. How hard would it be to add a column for 'Errors', so the status could still say 'OK' once the harvest completes, and the error column would be 'yes or no' and if yes, the yes is a link to the log.

And I'm guessing the phpunit tests need updating. :)

[janette]

@rhabbachi what if we scratch my additional column idea and instead under status it would list one of these:

• Finished with errors
• Finished
• Failed

[rhabbachi]

@janette Yeah I like the 2nd suggestion better.

Was out of commission as I just finished migrating to a new work machine. Planning on taking a look later today.

[rhabbachi]

@janette Still work in progress but this is the direction I'm taking for the status. The gist is that we are outgrowing the boolean View field handler views_handler_field_boolean_harvest_status.inc since we need to support 4+ status now (Finished with errors, Finished, Failed, Unknown) so I'm reworking the logic in the handler. Also adding support for migration in progress which should address the 2nd point on #2416.

The "failed" is not well supported, I will do more testing on this later next week.

[janette]

@rhabbachi right maybe 'failed' is not quite right, I think 'N/A' is what we get now? something to indicate it is not finished I guess, 'in progress' or 'stuck' .... staying with 'N/A' would be fine if we create a new ticket to work out the finer points of the status. Really appreciate your work on this.

[rhabbachi]

@janette Alright progress! I added a test to see if all the datasets tracked failed (count of the datasets recorded in the map table against the failed count), if all the datasets failed the import then the status is shown as.. failed.. This should work well when the source is lost or have problems.

I also added the "New" status for harvest migrations that were not executed before (no MLID).
I moved the code around a little bit and added more checks for the db_query calls.

Also to me 'N/A' sounded either new or unknown, since we support both now I dropped it from the returned status.

Interestingly, we can't really know if a Migration is stuck, it's either in progress or idle. I guess that should be left to the user's judgement (been showing as in progress for 3 days for example).

So to summarize:

• Finished with errors.
• Finished.
• Failed (All the datasets failed).
• In Progress.
• New (never executed).
• Unknown (failed to fetch status)

How does that sound? Also any idea about the color coding? 😄

[janette]

@rhabbachi sounds fantastic - very informative status values 😄
color ideas:

[rhabbachi]

@janette had to add a views token to the custom handler to have reliable css classes to target. But it should be working now!

Unfortunately I don't know have access to sources that will reproduce the other status, do you have examples that you test this?

[rhabbachi]

Looking at the phpunits errors, seems like we are getting some pathauto errors. Not sure about the origin of those errors :( I remember seeing similar errors reported during a real harvest

Any idea on why those errors are happening?

[dharizza]

Hi @rhabbachi,
I've been looking into these PHP Unit errors and I found that the extra error messages we are getting are the Cannot look-up the harvest source Node ID, so for having these tests passing I just deleted the following code from dkan_harvest.migrate.inc:

if (!isset($result['node'])) {
  // Something is wrong.
  $message = t('Cannot look-up the harvest source Node ID');
  $this->reportMessage($message);
}

At the end that code isn't really needed as we are checking later in the process for the existence of the harvest source and the user still get the message Items to import is 0. Looks like source is missing. No updates can be made at this time. when there is no source node available.

[rhabbachi]

Hey @dharizza!

Off the top of my head. I think the Cannot look-up the harvest source Node ID message is legitimate. The harvest source nid is needed to load the source state (current datasets for publishing and unpublishing, etc).

What are the other errors that you found? From the screenshot in my previous comment I got a multiple suspect MigrateException from pathauto. Did you get something similar?

[dharizza]

Yes, but comparing with the results from 7.x-1.x they are legit, and it is fine for them to be there according to the test files we are using. The differences are really on the Cannot look-up the harvest source Node ID, on 7.x-1.x I didn't got those when running php unit tests. And yes, you're right, they are legit but we are handling that later in the code, 5 lines after the code I removed we have:

if (isset($result['node'])) { // Here we load it if it exists
  $harvest_source_nids = array_keys($result['node']);
  $this->dkanHarvestSourceNid = array_pop($harvest_source_nids);
  $this->dkanHarvestSourceNode = node_load($this->dkanHarvestSourceNid);
}
else { // Here we handle when there is no source node
  $this->dkanHarvestSourceNid = FALSE;
  $this->dkanHarvestSourceNode = NULL;
}

And later in the code, we use that to tell the user there wasn't a source, so I think it is fine if we just get rid of it. I run the php unit tests with that change locally and they all passed, also did some manual testing and it worked ok.

Now, this part is just a theory: I'm not sure if this is related to the movement of $this->logHistory = FALSE; to before that first reportMessage. I think having that logHistory at the begining of the construct is fine, but I can do some more testing with this on 7.x-1.x to see if we get same issue.

[rhabbachi]

I see.

This change:

if (isset($result['node'])) { // Here we load it if it exists
  $harvest_source_nids = array_keys($result['node']);
  $this->dkanHarvestSourceNid = array_pop($harvest_source_nids);
  $this->dkanHarvestSourceNode = node_load($this->dkanHarvestSourceNid);
}
else { // Here we handle when there is no source node
  $this->dkanHarvestSourceNid = FALSE;
  $this->dkanHarvestSourceNode = NULL;
}

Should've replaced this snipped.

if (!isset($result['node'])) {
  // Something is wrong.
  $message = t('Cannot look-up the harvest source Node ID');
  $this->reportMessage($message);
}

When the 7.x-1.x was merged into this branch. But since I introduced the change at $this->reportMessage($message); it did not, I think it should've returned a merge conflict at least.

Your reasoning is correct @dharizza IMO! Thanks for spotting the subtle change!

[rhabbachi]

Ah wait! Seems like it was not deleted from the 7.x-1.x actually https://github.com/GetDKAN/dkan/blob/7.x-1.x/modules/dkan/dkan_harvest/dkan_harvest.migrate.inc#L131