Handle All Your Plugin Exceptions In One Place, And Then Hide It!

One of the simplest to understand, best practice of writing code (outside of maybe limiting # of lines in a method) is don’t create duplicate code.  Having duplicate code leads to tons of maintenance issues as bugs are fixed in some places, and not others.  Following this best practice, it’s very common recommended best practice to let your Plugin Base class logic handle catching and logging exceptions.

*Important Side Bar* Before going any farther, there are 101 ways to setup debugging in Visual Studio and in certain situations this doesn’t apply, but for the most part, I will assume that your Visual Studio Debugger is setup with most default settings still in place, including the “Enable Just My Code” option.  Also, I don’t know everything about the VS debugger or C# debugger attributes, so if there is a better way, please let us all know.  Alright, lets continue…

One of the problems this creates for those that have unit tests, is (more than likely) that when debugging a unit test, if the plugin itself throws an exception (NullRef anyone?) the debugger will stop execution at the throw statement in the plugin base, since that’s the last place that the exception is caught, before surfacing it to the application, normally CRM, in this case, it would be your test harness.  This is rather annoying, since you don’t see the actual like of code the error occurred at since it was caught by the plugin base class when thrown.  As the picture below shows, this gives 0 context as to where the exception has actually occurred without digging into the stack trace within the exception (as opposed to the Call Stack in VS)

With the equally less than helpful call stack:

So how do we get VS to stop debugging where the error happens, rather than at the plugin base exception handler logic?  Enter “Debugger Attributes” to the Rescue!

There are quite a few “Debugger Attribute” classes in the System.Diagnostics namespace, but the one that makes most sense here is the DebuggerStepThroughAttribute (Or, if you have an open source project that is distributed as code (code gists, source only nuget packages, submodules, etc) or if you want to use the “Enable Just My Code” debugger option to be able to control if you can set a break point and debug or not, then the DebuggerNonUserCodeAttribute makes more sense.).  By adding this attribute to your base plugin class that contains the throw (or method level if you so desire)

[DebuggerNonUserCode]
public abstract class DLaBGenericPluginBase<T> : IRegisteredEventsPlugin where T: IExtendedPluginContext
{

this will force VS to give the desired result:

Since the method handling the exception is “hidden” from the debugger, now the call site of the method that throws the exception, will be where the debugger stops.  Above we can see the actual method call that resulted in the null ref exception was GetByName(), and below the exception call site is shown in the calls stack, so the path to the exception is easily navigated to:

But wait, what happened to the base plugin call site?  Where did it go?  It’s represented by the [External Code] line.  It can’t be stepped into, or debugged without changing your debug settings or removing the attributes but it still shows up in the actual exception stack trace.  So spend less time diving into the exception stack trace, and instead, allowing VS to put you on the actual line where the exception is actually occurring.

 

Happy Coding!

Negotiating the CDS/CRM/Xrm Plugin Trace Log Length Limitation

With the Dynamics 365 CRM 2015 U1 update, the Plugin Trace entity was added to the platform.  This provided an OOB implementation for the ITracingService (although it only works in Sandboxed plugins) to log to that was a much needed addition to the platform.  Over time, my dependency and use of the ITracingService within the DLaB.Xrm library has greatly increased.  By default, the plugin base auto logs the name of the plugin that is executing, the start and stop time, each IOrganizationService call that is made, and on exceptions, the entire plugin context to make debugging easier.   With all of this logging, it is becoming more and more common for plugins to exceed the 10,240 character limit.  This results in the beginning of the trace log getting truncated.

So what’s the solution?  You could completely abandon the built in ITracingService, and trace to Application Insights.  As much as I love that solution, for anything but large CRM/CDS implementations it may be overkill.  With the assumption that most of the time, the information that is helpful for debugging will be at the beginning or the end of the trace, I’ve updated the default ITracingSevice in the DLaB.Xrm library, when in cases of the tracing being longer than 10,240 characters, to retrace the first 5,120 characters, and then retrace the last 5,120.

Let’s take a look at the implementation:

public class ExtendedTracingService: IMaxLengthTracingService
{
    private ITracingService TraceService { get; }
    public int MaxTraceLength { get; }
    private StringBuilder TraceHistory { get; }
 
    public ExtendedTracingService(ITracingService service, int maxTraceLength = 10244) {
        TraceService = service;
        MaxTraceLength = maxTraceLength;
        TraceHistory = new StringBuilder();
    }
 
    public virtual void Trace(string format, params object[] args) {
        try
        {
            if (string.IsNullOrWhiteSpace(format) || TraceService == null)
            {
                return;
            }
 
            var trace = args.Length == 0
                ? format
                : string.Format(format, args);
            TraceHistory.AppendLine(trace);
            TraceService.Trace(trace);
        }
        catch (Exception ex)
        {
            AttemptToTraceTracingException(format, args, ex);
        }
    }

    /// <summary>
    /// If the max length of the trace has been exceeded, the most important parts of the trace are retraced.
    /// If the max length of the trace has not been exceeded, then nothing is done.
    /// </summary>
    public void RetraceMaxLength()
    {
        if(TraceHistory.Length <= MaxTraceLength)
        {
            return;
        }
 
        var trace = TraceHistory.ToString().Trim();
        if(trace.Length <= MaxTraceLength)
        {
            // White Space 
            Trace(trace);
            return;
        }
 
        //Assume the three Traces will each add New Lines, which are 2 characters each, so 6
        var maxLength = MaxTraceLength - 6;
        if(maxLength <= 0)
        {
            return;
        }
 
        var snip = Environment.NewLine + "..." + Environment.NewLine;
        var startLength = maxLength / 2 - snip.Length; // Subtract snip from start
        if(startLength <= 0)
        {
            // Really short MaxTraceLength, don't do anything
            return;
        }
        Trace(trace.Substring(0, startLength));
        Trace(snip);
        Trace(trace.Substring(trace.Length -(maxLength - (startLength + snip.Length))));
    }
}

The ExtendedTracingService wraps the default ITracingService from the platform, and then on calls to trace, it intercepts the call, and adds the trace to an in memory StringBuilder first, before actually tracing the call.  The final step in the plugin base is to then call RetraceMaxLength().  This will check the length of the StringBuilder, and if it’s over the max length, trace the first part of the traces, and then the last part, with an “…” in the middle to serve as a “Snip” statement.

If you’re already using the DLaB.Xrm.Source library, get the latest (>= 2.3.0.13) version from NuGet, and enjoy ensuring you always see the beginning and end of reach trace.  If you’re not using the DLaB.Xrm.Source Library, why not? It’s free, open source, and because it’s a source only NuGet package, doesn’t require ILMerge when being used from a plugin.  You can even use the Visual Solution Accelerator in the XrmToolBox to bring it into your existing CRM/CDS VS solution.

Here is an example log: (I’ve removed a great deal of text, just notice that the “…” serves as the signal that the trace was too long, and the middle portion has been truncated)

Starting Timer for Execute Request for dlab_LeadSearch with * Parameters *,     Param[IsMovers]: False,     Param[PhoneNumber]: 5553214321. Timer Ended (  0.096 seconds) Starting Timer: IsRejectedOrCreateLead Partner Not First Party Lead validations: is 30 Days Logic: True is Same Day Inquiry: True is rejected: True - 30 Day Lead Logic Timer Ended (  0.000 seconds): IsRejectedOrCreateLead Starting Timer: is30DaysLogic Timer Ended (  0.000 seconds): is30DaysLogic Starting Timer for Create Request for dlab_leadqualifier with Id 00000000-0000-0000-0000-000000000000 and Attributes     [dlab_name]: Homer Simpson      [dlab_azureid]: 317578      [dlab_5daylogic]: 0      [dlab_7daylogic]: 0      [dlab_14daylogic]: 0      [dlab_30daylogic]: 0      [dlab_30daylogiccurrent]: 1      [dlab_jornayalogic]: 0      [dlab_dayslogic]: 0      [dlab_existinglead]: True Timer Ended (  0.033 seconds) Start of isUpdatePath - 2019-05-11-07:32:41 407 Starting Timer for Update Request for lead with Id c97e6f52-6431-e911-8190-e0071b663e41 and Attributes     [trans ...     Param[skipExport]: False      Param[subdivision]:      Param[subTotal]:      Param[primaryPhoneDnc]: False      Param[secondaryPhoneDnc]: False * Output Parameters *      Param[response]: PostEntityImages: Empty PreEntityImages: Empty * Shared Variables *      Param[Example.Xrm.LeadApi.Plugins|dlab_createLeadRequest|PostOperation|00000000-0000-0000-0000-000000000000]: 1 Has Parent Context: False Stage: 40