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.
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.
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.
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
When 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.