TransactionScope - The underlying provider failed on EnlistTransaction. MSDTC being aborted

Question

Our team have got a problem that manifests as:

The underlying provider failed on EnlistTransaction; Cannot access a disposed object.Object name: 'Transaction'.

which seemed to appear as soon as we began using TransactionScope to handle our applications' transactions.

The top part of the stacktrace is captured as:

at System.Data.EntityClient.EntityConnection.EnlistTransaction(Transaction transaction) at System.Data.Objects.ObjectContext.EnsureConnection() at System.Data.Objects.ObjectContext.ExecuteStoreCommand(String commandText, Object[] parameters) at Reconciliation.Models.BillLines.BillLines.Reconciliation.Interfaces.IBillLineEntities.ExecuteStoreCommand(String, Object[]) at Reconciliation.Models.Legacy.EntityDbEnvironment.ExecuteOracleSql(String sql) in EntityDbEnvironment.cs: line 41

At the same time the MSDTC log is updated, which I've extracted using the instructions here:

pid=7060       ;tid=7908       ;time=04/29/2013-16:38:30.269   ;seq=136        ;eventid=TRANSACTION_BEGUN                        ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction has begun, description :'<NULL>'"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:30.269   ;seq=137        ;eventid=RM_ENLISTED_IN_TRANSACTION               ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"resource manager #1002 enlisted as transaction enlistment #1. RM guid = 'defc4277-47a6-4cd9-b092-93a668e2097b'"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=138        ;eventid=RECEIVED_ABORT_REQUEST_FROM_BEGINNER     ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"received request to abort the transaction from beginner"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=139        ;eventid=TRANSACTION_ABORTING                     ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction is aborting"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=140        ;eventid=RM_ISSUED_ABORT                          ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"abort request issued to resource manager #1002 for transaction enlistment #1"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=141        ;eventid=RM_ACKNOWLEDGED_ABORT                    ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"received acknowledgement of abort request from the resource manager #1002 for transaction enlistment #1"
pid=7060       ;tid=7908       ;time=04/29/2013-16:38:31.658   ;seq=142        ;eventid=TRANSACTION_ABORTED                      ;tx_guid=60f6390c-7570-488a-97a9-2c3912c4ca3e     ;"TM Identifier='(null)                                            '" ;"transaction has been aborted"

As you can see an RECEIVED_ABORT_REQUEST_FROM_BEGINNER a second after RM_ENLISTED_IN_TRANSACTION was logged.

We can't understand where this abort request originates from, or why it was raised. The SQL causing the problem is a simple SELECT which we can execute without issue via our database client.

The application works most of the time, only occasionally displaying this issue.

We are using Oracle 10.2.0.5.0 with Entity Framework.

UPDATE

Following advice from @Astrotrain I set up the logging on System.Transactions. The final entry produced is literally cut off half-way though:

....
<ApplicationData>
<TraceData>
<DataItem>
<TraceRecord xmlns="http://schemas.microsoft.com/2004/10/E2ETraceEvent/TraceRecord" Severity="Information">
<TraceIdentifier>http://msdn.microsoft.com/2004/06/System/Transactions/TransactionScopeCreated</TraceIdentifier>
<Description>TransactionScope Created</Description>
<AppDomain>BillLineGeneratorUI.exe</AppDomain>
<ExtendedData xmlns="http://schemas.microsoft.com/2004/03/Transactions/TransactionScopeCreatedTraceRecord">
<TraceSource>[Base]

As you can see the exception actually prevents the log finishing. What can I learn from this? Any ideas?

Ague

How do you start the transactions? Are they nested? Can you post some related code? I'm ruling out for now issues related to reachability between the two MSDTC instances which participate in the transaction. – Perri

Scratch that. See this: blogs.msdn.com/b/ajit/archive/2010/05/31/… – Perri

The abort is more than 1 sec after the beginning. Maybe you have a configuration automatic/connection/command/transaction timeout that is defined at 1 second (or 1000 ms), instead of a reasonable time. – Pillbox

What EF version are you using? Why ODAC version are you using? Why do you need to create your own scope? Did it ever work? The dbcontext automatically creates a scope when you call the SaveChanges method. – Stoke

Have you checked the MSDN blogs article from my earlier comment? It's just a matter of running Filemon and seeing if ORAMTS10.DLL is missing . If it is, then you can use the solution described there. – Perri

@marceln - Thanks but the application works most of the time, only occasionally displaying the issue. – Ague

