Developing plugins for analysis – part IV

At the eXtreme365 conference in Lisbon, Portugal I did a session on plugin development with focus on adapting your code to empower the tracing and investigation features available in the Microsoft Dynamics 365 platform.
In this final article from that session I will dig deeper into how use the Correlation Id to trace plugin execution chains.

Missed the previous articles? Read the first, the second and the third.

Correlation

The Plugin Trace Log offers possibilities to track how execution of different plugins correlate to each other. This is done by identifying log records with same GUID in field Correlation Id.

The correlation id is described in the documentation as GUID for tracking plug-in or custom workflow activity execution, with remark used by the platform for infinite loop prevention, in most cases this property can be ignored.

This means that all trace log records originating form the same request to the platform will have the same Correlation Id. That information is very valuable during plugin analysis as you can follow exactly which user action that led to which plugins executing, and which plugins that executed as a result of the first plugins, and so on.

Plugin Trace Viewer

As I commented in a previous article – being humans makes us unfit to look at GUIDs. Plugin Trace Viewer compensates for that shortcoming, as correlation ids are converted to single capital letters.

Log records that are unique in their correlation id get no letter at all, indicating that this execution was not part of a greater chain of events. Note that the evaluation of correlated records is based on the current set of returned log records, based on given filter criteria.

Right-clicking on a log record brings up the context menu where you can see the actual GUID, add this correlation id to the filters, and select all records with this correlation id, to get a better visualization of which logs that are the result of the same originating request.

Demo 3 – Cherry picking the logs

When you need to analyze plugins in a heavily used [production] environment it can be quite hard to find the logs you are looking for. I will here demonstrate hands-on tips to make this a lot easier.

Setting up the environment

In my demo I added a couple of more plugins.

Copy address fields from account to relating contacts (with some conditions that contact did not have custom address)
Verify that State/Province is not automatically updated for contacts (this must be done manually on each contact)
Verify that Primary Contact on an account is not primary contact for another account
A plugin that forces SQL error by adding too long text in the mobile phone attribute of a contact

These are all available in the demo repository on GitHub. The plugins were tested and verified in different ways from CRM to generate logs needed for demonstration of the Correlation Id benefits.

Identifying the good cherries

The task was now to find out why the plugin that copies addresses failed intermittently. To do that, the following was done:

Set date interval to narrow down the logs to when the error occurred
Set filter for the plugin class to only get records related to the faulting plugin
Retrieve log records

Note that the Corr column is now usually empty, no two records from the same originating request are returned using this filter. And that is just fine.

Identify the log record from the execution you wish to investigate
Right-click and select Add correlation id to filter
Uncheck the filter for Plugin
Retrieve log records

We now get the 7 log records related to the problem with our account address copy plugin.

The first thing to notice is that two of these have the same exception thrown. Usually this means that one of the plugins caused (threw) it, and the other one was the plugin causing the throwing plugin to execute. In this case it is quite obvious, we have the AccountAddressToContacts plugin executing first, and the ContactPreventStateChange plugin has a Depth of 2, indicating it was executed as a result of another plugin executing.

So now we can focus on the plugin that actually caused the exception.

Chronology frauds

If you look at the log records above in detail, you notice that four of them have a timestamp at 9:52:28, and three of them 9:52:39. As mentioned in previous article, we cannot trust the chronology as milliseconds are not stored for the log records. (Please vote for this to change!)

Looking at the first four, we can use the Stage and Rank columns to get an indication of what the chronology should really look like. These plugins have probably executed in the following order (bottom to top) :

Unfortunately Plugin Trace Viewer cannot arrange the records in this order, with the missing milliseconds and order by constraints when composing the query.

Writing timestamps including milliseconds to the message block of the traces helps with the details. As I am using the JonasPluginBase that does this for me, I have all the details in the message block. Unfortunately there is no reasonable way to make that visible to sort by in the table. This means that sometimes you need to look at the details in the message block to be able to determine exact execution order of the plugins.

Removing not interesting cherries

Of the seven log records returned above, three are from the simple ContextLogger plugin. These records can easily be removed by adding filter !*ContextLogger for plugin name.

The exclamation mark before the plugin filter means “not”, and the asterisk is a wild card. So this filter translates to “Return all records where plugin does not end with ContextLogger”.