Tracing Plugins & Custom Workflow Activities in D365 – identify execution chains and much more

Deep into D365 plugins & async execution pipeline, when developers get puzzled with questions “why update of a single record field, triggers much more than needed business logic”, this framework for writing plugins and custom work flow activities can come of use.

What can this solution achieve

This solution is in place in production system for over 6 months at the time I first published this (i.e since September 2014).  I shall begin with first signifying its benefits:

1. It provides detailed logging of plugin or custom workflow activity execution. Log is saved as a custom entity record with additional tracing details as attached notes.
2. I implemented this long before Microsoft released Plugin Trace Log in 2015, and it provides much more details than trace logging. However it requires plugin & custom workflow activity code implement a base class as provided in framework for download at the end.
3. When it is needed to get inner details of plugin execution context, register an empty logic plugin and step on the required message, entity and stage. Complete plugin context shall be serialized as a note attachment on plugin execution.
4. In case of production system, where remote debugger cannot be attached due to security restrictions, this facility comes in very handy to locate errors in plugins.
5. CRM Developers usually throw deliberate exception from plugin code to see the trace. This requires changing code. With this facility one just needs to tracing service and look at the execution log records for the concerned plugin
6. The solution is intended for getting deeper insight of  MS Dynamics CRM execution pipeline, plugins and custom workflow activities. So it is best understood by individuals having handsome knowledge of these features in CRM.
7. This goes without saying that this solution helped us identify and fix some scenarios that greatly improved performance so we could identify unexpected plugin chains as also posted here:

Plugins chain and usage of SYSTEM context

Unexpected triggering of update plugins on Appointment Completion / Cancellation

Avoid update plugin steps triggering during Assign request

 Added with solutions ver. 1.0.0.1

If you have followed this post before, I have added some additional trace logging features to this facility.

1. Is WF Activity — if the custom logic is a workflow activity this flag will be set in trace log

2. Link to workflow/dialog — similarly lookup will be set to the workflow / dialog which invoked workflow activity

3. A url in trace log message (text area & note TraceMessages.log) to the async job or dialog session of the workflow of dialog instance, which invoked workflow activity. This cannot be built as an entity relation.

Synopsis

In one of my recent projects, I needed a facility to see details of plugins’ executions and moreover being able to see these details in the exact sequence in which each plugin-step triggered in execution pipeline. The closest I could get, with out of the box tools was to attach profiler on individual plugin steps in registration tool, but that could not suffice my requirements.

My concerning system is a fairly large and customized MS Dynamics CRM 2011 implementation (1700+ Sales, Marketing and Service users, 1.5 million accounts & contacts from 30+ business units), with following salient features:

1. 120+ custom entities encompassing the famous 3 sub-verticals: Sales automation, Marketing and Customer Service.
2. Team ownership and sharing of core entities across business units hierarchy.
3. Point to point integration with  corporate ERP system.
4. Plugins implemented for outbound data from CRM.
5. Middleware solution for inbound data from ERP consuming CRM webservices.
6. More than 150+ plugins and steps registered on various entities.
7. Most of update message steps registered  with Filtering set to “All attributes”.
8. Some business logic also implemented as workflows and dialogs.

System’s behavior

Best explained as: “Unpredictable”, “Indeterministic”

1. For some use-cases a plugin would execute in SYSTEM’s context while at times, same plugin would execute in another user’s context for same use-cases. This threw unprecedented security errors, becoming increasingly difficult to reproduce.
2. In some instances “Ping-Pong” effects (i.e, cyclic data updates between CRM and ERP) were identified in accounts audit history.
3. Some data updates triggered workflows, which due to asynchronous nature, executed silently but further triggered plugins.

Solution

An ideal solution would be to re-design integration interfaces and control the plugins chains execution smartly. This is obviously not practical, however even to fix existing implementation, a realtime overview of execution pipeline is what i needed. Something similar to OOTB “System Jobs” view, with data from execution context (of plugin or custom activity).

Requirements

I came up with following high-level requirements for this solution

