Test failure in System.Transactions.Tests.OleTxTests.Volatile_and_durable_enlistments

[buyaa-n]

Test failure in System.Transactions.Tests.OleTxTests, found in https://github.com/dotnet/runtime/pull/73748/checks?check_run_id=7812731906
LOG: https://helix.dot.net/api/2019-06-17/jobs/3d6ddf47-29eb-453d-96aa-7f19f2e55bc6/workitems/System.Transactions.Local.Tests/console

    System.Transactions.Tests.OleTxTests.Volatile_and_durable_enlistments(volatileCount: 0) [FAIL]
      System.NullReferenceException : Object reference not set to an instance of an object.
      Stack Trace:
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/DtcProxyShim/DtcProxyShimFactory.cs(315,0): at System.Transactions.DtcProxyShim.DtcProxyShimFactory.GetCachedOptions()
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/DtcProxyShim/DtcProxyShimFactory.cs(143,0): at System.Transactions.DtcProxyShim.DtcProxyShimFactory.BeginTransaction(UInt32 timeout, OletxTransactionIsolationLevel isolationLevel, Object managedIdentifier, Guid& transactionIdentifier, TransactionShim& transactionShim)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/OletxTransactionManager.cs(448,0): at System.Transactions.Oletx.OletxTransactionManager.CreateTransaction(TransactionOptions properties)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs(2172,0): at System.Transactions.TransactionStatePromoted.EnterState(InternalTransaction tx)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs(549,0): at System.Transactions.EnlistableStates.EnlistDurable(InternalTransaction tx, Guid resourceManagerIdentifier, IEnlistmentNotification enlistmentNotification, EnlistmentOptions enlistmentOptions, Transaction atomicTransaction)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Transaction.cs(503,0): at System.Transactions.Transaction.EnlistDurable(Guid resourceManagerIdentifier, IEnlistmentNotification enlistmentNotification, EnlistmentOptions enlistmentOptions)
        /_/src/libraries/System.Transactions.Local/tests/OleTxTests.cs(109,0): at System.Transactions.Tests.OleTxTests.Volatile_and_durable_enlistments(Int32 volatileCount)
           at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
        /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(64,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
  Finished:    System.Transactions.Local.Tests
=== TEST EXECUTION SUMMARY ===
   System.Transactions.Local.Tests  Total: 289, Errors: 0, Failed: 1, Skipped: 0, Time: 24,766s

[danmoseley]

@roji

[roji]

Will take a look, thanks.

[roji]

@danmoseley:

• Do we capture ETW logs for these test runs? There may be some valuable information there for diagnosing this.
• Is there a way to keep track of this failing test, so that I'm informed of more failures?

Notes (mainly to self):

• xunit happens to run the failing test first (Volatile_and_durable_enlistments). It also has 3 parameterized cases (volatileCount=0,1,2), and only the first fails. So this seems like a "very first time" failure, possibly as a result of MSDTC not yet being ready.
• The stack trace shows _transactionDispenser being null in DtcProxyShimFactory.cs:315. This isn't supposed to be possible...
• Going up the stack, this is called from OletxTransactionManager.CreateTransaction (448), where BeginTransaction is called.
• But BeginTransaction is invoked on _dtcTransactionManager.ProxyShimFactory, and ProxyShimFactory is a getter which calls Initialize(), eventually calling DtcProxyShimFactory.ConnectToProxy, which sets _transactionDispenser.
• Note that the ProxyShimFactory getter completed successfully, and I can't see exceptions being swallowed anywhere inside in the path.
• One theoretical possibility is that the ProxyShimFactory getter exited without calling Initialize(), because _whereabouts was non-null. The only I can see for _whereabouts to be non-null and _transactionDispenser to be null is if an exception was thrown in ConnectToProxy before setting the _transactionDispenser: when the whereabouts out param is set, that sets the member variable directly on DtcTransactionManager - #73918 fixes that by setting the out parameter only at the end of the method, after any exceptions which may get thrown.
• However, AFAICT our invocation is the very first one; there's no previous invocation which could fail, leaving us in this bad state.

[jakobbotsch]

We are also seeing win-arm64 failures on this test in libraries-jitstress runs but with a different message.
Example failure: https://dev.azure.com/dnceng/public/_build/results?buildId=1942500&view=ms.vss-test-web.build-test-results-tab&runId=50062640&resultId=200894&paneView=debug
Example log: https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-7009fae360db496db1/System.Transactions.Local.Tests/1/console.08fd122e.log?helixlogtype=result

Message:

  Starting:    System.Transactions.Local.Tests (parallel test collections = on, max threads = 8)
    System.Transactions.Tests.OleTxTests.Volatile_and_durable_enlistments(volatileCount: 0) [FAIL]
      System.Transactions.TransactionException : The operation is not valid for the state of the transaction.
      ---- System.Transactions.TransactionManagerCommunicationException : Communication with the underlying transaction manager has failed.
      -------- System.Runtime.InteropServices.COMException : The Transaction Manager is not available. (0x8004D01B)
      Stack Trace:
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs(203,0): at System.Transactions.TransactionState.EnlistDurable(InternalTransaction tx, Guid resourceManagerIdentifier, IEnlistmentNotification enlistmentNotification, EnlistmentOptions enlistmentOptions, Transaction atomicTransaction)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs(552,0): at System.Transactions.EnlistableStates.EnlistDurable(InternalTransaction tx, Guid resourceManagerIdentifier, IEnlistmentNotification enlistmentNotification, EnlistmentOptions enlistmentOptions, Transaction atomicTransaction)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Transaction.cs(503,0): at System.Transactions.Transaction.EnlistDurable(Guid resourceManagerIdentifier, IEnlistmentNotification enlistmentNotification, EnlistmentOptions enlistmentOptions)
        /_/src/libraries/System.Transactions.Local/tests/OleTxTests.cs(109,0): at System.Transactions.Tests.OleTxTests.Volatile_and_durable_enlistments(Int32 volatileCount)
           at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
        /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(64,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
        ----- Inner Stack Trace -----
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/OletxTransactionManager.cs(613,0): at System.Transactions.Oletx.OletxTransactionManager.ProxyException(COMException comException)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/DtcTransactionManager.cs(63,0): at System.Transactions.Oletx.DtcTransactionManager.Initialize()
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/DtcTransactionManager.cs(79,0): at System.Transactions.Oletx.DtcTransactionManager.get_ProxyShimFactory()
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/OletxTransactionManager.cs(448,0): at System.Transactions.Oletx.OletxTransactionManager.CreateTransaction(TransactionOptions properties)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs(2172,0): at System.Transactions.TransactionStatePromoted.EnterState(InternalTransaction tx)
        ----- Inner Stack Trace -----
           at System.Transactions.DtcProxyShim.DtcInterfaces.ITransactionImportWhereabouts.GetWhereaboutsSize(UInt32& pcbSize)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/DtcProxyShim/DtcProxyShimFactory.cs(87,0): at System.Transactions.DtcProxyShim.DtcProxyShimFactory.<>c__DisplayClass10_0.<ConnectToProxy>b__0()
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/DtcProxyShim/OletxHelper.cs(41,0): at System.Transactions.DtcProxyShim.OletxHelper.Retry(Action action)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/DtcProxyShim/DtcProxyShimFactory.cs(87,0): at System.Transactions.DtcProxyShim.DtcProxyShimFactory.ConnectToProxy(String nodeName, Guid resourceManagerIdentifier, Object managedIdentifier, Boolean& nodeNameMatches, Byte[]& whereabouts, ResourceManagerShim& resourceManagerShim)
        /_/src/libraries/System.Transactions.Local/src/System/Transactions/Oletx/DtcTransactionManager.cs(38,0): at System.Transactions.Oletx.DtcTransactionManager.Initialize()

[roji]

@jakobbotsch thanks. Yeah, I suspect the root cause here is the same as the NRT posted above, #73918 may eliminate the NRT itself and make the real exception propagate.

As written above, tes Volatile_and_durable_enlistments with volatileCount=0 is the very first test which communicates with MSDTC, and the stack trace shows the communication failure happening on the very first attempt to connect to it (ConnectToProxy). MSDTC has an on-demand feature, where it's disabled by default on Windows boot, and then the first call to it (DtcGetTransactionManagerEx) starts is "on demand". This call throws XACT_E_TMNOTAVAILABLE, but only on the very first connection; so I suspect that in our CI environment the MSDTC starts too slowly or similar, causing the first failure, but by the time the 2nd test runs, all is OK.

I'll work around this by using a class fixture to trigger DtcGetTransactionManagerEx multiple times, as necessary, before the first test runs. If we see users complaining about this, we can consider some sort of loop inside Sys.Tx itself.