Strategy for logging in production for Dynamics CRM plugins

Question

CRM 2011 on premise.

I have a plugin written in C#. It could throw exceptions or otherwise behave badly in production.

When this happens I want to capture information about the state and about recent code execution to help me analyse the problem.

Ideally I would like the following:

1. If the code decides I should know about a problem then I want it to be able to tell me that there was a problem asap, without me looking to see if a problem has occurred.

2. I want the information about the problem to be easily accessible to me. I don't want to have to RDP to another machine and search through files.

3. I don't want logging to have much impact on performance.

I guess I'm looking for something like this:

• Retention of last n lines of log in memory.
• A single function call to add a line to the log.
• A single function call to cause an error to be recorded.
• When there's an error, email to me saying there was a problem. This contains summary info.
• The email contains a link to a web page showing me full error details. Stack trace, error message, date, time, user etc, last n lines of log.
• It'd be nice if there was also a web page somewhere showing me all errors, with filtering, sorting and so on.

I'm fairly new to CRM but I've developed systems like this before. Since CRM has been around for many years I'd expect this to be available for it.

Droop

Answer 1

To support your wish list, I'd create these Entities:

PluginLog

• Contains what ever information you'd like to retain for plugin calls that completed successfully
• Is related to a Plugin Exception Class. This way you could look up what happened before an exception occurred

PluginException

• Contains any special information regarding the exception (user, context, stack trace)

Now let's go through your wish list:

• Retention of last n lines of log in memory.
  • Not sure if you want to log the particular plugin class, or all plugins classes defined in the DLL, I'll assume a particular plugin class:
  • Create a static ConcurrentQueue for the plugin
• A single function call to add a line to the log.
  • Create a single function that creates a PluginLog entity in memory (without creating it in the CRM database) and adds it to the queue.
  • If it's length > n, dequeue.
• A single function call to cause an error to be recorded.
  • Again, this is something that you'll need to create. Basically I'd create a PLuginException Entity in CRM, then dequeue all the items off of the Queue, populating the Plugin Exception Id, and saving it to CRM
• When there's an error, email to me saying there was a problem. This contains summary info.
  • As long as the App Domain context of the executing plugin has the rights needed (not sure if it does in CRM Online) this should be trivial.
• The email contains a link to a web page showing me full error details. Stack trace, error message, date, time, user etc, last n lines of log.
  • You can create a link to the PluginException Entity Created, and include it in the e-mail along with all other pertinent information.
• It'd be nice if there was also a web page somewhere showing me all errors, with filtering, sorting and so on.
  • Advanced Find to the rescue

Edit