1. It should be possible to view details of plugins and custom workflow activities executions in a usual CRM view.
2. From the view it should be possible to identify 1 or more executions which triggered within same request.
3. It should be possible to see trace messages from each execution.
4. It should be possible to see which execution failed with errors and error details. At the moment errors thrown from plugins (executed due to inbound information from ERP) can only be seen in the source system (middleware).
5. It should be possible to enable/disable logging feature within CRM’s usual interface. Plugin profiler tool requires special permissions and requires more technical knowledge in order to do profiling and does not allow to profile custom workflow activities.
6. It should be possible to see full execution context passed to plugin / custom workflow activity by the pipeline.

CRM Views

Something like this is then available in CRM views

Extended Execution Log View

While the following information is available on execution log’s form

Extended Execution Log Form 1

While following notes are also available in the form

Extended Execution Log Form 2

Design

Step 1

I started with designing two custom Organization Owned entities “Configuration Key” & “Extended Execution Log”.

Configuration Key — this is a simple entity with key, value & description. A simple key named “ExtendedLoggingEnabled” holding value “1, yes, y or true” (Case Insensitive) will enable the logging

Extended Execution Log — This entity holds the log of executions

Entity is enabled for “Notes”

1. Correlation Id — String; Guid value, key to group custom logic executions triggered due to one request to CRM
2. Sequence — Whole number; millisecond of the day when custom logic executed
3. Message — String; all messages written to tracingservice during code (TracingService.Trace(“message”);
4. Initiating User — Lookup; Initiating user from execution context
5. Name — String; Name of custom logic code component, class file name etc
6. Message Name — String; MessageName from execution context which triggered the plugin
7. Primary entity — String; name of primary entity from execution context
8. Secondary entity — String; name of secondary entity from execution context
9. Operation CreatedOn — DateTime; OperationCreatedOn from execution context to plugin
10. Operation StartedOn — DateTime; Exact time when code logic actually started (typically before execute method is invoked)
11. Operation CompletedOn — DateTime; Exact time when code logic completed (typically after execute method)
12. Error in execution — Yes / No; if logic execution failed, value is set to Yes
13. Error message — String; Exception / Error details
14. Is WF Activity — Yes / No; Set if this is a custom wf activity (added with solutions ver. 1.0.0.1)
15. Workflow/Process — Lookup; Workflow/Dialog triggering custom activity, if it is wf activity (added with solutions ver. 1.0.0.1)

Step 2

Time to write some utility library code :=). The facilities (API) from library are used in base classes for plugins and custom activities. Basically we need to achieve following:

• An abstract base class for plugins (that implements IPlugin) and allows derived plugins to override OnExecute
• An abstract base class for custom workflow activity (that extends CodeActivity) and allows derived activities to override OnExecute
• Base classes inject custom interfaces into OnExecute methods which expose required details for implementing plugins / custom activities
• The injected custom interfaces are known to library’s IExecutionRecorder which exposes methods to log the execution in the custom entity. Base classes make use of IExecutionRecorder
• Provide following extended execution context interfaces which are injected by base classes into implementing classes
  • ICustomExecutionContext
  • ICustomPluginContext
  • ICustomWorkflowContext
• Extend ITracingService interface as IRecordableTracing so base classes inject its implementation into implementing derived plugins / custom activities
• Implement following serializable extensions of IExecutionContext. These implementations are only used internally by ExecutionRecorder in order to serialize execution context
  • TracingExecutionContext
  • TracingPluginContext
  • TracingWFContext
• Being an interface driven approach, i made use of these facilities in existing base plugins class.

Solution Package

And here are the details of attached package:

1.   There are three managed solutions, each for 2011, 2013 & 2015.

(Note: Remember to import using Deployment Admin user).

Managed Solutions for 2011, 2013, 2015

2.   Deployed assemblies — view from plugins registration tool

1. CRM.Toolkit.Plugins.Merged — demo plugins assembly created using MS CRM developer toolkit in VS 2012. Plugins are registered on entity + message + stage combination as also programmed in plugin class.
2. CRM.Toolkit.Workflow.Merged — custom wf activities assembly created using MS CRM developer toolkit in VS 2012. Contains a demo custom wf activity that fetches user by domain name. It is used in a workflow process that is part of managed solution.
3. CustomPluginsLib.Merged — a C# class library with two demo plugins classes. These plugins can be registered on any message on any entity i.e, not restricted by plugin code. One plugin throws deliberate exception.

Plugins and WF Activities Assemblies

