Fighting “General SQL Error” in Dynamics CRM custom workflows

Working for my client Valx, I had some serious problems in custom workflows for Microsoft Dynamics CRM 4. Every now and then, a workflow would throw a SoapException. I always put the original exception in the InvalidPluginExecutionException (second parameter “inner exception”). Now the actual exception information you want to see is in SoapException.Detail, which is an XmlNode. You won’t see that info if you just put the SoapException in the InvalidPluginExecutionException’s inner exception. Therefore, I use the following try/catch construction in each custom workflow’s Execute method to see some relevant information in the WorkflowLog view of the Dynamics CRM database.

try
{
    // do stuff
}
catch (Exception ex)
{
    string soapExceptionDetail = string.empty;
    if (ex is SoapException)
    {
        soapExceptionDetail =
            string.Format(
                "\nSoapException Detail: {0}\n",
                ((SoapException)ex).Detail.InnerText
            );
    }
    throw new InvalidPluginExecutionException(
        string.Format(
            "An error occurred in the {0} plug-in.{1}",
            this.GetType().ToString(), soapExceptionDetail
        ),
        ex
    );
}

Now sometimes, property names promise a bit too much. Because the error I was getting in the SoapException.Detail was the anything but helpful “Generic SQL Error” (0x80044150 or 2147762512). That could be anything. By the way, the following is the SQL query I’m running on the WorkflowLog view of the organization’s Dynamics CRM database. It will only show the ones with an ErrorCode, sorted by newest date first.

SELECT TOP 1000
  [AsyncOperationIdName]
  ,[Description]
  ,[Message]
  ,[CreatedOn]
  ,[ModifiedOn]
  ,[CompletedOn]
  ,[StepName]
  ,[Status]
  ,[ErrorCode]
  ,[ActivityName]
FROM [WorkflowLog]
WHERE ErrorCode IS NOT NULL
ORDER BY ModifiedOn DESC, StepName DESC

We’re looking at the “Message” column of data here. If a plugin throws an InvalidPluginExecutionException, you’ll find the error message (provided you’ve entered one) and the stack trace (also of any inner exceptions) in this database field. Neat! But… “Generic SQL Error” won’t get us any closer to a solution.

Next, you’ll want to switch on tracing/logging for Dynamics CRM. For MS Dynamics CRM 4, this will put the trace in the following folder: Drive:\Program Files\Microsoft Dynamics CRM\Trace. I tend to restart IIS and the CrmAsyncService after such a change.

There will be trace logs created with names like servername-crmasyncservice-bin-20110922-1.log or servername-w3wp-wwwroot-20110922-1.log. Since my custom workflows are running asynchronously, I’m first interested in the CrmAsyncService log. Pretty quickly, I could find stuff like this:

[2011-09-20 05:28:12.1] Process:CrmAsyncService |Organization:7a8005ba-c6b4-4fc7-8ba0-82a57dd75a6e |Thread:   46 |Category: Platform.Async |User: 00000000-0000-0000-0000-000000000000 |Level: Error | AsyncOperationCommand.Execute
>Exception while trying to execute AsyncOperationId: {B7627B65-38E3-E011-A4C1-000C29D1C68A} AsyncOperationType: 1 - System.Data.SqlClient.SqlException: Transaction (Process ID 71) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
   at Valx.Crm.Plugins.UpdateKitProduct.UpdateKitProductPlugin.Execute(IPluginExecutionContext context)
   at Microsoft.Crm.Asynchronous.EventOperation.InternalExecute(AsyncEvent asyncEvent)
   at Microsoft.Crm.Asynchronous.AsyncOperationCommand.Execute(AsyncEvent asyncEvent)

Alright, database deadlocks! We’re pounding that poor SQL Server too hard… Poor thing. Now in my opinion there are two obvious solutions: reduce the number of parallel/concurrent threads of the CrmAsyncService, or start throttling the database queries (or the CrmService calls). Since reducing the number of parallel/concurrent threads of the Crm Asynchronous Service is not really well-documented, I chose to look into throttling.

First, I make the assumption that, when the workflow catches a SoapException that mentions a “Generic SQL Error” in its Detail, it is a SQL deadlock. That’s why you need to check the trace for the actual SQL error. But as far as I could tell, in my trace log files of a couple of days, the only SQL errors were of the kind “chosen as the deadlock victim”.

