Missed the previous articles? Read the first, the second and the third.
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.
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.
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.
In my demo I added a couple of more plugins.
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.
The task was now to find out why the plugin that copies addresses failed intermittently. To do that, the following was done:
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.
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.
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.
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”.
This is the final article in a series about plugin development for analysis, based on my session at eXtreme365 in Lisbon.
To access presentation and code follow the links below:
JonasPluginBase repository: https://github.com/rappen/JonasPluginBase
JonasPluginBase package: https://www.nuget.org/packages/Rappen.Xrm.JonasPluginBase/
eXtreme354-2017-Plugin repository: https://github.com/rappen/eXtreme365-2017-Plugin
Labels: Community, Conferences, Open Source, Plugin, Tools