We create XrmToolBox tools at Dynamics 365 Saturdays!

Jonas Rapp creating XrmToolBox tools at D365 Saturdays

The community of developers for Microsoft Dynamics 365 / CRM in general and for XrmToolBox in particular is a great bunch of people. But I wish there were more of us – the more the merrier ?

The D365 Saturday phenomenon with pro bono speakers at a full day event, free of charge for participants, has spread like wildfire over the last couple of years.
The connection to the XrmToolBox is obvious:

  • Both were started by CRM heroes (Raz for the Saturdays and Tanguy for the toolbox).
  • Both are driven by a passion to share and a love for the platform.
  • Both do these things without any ambition to “get rich quick” (or ever).

I got an idea to combine these two phenomena.

Continue reading “We create XrmToolBox tools at Dynamics 365 Saturdays!”

We created an XrmToolBox tool at Dynamics 365 Saturday Stockholm!

Last Saturday some 100+ experts, partners and user of Microsoft Dynamics 365 met up at the Microsoft offices in Stockholm, Sweden for a day packed with content at the Dynamics 365 Saturday event.

I delivered two sessions at the event, and in one of them I took on a somewhat challenging session called

Let’s build an XrmToolBox tool!

Continue reading “We created an XrmToolBox tool at Dynamics 365 Saturday Stockholm!”

FetchXML Builder and Friends at D365UG Virtual Summer Camp

On August 7-9, the first ever Virtual Summer Camp for the Dynamics 365 platform will take place.

During this free event the D365UG offer some 30+ sessions with focus on Customer Service and Field/Project Service.

I will be doing one of a few cross vertical sessions, where I discuss and demonstrate some useful XrmToolBox tools that help customizers, administrators and users with information analysis and enhancing the capabilities of the system.

Below is a description of my session – enjoy and make sure you sign up! Click the link: D365UG Virtual Summer Camp

Continue reading “FetchXML Builder and Friends at D365UG Virtual Summer Camp”

Five ways to improve Quality and Productivity of Dynamics 365 development

a.k.a – Once I did a session twice

Just like last year in Lisbon, I did a developer focused session during eXtreme365 in Dubrovnik. Last year I had full focus on how to develop plugins for analysis, primarily using the Plug-in Trace Log in the code and how to best analyze the results of it.
This year I took a bit wider approach with an ambition to help developers become more productive and get higher quality of their code. In this article I will go through the five different areas I covered in the session.

Continue reading “Five ways to improve Quality and Productivity of Dynamics 365 development”

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.


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

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

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

  1. Set date interval to narrow down the logs to when the error occurred
  2. Set filter for the plugin class to only get records related to the faulting plugin
  3. 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. image

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

We now get the 7 log records related to the problem with our account address copy plugin. image 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) : image 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. image 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: Presentation: http://tiny.cc/eXtremePluginDev 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

Developing plugins for analysis – part III

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.
This is the third article from that session where the Plugin Trace Viewer is explained.

Missed the first articles? Read the first and the second.  

The Plugin Trace Viewer

This tool in the “industry standard” XrmToolBox was created to make the potential power of the Plugin Trace Log available to anyone. image The log contains so much information that can make plugin analysis a lot easier, if presented in an intelligent way.  

Key features

In Plugin Trace Viewer (PTV) the user is empowered by a few different key features:

imageMore and relevant information

All relevant fields from the Plugin Trace Log is displayed; Correlation Id, Start Time, Duration, Operation, Plugin, Depth, Mode, Message, Entity. If an exception was thrown, PTV extracts the actual error message from the exception details text block and shows that directly in the Exception column. The Plugin Step that triggered the plugin is not related with a regular relationship, only the guid of the step is stored. PTV can still use this to display which Stage and Rank the step has. This is relevant when analyzing exact order of execution.

Smarter filtering