Dynamics CRM 4 already has a mechanism for recovering from SQL errors, both for plugins and workflows. But! You cannot throw a SQLException from a SoapException. As you can see on the above-linked page, a workflow will undoubtedly fail after throwing a InvalidPluginExecutionException. After some experimenting, I devised the following methods. These are extension methods for the ICrmService and what they do is simple: if the call fails with a SoapException and the SoapException.Detail contains the text “generic sql error”, it will retry, but only after waiting. Now the waiting time is extended for each iteration. I chose 1 second times the number of iterations, you can choose so at will.

The wait is implemented using a Thread.Sleep(). That might not always be good, but in this case it’s great, because it will prevent spawning more threads by the asynchronous CRM service, thus creating some breathing space for this waiting thread.

Here are the extension methods:

using System;
using Microsoft.Crm.Sdk;
using Microsoft.Crm.SdkTypeProxy;

namespace Broes.Crm.Workflows
{
    public static class CrmServiceExtensions
    {
        /// <summary>
        /// Method to execute a Request on the given ICrmService.
        /// When the CrmService throws a SoapException
        /// which points to a SQL Server error,
        /// it most probably is a deadlock. Subsequently,
        /// this method will sleep the current Thread
        /// for a short while and then retry. It will retry for
        /// a maximum of five times, each time with a
        /// greater interval.
        /// </summary>
        /// <typeparam name="T">The Response type, e.g. RetrieveResponse.</typeparam>
        /// <param name="crmService">The ICrmService to connect to the CRM.</param>
        /// <param name="request">The Request to execute on the CRM service.</param>
        /// <returns>The Response object.</returns>
        public static T ExecuteWithRetry<T>(this ICrmService crmService, Request request)
            where T : Response
        {
            T response = null;
            int i = 0;

            // Maximum of five iterations.
            while (i < 5)
            {
                try
                {
                    response = (T)crmService.Execute(request);
                    
                    // If the Execute does not throw an Exception, break the loop
                    break;
                }
                catch (System.Web.Services.Protocols.SoapException e)
                {
                    // Retry if the SoapException is a "Generic SQL Error",
                    // otherwise rethrow the SoapException.
                    // "Generic SQL Error" might indicate a deadlock.
                    if (e.Detail.InnerText.ToLower().Contains("generic sql error"))
                    {
                        ++i;
                        // Wait (sleep thread) for i * 1000 milliseconds.
                        // So, first iteration waits 1 second,
                        // while fifth iteration will wait 5 seconds.
                        System.Threading.Thread.Sleep(i * 1000);
                    }
                    else throw;
                }
            }

            if (i >= 5)
            {
                throw new Exception("CrmServiceExtensions.ExecuteWithRetry: too many retries");
            }

            return response;
        }

        /// <summary>
        /// Method to execute a Fetch XML on a given ICrmService.
        /// When the CrmService throws a SoapException
        /// which points to a SQL Server error,
        /// it most probably is a deadlock. Subsequently,
        /// this method will sleep the current Thread
        /// for a short while and then retry. It will retry
        /// for a maximum of five times, each time with a
        /// greater interval.
        /// </summary>
        /// <param name="crmService">The ICrmService to connect to the CRM.</param>
        /// <param name="fetchXml">The Fetch XML to execute.</param>
        /// <returns>The result string of the Fetch method.</returns>
        public static string FetchWithRetry(this ICrmService crmService, string fetchXml)
        {
            string fetchXmlResponse = string.Empty;
            int i = 0;

            while (i < 5)
            {
                try
                {
                    fetchXmlResponse = crmService.Fetch(fetchXml);

                    // If the Fetch does not throw an exception, break the while-loop.
                    break;
                }
                catch (System.Web.Services.Protocols.SoapException e)
                {
                    // Retry if the SoapException is a "Generic SQL Error",
                    // otherwise rethrow the SoapException.
                    // "Generic SQL Error" might indicate a deadlock.
                    if (e.Detail.InnerText.ToLower().Contains("generic sql error"))
                    {
                        ++i;
                        // Sleep the current thread for i * 1000 milliseconds
                        System.Threading.Thread.Sleep(i * 1000);
                    }
                    else throw;
                }
            }

            if (i >= 5)
            {
                throw new Exception("CrmServiceExtensions.ExecuteWithRetry: too many retries");
            }

            return fetchXmlResponse;
        }
    }
}

Hope this helps sharing with you, because I found a ton of users battling the “Generic SQL Error” and “deadlock victim” errors in (asynchronous) plugins and workflows, but so far have not seen anyone creating a possible solution.