Can you show us some code? I have seen this kind of error with shared resources and concurrency (web app for example), bad nested transactions management or wrong use of <using> clausule and/or variable scopes. – Lylalyle

We've have got nested transactions. I could show you something but I've no idea how id distill it into a manageable chunk. Transactions are opened once with a Using ts As New TransactionScope(TransactionScopeOption.Required, New TimeSpan(0, 0, 0, 0)) with the occasional nested TransactionScope using TransactionScopeOption.Suppress. Do you have any guidelines or pointers we can check against? – Ague

Answer 1

Instead of using the MSDTC trace tool (which I find horribly spartan), I can recommend using the System.Transactions trace source - just include the following in your web.config:
If you open the log files with SvcTraceViewer.exe you'll get a nice visual representation of the steps.

<configuration>
  <system.diagnostics>
   <trace autoflush="true" />
   <sources>
     <source name="System.Transactions" switchValue="Information">
       <listeners>
         <add name="tx"
              type="System.Diagnostics.XmlWriterTraceListener"
              initializeData="C:\MyApp-transactions-log.svclog" />
       </listeners>
     </source>
   </sources>
  </system.diagnostics>
</configuration>

Not a solution per se, but this might give you some more information about what goes wrong.

Ennoble

Great idea. The docs appear to be very WCF specific however I assume it's still applicable? – Ague

I don't think it's WCF-specific, the System.Transactions is just a regular TraceSource. The output format generated by the XmlWriterTraceListener does seem to be the same, but I know for a fact that you don't need to use it in combination with a WCF application. – Ennoble

I've managed to use this method to log the moment the exception occurs, it actually stops the log dead (mid tag). I've updated the question with more info. – Ague

@Ague Assuming that you used "<trace autoflush="true" />", the only way that I can think of to get a more complete log message is to use one of the other tracelisteners, e.g. see weblogs.asp.net/ralfw/… – Ennoble

Answer 2

As you mentioned "The application works most of the time, only occasionally displaying this issue." by this we can conclude that the provider does supports distributed transactions and the reason is some other intermittent glitch either in connection or handling.

• Are you using nested transaction scopes, because if, due to some reason, inner scope is rolled back (disposed without calling complete) that would immediately roll back the outer transaction causing the error. Use TransactionScopeOption.Required (RequiresNew will also do but RequiresNew has other deadlock related issues associated with it so it is better to use Required) to resolve this

• Otherwise it might be because of some other operation while the transaction is active and to resolve in this case use IsolationLevel = IsolationLevel.ReadCommitted.

Cyton

Answer 3

We had this problem too. The best way to solve it seems to open a new database connection and just do the things needed in the transaction. Keep transactions as small as possible is always good.

 DatabaseContext db1 = new DatabaseContext();

 doSomeDatabaseActions(db1);

 TransactionOptions transOpts = new TransactionOptions();
 transOpts.IsolationLevel = System.Transactions.IsolationLevel.Serializable;

 using (TransactionScope scope = new TransactionScope(TransactionScopeOption.Required, transOpts))
 {
     using (DatabaseContext db2 = new DatabaseContext())
     {
        doDatabaseChecksWithLock(db2);
        doChanges(db2);
        db2.SaveChanges();
     }

     scope.Complete();
  }

We had the problem without introducing the 2nd connection. Note that the error was also gone using 1 connection (db1) if the transaction was enlarged (made doSomeDatabaseActions part of the transaction).

Perished

Answer 4

This maybe should be a comment but it is too big. I hope it helps.

One of the most tipical error with nested transactions is this:

using(TransactionScope outerScope = new TransactionScope())
{
    // Execute query 1

    using(TransactionScope innerScope = new TransactionScope())
    {
        try
        {
            // Execute query 2
        }
        catch (Exception)
        {
        }

        innerScope.Complete();
    }

    outerScope.Complete();
}

Now if query 2 which is inside of the try/catch block, rasies an error you will catch the exception in the try/catch block and handle it, but here is a supprise the application will throw an ObjectDisposedException on line 15 when you try to complete the transaction. This is because the DTC has already caught the exception and although you have handled it, the TransactionScope objects where already disposed by the .Net code and the transaction has been rolled back. Notice that I have said “objects” this is because both of the TransactionScope object have been disposed as they are a part of the same transaction.

Lylalyle

How do I handle / prevent this situation occurring? – Ague