image PTV allows filtering of all relevant information. This includes Execution Time, Plugin Type, Message, Entity, Operation Type, and Mode. You can also specify Execution Duration limits to identify long-running plugins or if there are many small atomic plugins that might benefit from being combined into fewer all-purpose plugins. It is possible to only show records from plugin executions that ended with an exception being thrown. Finally it is also possible to filter by Correlation Id. In the last article in this series, I will go deeper into working with Correlation Id to follow execution chains and how plugins correlate to each other.


The form layout of PTV provides an easy way to select which columns to display (right-click the table headers to select columns) and sizable quick-view windows for the Message Block and Exception Details multiline fields. It is possible to turn word wrap on or off for these. To maximize utilization of the form the Filter panel can be hidden.

imagePlugin Type Statistics

CRM collects life-time statistics for all plugins. This contains execution count, failure count, average execution time, and different crash numbers. When a log record is selected in PTV, the Plugin Type Statistics for that plugin is retrieved and displayed. To get an idea of how much impact a plugin has on the system, PTV also calculates average execution time per day as:
  AvgExecTime * ExecCount / (ModifiedOn – CreatedOn)


The Plugin Trace Log offers many opportunities for analyzing your plugins. There are however still a few challenges to overcome.

Exact Execution Time

All datetime fields in the log are displayed with date, hour and minute in CRM. In the database they are saved with second, which is displayed in Plugin Trace Viewer. Unfortunately the millisecond part of these timestamps are always zero. This makes it really difficult, and sometimes impossible, to know the exact order of execution between plugins. I have submitted a CRM Idea to also include milliseconds, vote this up if you would like to see that too!

Full Trust plugins

According to the SDK documentation claims that “Tracing is supported for sandboxed (partial trust) and full trust registered custom code”, but as a handful forum threads out there disappointingly conclude, this is not the case. This means you currently have to register your plugins in Sandboxed partial trust to get anything written to the Plugin Trace Log, with the limitations that means to your plugin execution. If I am not the only one who would like the functionality to live up to the expectations in the documentation, vote this CRM Idea up!

10k Limit on Message Block

The Message Block field is limited by CRM core code to 10k characters. When writing more text, it will be truncated from the top. For complex plugins with verbose logging, this poses a problem to the analysis. The reason to put a limit is quite viable, but I sure would like this limit to be configurable for my organization. There is another CRM Idea to make this happen!

Resetting Plugin Type Statistics

The Plugin Type Statistics entity only supports two messages; Retrieve and RetrieveMultiple. This means there is no way to reset the statistics for a plugin. After refactoring your code, it sure would be nice to be able to reset the statistics to evaluate behavior after the improvement. Vote to have Microsoft make this possible!

Demo 2 – PTV at a glance

In this demo I created a simple plugin that verifies that the fax field has not been entered on the entity triggering the plugin. The plugin uses the JonasPluginBase class to make development easier and get a lot of tracing for free. The code is really simplistic and looks like this:

    public class NoFaxPlease : JonasPluginBase.JonasPluginBase
        public override void Execute(JonasPluginBag bag)
            // Read updated value for Fax from Target entity
            string fax = bag.TargetEntity.GetAttributeValue("fax");

            if (!string.IsNullOrWhiteSpace(fax))
                throw new InvalidPluginExecutionException($"Fax? Really? This is {DateTime.Now.Year}, you know... ");

            // Get name of the record that triggered the plugin
            string recordName = bag.CompleteEntity.Name(bag, false);
            bag.Trace("No fax for {0}, this {1} is ready for the future.", recordName, bag.PluginContext.PrimaryEntityName);

The plugin produces an error message like this if enything is entered in the fax field:
Looking at the log in Plugin Trace Viewer shows this information:

10:30:30.007	*** Enter
10:30:30.007	[JPB] Context details:
  Step:  eXtremePlugins.NoFaxPlease: Update of  any Entity
  Msg:   Update
  Stage: 10
  Mode:  0
  Depth: 1
  Corr:  c3d58faf-f9ed-496d-b53d-63e6711bfe89
  Type:  account
  Id:    1bcc51ab-58fe-e611-80fb-5065f38b2601
  User:  9cc6ecfd-cce1-4bd5-8832-20e476f776e1
  IUser: 9cc6ecfd-cce1-4bd5-8832-20e476f776e1

