The Milliseconds Are Here!

Ever since I started using the Plugin Trace Log for investigation of my plugins around three years ago, I have wondered why we don’t have timestamps with better granularity than seconds.
As I expressed it in an article from 2017:

Given the CPU power we have today, it is just incomprehensible why we should not get more detail in the timing of plugin execution.
It is like defining my age by saying I was born sometime during the second half of the 20th century.

From A Canary in CRM
Continue reading “The Milliseconds Are Here!”

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”

A canary in CRM

Have you ever faced a situation when you don’t know why your Microsoft Dynamics 365 Customer Engagement system behaves the way it does, or why your own plugins behave the way they do?

If you have, this might be a good time to put a canary in your system.

– A what?
– A canary. 

You know when we were manually laboring down the coal mines, it happened that drilling into the rock inadvertently let out poisonous gas. So we brought in cages with canary birds putting their life at stake, to save our coal miners’ lives. The canaries were signaling the content of the atmosphere long before the coal miners would detect something dangerous. They did this by suddenly being upside down, instead of happily chattering.

As a plugin developer of many years, I have added extra tracing to my plugins more times than I can count and sometimes even added steps for more messages than necessary, and I am sure most of you reading this post have too, in one way or another.

Continue reading “A canary in CRM”

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

References

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.

Layout

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)

Challenges

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

CRM UX

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

Considerations

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!

I get by with a little help from my [base class]

Developing plugins for Microsoft Dynamics 365 (CRM) only using bare SDK libraries make you do the same stuff over and over.
This is why one of the first things I did when starting to work with the platform was to create a helping hand in the form of a plugin base class, implementing IPlugin.

This class soon evolved to a library implementing our own organization service, custom file logging, encapsulate our translation and configuration management entities, and tons of other useful stuff that helps me and my colleagues develop plugins and integration services so much faster and easier than without it. Development speed aside, it makes our code more readable and easier to follow, as most of the background activities are performed in the same way. Another benefit is that if optimizations to the backing libraries are possible, we can ship the improvements with a few simple clicks to all of our products and customer projects by just publishing a new version of our private NuGet packages, instantly available to any and all consumers. As these libraries have evolved over the versions, beginning with Microsoft Dynamics CRM 4.0, they quite naturally contain some technical debt, which for me as responsible developer translates to bad sleeping patterns and a nagging feeling that one day I want to rip it all out and rewrite everything. In our day to day work, we improve on the libraries, but want to keep breaking changes to a minimum, which by definition can only increase the debt.  

I saw the light

Average winter day in SwedenThen a few months ago, the clouds parted and I got a glimpse of the light – I was invited to speak at the CRM Saturday event in London to tell my story about XrmToolBox and how I use it to simplify development on the Dynamics platform. If I was to do this I really wanted to show my own favorite tool; the Plugin Trace Viewer which has helped me and my colleagues time after time after time when analyzing plugin behavior. I didn’t want the demo to go with bare SDK, and I didn’t want to bring in our bloated DevUtils dinosaur. So this gave me an opportunity to start over, to create a more minimalistic plugin base class that helps with the things I need most:

  • Extract plugin context
  • Get a service to work with
  • Initialize tracing service
  • Always write details and timing information to the trace when using the service
  • Provide easy access to target entity, pre image and post image

 

JonasPluginBase

I rather quickly had something that was good enough for a demo, to get a feeling for the benefits of working this way and to make a habit of writing to the trace log. And it didn’t take long until I thought someone else might actually find this useful. So I went public. However, my Swedish humility tells me that things can always be made better than how I make them. I do know a little about a few things, but I am definitely no wizard in C# technicalities like interfaces, inheritance and other stuff making development more efficient, so going open source with my little library was the only way to go. I hoped that if anyone actually picked it up, it might go from my little hack to a really professional library. You can find it here: https://github.com/rappen/JonasPluginBase The repository contains two projects, one containing “the library” and one containing some sample plugins and custom workflow activities.  

How does it work?

I would like to think that this sentence says everything you need to know:

Inherit class JonasPluginBase instead of implementing the IPlugin interface.

But maybe a few more words are necessary after all.

Adding the package

The JonasPluginBase library is available as a package on NuGet. Add it to the project, and install updates to dependent packages if there are any available. image To make this library available on the server executing the plugin, you can use ILMerge to merge your plugin assembly with the JonasPluginBase assembly. An instruction is published here, and a sample post-build event could look like this:

ILMerge.exe /keyfile:....mysignature.snk /target:library /copyattrs /targetplatform:v4,"C:WindowsMicrosoft.NETFrameworkv4.0.30319" "/out:$(TargetName).Merged.dll" "$(TargetFileName)" "JonasPluginBase.dll"

I think it is convenient to include ILMerge by adding the ILMerge NuGet package to my project and adding the ILMerge.exe from the package folder as a reference, with Copy Local = True. When this is done you can use the build event sample above.

Creating a plugin

First you need to implement the abstract method Execute.
image
This method gets a parameter of type JonasPluginBag. This is a bag packed and ready for anything (well almost) you might want to do in your plugin!

The techy details

This class exposes the following public methods and properties:

        public IPluginExecutionContext PluginContext { get; }
        public IWorkflowContext WorkflowContext { get; }
        public JonasServiceProxy Service { get; }
        public JonasTracingService TracingService { get; }
        public Entity TargetEntity { get; set; }
        public Entity PreImage { get; } 
        public Entity PostImage { get; }
        public Entity CompleteEntity { get; }

        public void Trace(string format, params object[] args);
        public void TraceBlockStart();
        public void TraceBlockStart(string label);
        public void TraceBlockEnd();
        public string GetOptionsetLabel(string entity, string attribute, int value);