3.   Visual Studion 2012 solution folder structure

1. CRM.Models — C# class library to hold CRM early bound proxy classes and helper code
2. CrmPackage — MS CRM developer toolkit deployment folder
3. CustomPluginsLib — C# class library for custom plugins i.e, not created by toolkit’s utility.
4. Library — solution folder where all required dlls / executables (for build etc) are placed. Also contains 3 framework dlls.
5. Toolkit.Plugins — MS CRM developer toolkit plugins project. In order to see how execution recorder is used, look at how i changed LocalPluginContext & Plugin (base class) generated by toolkit. There is no change required in derived plugin classes
6. Toolkit.Workflows — MS CRM developer toolkit custom wf activities project

Note: for 3, 5, 6 above, solution’s postbuild event makes sure to ILMerge required dlls to create merged plugin / wf activities dll for deployment. Framework only uses late bound classes, so implementing assemblies can generate and provide own namespace to early bound classes, this keeps the final dll from any types ambiguity during runtime.

VS 2012 Solution Projects and Folders

4.   Contents of library folder (as in 3 above):

Following dlls comprise the framework (rest are SDK dlls etc)

1. CRM.Common.Utils.dll — Contains interfaces, and concrete implementations of execution recorder, rerordable tracing, and a classes to serialize execution context into XML
   Following is the class diagram from utility library:
   
2. CRM.Common.Plugins.dll — Contains plugins base class (extended as an example in CustomPluginsLib) and a concrete implementation of ICustomPluginContext (injected into derived classes)
   

   Classes in base plugins library

3. CRM.Common.WFs.dll — Contains wf activities base class (extended as an exmaple in Toolkit.Workflows) and a concrete implementation of ICustomWorkflowContext (injected into derived classes)
   

   Classes in base wf activities library

Note: I have kept base classes for plugins and wf activities in separate assemblies because I like clear separation of framework assembly names based on responsibilities. I also like to keep separate assemblies for derived plugins and wf activities. These two type of components should also be kept apart in different assemblies for ease of maintenance and deployment.

Library folder contents

Download the zip package for this implementation here:

How to see it working

1.   After importing solutions, refresh and go to Settings area to create a Configuration Key entity with Key=ExtendedLoggingEnabled and Value=yes, y, 1, or true (case insensitive) in order to start tracing.

2. Define another Configuration Key as Key=OrgBaseUrl and Value=http://host:port/orgname. With this key defined, a full url to async job or dialog session will be available in trace message e.g, http://win-hov9h4ng751:5555/ahad/sfa/workflowsession/edit.aspx?id=737aef28-48cc-e411-90a0-080027199d20. (added with solutions ver. 1.0.0.1)

2.   Create a record of Test Entity from Settings area.

3.   Tracing will appear in Extended Execution Logs view in Settings area. Open trace and look into details and notes.

4.   Using plugin registration tool, register some steps on supported messages of any other entity on AnyMessageOnEntityPlugin class in CustomPluginsLib.Merged assembly.

Hope this helps you debug with much ease!!

Finally, zip package as described above, can be downloaded here:

Download Extended Logging.zip

Updates
November 23, 2015

Adjusted context serialization, which is attached as an XML (log file) note to the Logging record. In one of the online CRM 2015, the context Context serialization using .Net’s out-of-box was throwing security exception. This was because plugins could only be registered in sandbox. With custom serialization, I have made sure that all needed properties of whole context object graph are serialized. The custom serialization is done only if out-of-box serialization throws exception. Latest CRM solution version is 1.0.0.2. Also VS 2012 Solution has CRM.Common.Utils.dll which holds serialization logic

Conclusions

1.   Plugins are a powerful feature in CRM, however with power also comes responsibility. Know what your plugin is doing, and part of that knowledge also means to be aware of what events actually trigger plugins and what is passed in context

2.   Make use of SYSTEM user carefully, as that might give varying output if subsequent plugins make use of properties and relations of initiating user.

3.   Workflows execution could also trigger plugins that might not be required. So make necessary checks in plugins for such situations. Business users can create workflows, but likely not write plugins ;-).

4.   Throw meaningful exceptions from plugin code. This goes without saying that code should be written with some basic etiquttes in place to take care of errors like, Null Reference, Key Not Found, Duplicate Key and more 🙂