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