10:30:30.085	[JPB] Incoming account
  accountid = 1bcc51ab-58fe-e611-80fb-5065f38b2601 (Guid)
  fax       = 123456 (String)

10:30:30.085	BEGIN Microsoft.Xrm.Sdk.InvalidPluginExecutionException
10:30:30.085	  [JPB] Microsoft.Xrm.Sdk.InvalidPluginExecutionException: Fax? Really? This is 2017, you know... 
   at eXtremePlugins.NoFaxPlease.Execute(JonasPluginBag bag)
   at JonasPluginBase.JonasPluginBase.Execute(IServiceProvider serviceProvider)
10:30:30.085	END Microsoft.Xrm.Sdk.InvalidPluginExecutionException
10:30:30.085	[JPB] Internal execution time: 6 ms
10:30:30.085	*** Exit

The JonasPluginBase code is available at GitHub and as NuGet package. The plugin sample is available at GitHub.

In the fourth article in this series, I will dig deep into the possibilities of tracing execution chains, events triggering events, and how to follow the breadcrumb trail in our logs using the Correlation Id.

Continue to final article in this series!

Developing plugins for analysis – part II

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.
This is the second article in a series to describe the essence of that session.

Missed the first article? Read it here.

The Plugin Trace Log

The Plugin Trace Log is basically an entity in CRM. One trace log record contains details about one plugin execution. The entity has a number of fields that describes some “hard facts” about the execution, such as start time, duration, entity and message that triggered the execution and other details from the execution pipeline. It also contains a field called Message Block, and this is where your own custom logging information ends up. This is where you tailor your style of logging, this is where it gets interesting. Finally if the plugin caused or threw an exception, the Exception field contains information about the exception that was thrown, as well as anything written to the Message Block. This field contains the same information as that you get from the CRM UI when an error message has been shown and you click the Download log file button. The Plugin Trace Log can be found in CRM if you go to Settings – Customization – Plugin Trace Log.


Investigating the Plugin Trace Log in CRM is unfortunately quite discouraging. The default view is missing some painfully obvious columns, such as which Entity that triggered the plugin writing the record and the Execution duration. But you do see the column Is system generated, which should be quite obvious. (When would you manually create Plugin Trace Log records? Why?) imageIf you open Advanced Find to make the view work a little better for you, you realize that some things just cannot be done. You cannot filter the view by triggering entity. You cannot see in which stage it executed. You cannot filter to only display logs with exceptions or duration to identify long running plugins. When you look at the form, you see four fields that show you guids. We are human beings looking at this form, and we are not made for looking at guids! The four fields are Persistence Key, Plugin Step Id, Correlation Id and Request Id. These really tell you nothing, especially since they are only visible on the form, if you stretch it some of these guids might be useful when looking for patterns over multiple trace log records (an example of this will be given in the next article where we use the Correlation Id to track chains of events).


When using the Plugin Trace Log, there are some parameters to consider.

  • Always on
    The performance impact of having the trace activated is small from a user perspective as the trace log records are written asynchronously. But it does affect the database size.
  • Recurring delete job
    Make sure there is a recurring bulk delete job that removes older trace log records. CRM provides a default job that deletes records older than one day, once a day. This can of course be adjusted to fit your needs, but make sure you have thought this through.
  • Logging verbosity
    How much should your plugins write to the message block? More detail helps you better, but there is also a 10k limit to this field, where the text is truncated from the top when it exceeds 10k. You can vote on this CRM Idea to make this limit configurable.
  • Sandboxing
    Currently only sandboxed plugins write to the Plugin Trace Log. Plugins in isolation have tighter limits for execution time and trust level. SDK documentation still claims it should work for both partial and full trust plugins. Vote for this CRM Idea to make that true.

imageDemo 1 – OOTB features

