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?

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.