To help get you started, this is what I currently use to retrieve all the information from the plugin context, and convert it into text that gets inserted into an Exception:

    #region GetPluginInfo

    private Exception GetPluginExecutionInfoForLog(IServiceProvider serviceProvider, Exception ex)
    {
        if(ex.GetType() == typeof(InvalidPluginExecutionException)){ return ex; }

        try
        {
            var context = serviceProvider.GetContext();

            ex = new InvalidPluginExecutionException(
                String.Format("Error During Plugin Execution: {0}**** Context Values ****{0}{1}", 
                    Environment.NewLine, GetPluginExecutionInfo(context)), ex);
        }
        catch (Exception childEx)
        {
            OnError(childEx);
        }
        return ex;
    }

    protected String GetPluginExecutionInfo(IPluginExecutionContext context)
    {
        var lines = new List<String>();
        var target = GetTarget<Entity>(context);

        lines.Add("MessageName: " + context.MessageName);
        lines.Add("PrimaryEntityName: " + context.PrimaryEntityName);
        lines.Add("PrimaryEntityId: " + context.PrimaryEntityId);
        lines.Add("BusinessUnitId: " + context.BusinessUnitId);
        lines.Add("CorrelationId: " + context.CorrelationId);
        lines.Add("Depth: " + context.Depth);
        lines.Add("Has Parent Context: " + (context.ParentContext != null));
        lines.Add("InitiatingUserId: " + context.InitiatingUserId);
        AddParameters(lines, context.InputParameters, "Input Parameters");
        lines.Add("IsInTransaction: " + context.IsInTransaction);
        lines.Add("IsolationMode: " + context.IsolationMode);
        lines.Add("Mode: " + context.Mode);
        lines.Add("OperationCreatedOn: " + context.OperationCreatedOn);
        lines.Add("OperationId: " + context.OperationId);
        lines.Add("Organization: " + context.OrganizationName + "(" + context.OrganizationId + ")");
        AddParameters(lines, context.OutputParameters, "Output Parameters");
        AddEntityReference(lines, context.OwningExtension, "OwningExtension");
        AddEntityImages(lines, context.PostEntityImages, "Post Entity Images");
        AddEntityImages(lines, context.PreEntityImages, "Pre Entity Images");
        lines.Add("SecondaryEntityName: " + context.SecondaryEntityName);
        AddParameters(lines, context.SharedVariables, "Shared Variables");
        lines.Add("Stage: " + context.Stage);
        lines.Add("UserId: " + context.UserId);

        if (target == null || target.Attributes.Count == 0)
        {
            lines.Add("Target: Empty ");
        }
        else
        {
            lines.Add("* Target " + target.ToEntityReference().GetNameId() + " *");
            foreach (var att in target.Attributes)
            {
                lines.Add("    Entity[" + att.Key + "]: " + GetAttributeValue(att.Value));
            }
        }

        lines.Add("* App Config Values *");
        foreach (var key in ConfigurationManager.AppSettings.AllKeys)
        {
            lines.Add("    [" + key + "]: " + ConfigurationManager.AppSettings[key]);
        }

        return String.Join(Environment.NewLine, lines);
    }

    private static string GetAttributeValue(object value)
    {
        if(value == null){
            return "Null";
        }
        var type = value.GetType();
        if (type == typeof(OptionSetValue))
        {
            return ((OptionSetValue)value).Value.ToString();
        }
        else if (type == typeof(EntityReference))
        {
            return ((EntityReference)value).GetNameId();
        }
        else
        {
            return value.ToString();
        }
    }

    private static void AddEntityReference(List<string> nameValuePairs, EntityReference entity, string name)
    {
        if (entity != null)
        {
            nameValuePairs.Add(name + ": " + entity.GetNameId());
        }
    }

    private static void AddEntityImages(List<string> nameValuePairs, EntityImageCollection images, string name)
    {
        if (images != null && images.Count > 0)
        {
            nameValuePairs.Add("** " + name + " **");
            foreach (var image in images)
            {
                if (image.Value == null || image.Value.Attributes.Count == 0)
                {
                    nameValuePairs.Add("    Image[" + image.Key + "] " + image.Value.ToEntityReference().GetNameId() + ": Empty");
                }
                else
                {
                    nameValuePairs.Add("*   Image[" + image.Key + "] " + image.Value.ToEntityReference().GetNameId() + "   *");
                    foreach (var att in image.Value.Attributes)
                    {
                        nameValuePairs.Add("        Entity[" + att.Key + "]: " + GetAttributeValue(att.Value));
                    }
                }
            }
        }
        else
        {
            nameValuePairs.Add(name + ": Empty");
        }
    }

    private static void AddParameters(List<string> nameValuePairs, ParameterCollection parameters, string name)
    {
        if (parameters != null && parameters.Count > 0)
        {
            nameValuePairs.Add("* " + name + " *");
            foreach (var param in parameters)
            {
                nameValuePairs.Add("    Param[" + param.Key + "]: " + param.Value);
            }
        }
        else
        {
            nameValuePairs.Add(name + ": Empty");
        }
    }

    #endregion // GetPluginInfo

Allier

That's a really nice answer. Isn't creating entity records for each log line going to be rather expensive? – Droop

@Droop As I attempted to specify, only create the records in CRM when you have an exception. Just creating an entity in Memory is extremely cheap (assuming it's not ginormous) If you wanted to save it to CRM every time, yes that would be expensive. If you're throwing an exception in your plugin multiple times a minute, yes that would be expensive as well, but if everything is smooth exception for the occasional blip, it shouldn't be a concern. – Allier

You did explain that well. I usually assume the worst though :) – Droop

Not that I know of. It wouldn't be too hard to implement with a Manage Solution and a Plugin Base Class that if someone inherited from it, would auto-magically perform the specified logging. – Allier

I'll wait a few days to see if I get an even better answer, but otherwise I'll tick yours. – Droop

I'm going to mark this as answer because I like it and might implement it if the built in solution I found isn't enough for me. But for now I'm going to try using the built in solution I mention in my answer. – Droop

Answer 2

I've found a very quick way to do this at http://mscrmtech.com/mscrm-2011-useful-itracingservice-addiion-when-creating-plugin-assemblies/

It is documented (barely) here: http://msdn.microsoft.com/en-us/library/microsoft.xrm.sdk.itracingservice.aspx

So I can do

    public void Execute(IServiceProvider serviceProvider)
    {
        ITracingService tracingService = (ITracingService)serviceProvider.GetService(typeof(ITracingService));
        if (tracingService == null)
            throw new InvalidPluginExecutionException("Failed to retrieve the tracing service.");
        tracingService.Trace("CRMSTClasses.Main_Code.Execute - testing tracing");

        throw new InvalidPluginExecutionException("Test exception");

And then the log file I can download from the error dialogue includes:

[CRMSTClasses: CRMSTClasses.Main_Code.Receiver]
[cb42fcb0-0717-e311-9097-0050569274a2: CRMSTClasses.Main_Code.Receiver: Create of incident]
CRMSTClasses.Main_Code.Execute - testing tracing

Droop

So this allows you to write information to the Log file the user downloads? – Allier

Answer 3

In the latest versions of Dynamics, the Plugin Trace Log captures a lot of this information simply by a user calling the pre-built Tracing Service. It doesn't enable proactive notifications as requested, but it has lots of other nice features. When you're ready to upgrade (if that's in the cards), I would recommend taking a look at it.

Incorporeal