During the first demo I showed how features around the Plugin Trace Log in the CRM UI.
How to activate the log, the default view, what possibilities you have to create your own views within CRM, and the standard form for the entity. Unfortunately there really is nothing from the demo on out of the box Plugin Trace Log investigation worth more space on this blog than the image to the right.   Instead I will dedicate the next article in this series to the Plugin Trace Viewer in XrmToolBox.

Continue to next article in this series!

Developing plugins for analysis – part I

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.
ICYMI: This article is the first in a series to describe the essence of that session.

image I was quite surprised to see a crowd of about 60 attendants, of which most were developers already focusing on plugin development.
There is evidently a demand for the deep techy sessions at events such as eXtreme365, where most sessions have a distinctly “higher” perspective on the platform. The fact that this session attracted more people than my competitors on the technical track in this time slot (three sessions led by Matt Barbour, Roger Gilchrist and Julie Yack) makes it even more obvious – “nerdy” sessions like this are really appreciated!
Links to presentation and code are published in the last post in this series, go there now.

Injecting code into a black box

Like many other developers in the Microsoft Dynamics 365 Customer Engagement (okay I can’t write that every time, from now on I will simply do as Matt B still does – call it CRM) community I come from a background of “normal” development, doing winform applications and the occasional web app. The transition to development in CRM quickly gives you a feeling of not being in control anymore. There is a big black box which is the CRM core, and we develop code that is injected into this box in the form of plugins triggering on events firing in the platform. As long as you stay “supported” there is no way around this. And the more we move to cloud based environments, the darker the black box gets.

imageCreate your radiation

What we can do though is to send out some signals from the black box. Just like Stephen Hawking came up with a theory that black holes are not entirely black, they actually emit “Hawking radiation” that contains information about the black hole characteristics, we can implement our code to generate our own Hawking radiation. Then we just need to know how to use the right tools to pick up these signals.

Investigation options

To investigate plugin behavior you basically have two options; you debug in Visual Studio (direct) or you look at logs (indirect). Debugging is “direct” as you step though the code line by line as the plugin executes, whereas looking at logs is “indirect” since you are only looking at the results or the history – the radiation – of plugins being executed.

Investigation by debugging code

Debugging comes with some challenges. I will mention a couple of these. If you have an on premise environment and access to the server, you can attach VS to a server process and start debugging your plugin as it executes on the server. This will block all other execution, so this obviously cannot be done in a production environment. Another option is to use the Plugin Profiler to record the context where a plugin got triggered, to replay it with debugging in Visual Studio. In both these scenarios you have to try to reproduce the circumstances under which the plugin executed in production. Usually you don’t have exact copies of production to work with, so the context will be somewhat different. A problem with debugging that many times is being overlooked is that debugging a plugin can be like watching quarks. When systems under load behave unexpectedly, plugins execute more or less simultaneously, different parts of your code start interacting in ways you did not intend. Trying to debug this will change that behavior, as pausing execution of one plugin will automatically reduce the amount of “simultaneousness” amongst the plugins. Just like when you observe elementary particles their behavior can change just by being exposed to the photons introduced to see them.

Investigation by analyzing logs

imageWhen you analyze logs you cannot see the code executing as during debugging, but you have unaltered “evidence” of what has happened. If debugging can give you alt-facts due to the quark-watching issue and context mimicking challenges, the logs contain true fact-facts. To get usable logs you obviously have to make sure you write relevant and structured information when you add tracing to your code. You definitely should use some kind of wrapping classes to make this easier and to get a uniform logging style. The Server Trace File can be activated for on premise installations. The file is not very “user friendly”, even if there are tools to help you interpret and find information in the file. There is also really no way to add your own logging information to the file, instead it contains tracing information from the CRM core operations. The Plugin Trace Log introduced in CRM 2015 Update 1 can be activated in any environment without (?) negative performance effects, so it is really useful when analyzing behavior even in production environments.   The next article in this series will focus on the Plugin Trace Log, and how you can make it really work for you.

Continue to next article in this series!