could not execute batch command.[SQL: SQL not available]

[mrisen]

In my test environment I often get a could not execute batch command.[SQL: SQL not available] exception when running tests. It only happens when I run many tests at the same time... some sort of race condition. The call that receives the exception is:

Code: Select all

transactionsManager.ApplyChanges(Constants.TestString, transaction);

Does anyone have any suggestions on what might be causing this?

[John Morris]

Do you have a complete stack trace for the exception?

[mrisen]

at SoftPro.ClientModel.Proxies.ClientProxy`1.OnHandleFaultException(FaultException exception)
at SoftPro.ClientModel.Proxies.ClientProxy`1.HandleFaultException(FaultException exception)
at SoftPro.Accounting.Client.Transactions.TransactionsManagerServiceClient.ApplyChanges(String reason, List`1 transactions)
at SoftPro.Accounting.Client.Transactions.TransactionsManager.SoftPro.Accounting.Client.Transactions.ITransactionsManager.ApplyChanges(String reason, ITransaction[] transactions)
...Client code...

[John Morris]

Please provide the server side error log entry from the eventlog.

[mrisen]

An error occured on the service boundary.Error: could not execute batch command.[SQL: SQL not available]
Stack Trace:
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps)
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch()
at NHibernate.Engine.ActionQueue.ExecuteActions()
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session)
at NHibernate.Event.Default.DefaultFlushEventListener.OnFlush(FlushEvent event)
at NHibernate.Impl.SessionImpl.Flush()
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.UniqueConstraintViolationAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.StaleObjectStateExceptionAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.DeadlockDetectionAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.Accounting.Persistence.Transactions.TransactionSearchData.SaveInstance(Transaction transaction)
at SoftPro.Select.Persistence.Search.SearchData`1.Save(T[] instances)
at SoftPro.Accounting.Persistence.Transactions.TransactionsDataContext.OnInsertOrUpdate(Object[] entities)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.UniqueConstraintViolationAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.StaleObjectStateExceptionAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.PersistenceModel.DeadlockDetectionAspect.SoftPro.ServerModel.Aspects.IAspect.Process(Action method)
at Castle.DynamicProxy.AbstractInvocation.Proceed()
at SoftPro.Accounting.Server.Transactions.TransactionsManager.ApplyChanges(String reason, Boolean useIndividualReasons, Boolean postingChecks, ITransaction[] transactions)
at SoftPro.Accounting.Server.Transactions.TransactionsManager.ApplyChanges(String reason, ITransaction[] transactions)
at SoftPro.Accounting.Server.Transactions.TransactionsManagerService.ApplyChanges(String reason, Transaction[] transactions)
at SyncInvokeApplyChanges(Object , Object[] , Object[] )
at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc)
at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc)
at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage31(MessageRpc& rpc)
at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)
***********************************************************************************
Error: Transaction (Process ID 123) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
Stack Trace:
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientSqlCommandSet.ExecuteNonQuery()
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)

Claims:
Type=http://schemas.xmlsoap.org/ws/2005/05/i ... laims/hash, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=System.Byte[]
Type=http://schemas.xmlsoap.org/ws/2005/05/i ... identifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... t/identity, Resource=System.IdentityModel.Tokens.SamlNameIdentifierClaimResource
Type=http://schemas.xmlsoap.org/ws/2005/05/i ... identifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=System.IdentityModel.Tokens.SamlNameIdentifierClaimResource
Type=http://schemas.softprocorp.com/claims/sessionidentifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=5243d755-3176-47ae-a2ea-0a7a50741bb8
Type=http://schemas.softprocorp.com/claims/trusteeidentifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=08011c16-f370-417a-96df-72a501456141
Type=http://schemas.softprocorp.com/claims/trusteeusername, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=admin
Type=http://schemas.softprocorp.com/claims/d ... identifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=00000000-0000-0000-0000-000000000000
Type=http://schemas.softprocorp.com/claims/d ... identifier, Right=http://schemas.xmlsoap.org/ws/2005/05/i ... ssproperty, Resource=00000000-0000-0000-0000-000000000000
Action=http://schemas.softprocorp.com/select/t ... plyChanges, ReplyTo=http://schemas.microsoft.com/2005/12/Se ... /Anonymous, FaultTo=

[John Morris]

You're getting a sql deadlock. Can you provide more details about your test case?

[mrisen]

Here is the full method:

Code: Select all

        public void ApplyTemplateAndDisburse(string orderNumber)
        {
            var configuration = GetConfiguration();
            using (var selectServer = GetSelectServer(configuration))
            {
                var orderStore = selectServer.GetService<IOrderStore>();

                var orderInfo = orderStore.Orders.FirstOrDefault(x => x.Number == orderNumber);
                var order = orderStore.OpenOrder(orderInfo, false);
                var dynamicOrder = (dynamic) order;

                var accountsManager = selectServer.GetService<IAccountsManager>();
                var trustAccountInfo = accountsManager.TrustAccounts.FirstOrDefault(x => x.Code == "Test");

                order.SetTag("TrustAccountId", trustAccountInfo.ID.ToString());


                // Figure out which template to use
                string templateName;
                
                switch (orderInfo.State.Code)
                {
                    case "CA":
                    switch (orderInfo.SettlementType)
                    {
                        case SettlementType.HUD1:
                            templateName = "TestSPBankCA-Temp";
                            break;
                        case SettlementType.CDF:
                             templateName = "TestSPBankCA-CDF";
                           break;
                        default:
                            throw new Exception("Unrecognized Settlement Type");
                    }
                        break;
                    case "HI":
                    switch (orderInfo.SettlementType)
                    {
                        case SettlementType.HUD1:
                            templateName = "TestSPBankHI-Temp";
                            break;
                        case SettlementType.CDF:
                            templateName = "TestSPBankHI-CDF";
                            break;
                        default:
                            throw new Exception("Unrecognized Settlement Type");
                    }
                        break;
                    default:
                    switch (orderInfo.SettlementType)
                    {
                        case SettlementType.HUD1:
                            templateName = "TestSPBankWA-Temp";
                            break;
                        case SettlementType.CDF:
                            templateName = "TestSPBankWA-CDF";
                            break;
                        default:
                            throw new Exception("Unrecognized Settlement Type");
                    }
                        break;
                }

                var templateInfo = orderStore.Orders.FirstOrDefault((x => x.Number == templateName));
                var template = orderStore.OpenOrder(templateInfo, true);

                order.ApplyTemplate(template);

                try
                {
                    orderStore.ApplyChanges(dynamicOrder);
                }
                catch (Exception)
                {
                    Trace.WriteLine("----- Order Messages");
                    foreach (var message in order.GetMessages())
                    {
                        Trace.WriteLine(message.Text);
                    }
                    Trace.WriteLine("----- End Order Messages");

                    throw;
                }
                
                var orderId = orderInfo.Identifier.Guid;
                var ledgersManager = selectServer.GetService<ILedgersManager>();
                var ledgerInfo = ledgersManager.GetLedgerForOrder(orderId);
                var ledger = ledgersManager.GetLedger(ledgerInfo);
                var orderLedger = (IOrderLedger)ledger;
                var transactionsManager = selectServer.GetService<ITransactionsManager>();

                // load the full ledger object
                var ledgerOrderInfo = orderLedger.GetOrderInformation();

                foreach (var transactionInfo in ledger.Transactions)
                {
                    var transaction = transactionsManager.GetTransaction(transactionInfo);

                    if (transaction.Kind == TransactionKind.LedgerTransferOut)
                    {
                        var orderContactIDTags = transaction.Tags.Where(t => t.Name == "OrderContactID");

                        if (!orderContactIDTags.Any())
                        {
                            var underwriter = ledgerOrderInfo.Contacts.Single(c => c.Code == "U");
                            transaction.Tags.Add(new Tag("OrderContactID", underwriter.ID.ToString()));
                        }

                        var ledgerTransferOut = (ILedgerTransferOutTransaction) transaction;

                        var destinationLedgerName = "TestFeeLedger";
                        switch (orderInfo.State.Code)
                        {
                            // California, Colorado, and Florida are all handled by California
                            case "CA":
                            case "CO":
                            case "FL":
                                destinationLedgerName = "CATestFeeLedger";
                                break;
                            case "HI":
                                destinationLedgerName = "HITestFeeLedger";
                                break;
                        }

                        var destinationLedgerInfo = ledgersManager.Ledgers.Single(l => l.Name == destinationLedgerName);
                        var ledgerTransferIn = transactionsManager.NewLedgerTransferIn(ledgerTransferOut, destinationLedgerInfo, TransactionStatus.Posted, null);
                        transaction.Name = Constants.TestString;
                        transaction.Status = TransactionStatus.Posted;

                        try
                        {
                            transactionsManager.ApplyChanges(Constants.TestString, transaction);
                        }
                        catch (Exception e)
                        {
                            Trace.WriteLine("----------SQL Exception(s)----------");
                            Trace.WriteLine(e.Message);

                            while (e.InnerException != null)
                            {
                                e = e.InnerException;
                                Trace.WriteLine(e.Message);
                            }
                            throw;
                        }
                    }
                }
            }
        }

[mrisen]

Thoughts?

[John Morris]

You are getting SQL deadlock. You'd need to provide the SQL deadlock graph in order for us to help further. Can you provide that?

[mrisen]

Ok, I had to lookup how to do that. Looks like a useful thing to know, though I'm not 100% sure how to read the results. There are 2 deadlocks on this graph. Both relating to updating pt.SearchTransaction. One looks like a straightup deadlock while the other does not (all the requests are going in one direction). Hopefully you are familiar with this problem. Attached is the .xdl file.