Since this library contains a base class for custom workflow assemblies too, the Bag contains properties for both PluginContext and WorkflowContext. Obviously only one of them is assigned a value, depending on where the library is used.
The Service property is of type JonasServiceProxy, which implements the IOrganizationService interface. The benefit of using this type is that it automatically writes detailed timing information to the plugin trace log when using it’s methods.
Similarly the JonasTracingService automatically adds timestamps to each line written using the Trace method.
Then there are four properties of type Entity. These are all extracted from the context, where TargetEntity is the entity found using code similar to context.InputParameters[“Target”] as Entity. The PreImage and PostImage contains the first (if any) item in the PreEntityImages and PostEntityImages collections of the context.
The CompleteEntity contains a copy of the Target entity (not direct reference) where attributes from the PostImage and the PreImage have been added, to comprise “as much information possible” about the record that triggered the plugin. This is very useful when you just want to know the current value of attributes, without concern if they were changed in this transaction or not, and not having to if-else look for it in the target and images, and for the sake of performance you don’t want to retrieve the record from the database again.
image
The Trace method found in the bag is simply a shortcut to writing to the log using JonasTracingService.Trace. As mentioned above, this method adds timestamps, but also adds indentation defined by the following methods.
TraceBlockStart adds a trace block to the trace in the format BEGIN <name of calling method>. Each line written to the trace after this will be indented, until next call to TraceBlockEnd. This feature makes it easier to read the log and follow the execution with an appearance resembling a causality chain, if used consistently. The TraceBlockStart overload that takes a label parameter can be used to “name” the block something else than default.
Finally, the GetOptionsetLabel method is an example of how to encapsulate common methods and making them available through the base class structure.

A simple example

A simple plugin using the JonasPluginBase is available in this example on GitHub.
Resulting trace log for an account that moved from the 5th Floor to the 6th Floor, where one of the company’s contacts is defined to inherit the address:

23:48:03.782 *** Enter
23:48:03.798 [JPB] Context details:
  Step:  eXtremePlugins.AccountAddressToContacts: Update of account
  Msg:   Update
  Stage: 40
  Mode:  0
  Depth: 1
  Corr:  81762ffb-db01-4400-93ad-e47193686626
  Type:  account
  Id:    15cc51ab-58fe-e611-80fb-5065f38b2601
  User:  9cc6ecfd-cce1-4bd5-8832-20e476f776e1

23:48:03.861 [JPB] Incoming account
  accountid          = 15cc51ab-58fe-e611-80fb-5065f38b2601 (Guid)
  address1_line2     = 6. Floor (String)
                  PRE: 5. Floor

23:48:03.876 BEGIN GetContactsInheritingAddress
23:48:03.876   Adding filter for address1_line1 = 9068 Muir Road
23:48:03.876   Adding filter for address1_line2 = 5. Floor
23:48:03.876   Adding filter for address1_line3 = 
23:48:03.876   Adding filter for address1_city = Los Angeles
23:48:03.876   Adding filter for address1_stateorprovince = KA
23:48:03.876   Adding filter for address1_postalcode = 20593
23:48:03.876   Adding filter for address1_country = U.S.
23:48:03.876 END GetContactsInheritingAddress
23:48:03.892 [JPB] RetrieveMultiple(contact)
23:48:04.064 [JPB] Retrieved 1 records in: 83 ms
23:48:04.064 BEGIN UpdateContacts
23:48:04.079   [JPB] Execute(RetrieveEntity)
23:48:04.548   [JPB] Executed in: 478 ms
23:48:04.548   [JPB] Metadata retrieved for contact
23:48:04.548   [JPB] Primary attribute is: fullname
23:48:04.548   Updating contact: Sidney Higa (sample)
23:48:04.548   Checking: address1_line1
23:48:04.564   Checking: address1_line2
23:48:04.564   Setting address1_line2 = 6. Floor
23:48:04.564   Checking: address1_line3
23:48:04.564   Checking: address1_city
23:48:04.564   Checking: address1_stateorprovince
23:48:04.564   Checking: address1_postalcode
23:48:04.564   Checking: address1_country
23:48:04.579   [JPB] Update(contact) 7bcc51ab-58fe-e611-80fb-5065f38b2601 (9 attributes)
23:48:04.704   [JPB] Updated in: 137 ms
23:48:04.704 END UpdateContacts
23:48:04.704 [JPB] Internal execution time: 845 ms
23:48:04.704 *** Exit

Note that all log lines have a timestamp, and that log lines originating from within the JonasPluginBase library itself have a prefix [JPB].
 

I know I’m not alone

Being completely aware of the fact that I am not alone with the approach of creating supporting libraries – I guess most developers or companies that regularly produce plugins for Microsoft Dynamics CRM (365) do it – this is an example of a minimalistic base class for plugins. I am sure there are a lot more advanced libraries and templates out there.
But I like things simple.
You can always create more features, more “must haves” that in the end might be used so rarely that you could just as well have implemented them in the few plugins that need them rather than making it part of your framework on which you base all plugin development.
I honestly think this is the hardest part of building frameworks like this – to keep them light weight and have them focus on doing the most common tasks that we do not want to deal with over and over in our code.
Finally I am really eager to know what you think – so please comment on this post, or fork the repository for JonasPluginBase and create a pull request with suggested improvements!
Do you love early bound? What changes would you like to see in this library?