BUG: SqlDelegatedTransaction hides promoteException

[ionmincu]

Description

Sometimes on our servers we see the exception below. I think this is a problem because it hides the underlying promoteException

Excepton message:

The operation is not valid for the state of the transaction.

Issue #784 seems to present the same stacktrace (second one) .

This mentions #543 which seems to be the culprid because they introduced a new if statement and checks the status here

                //Throw exception only if Transaction is still active and not yet aborted.
                if (promoteException != null && Transaction.TransactionInformation.Status != TransactionStatus.Aborted)
                {
                    throw SQL.PromotionFailed(promoteException);
                }

Source: https://github.com/dotnet/SqlClient/pull/543/files#diff-318a0b3769dd34240f6758ac2efc7fc599875e28230753d10d438f6a1c797fbfR211

Stacktrace:

Linux x64

0 { "method":"System.Transactions.TransactionStatePSPEOperation.get_Status",     "level":0, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }
1 { "method":"System.Transactions.TransactionInformation.get_Status",            "level":1, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }
2 { "method":"System.Data.SqlClient.SqlDelegatedTransaction.Promote",            "level":2, "line":0, "assembly":"System.Data.SqlClient,     Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a" }
3 { "method":"System.Transactions.TransactionStatePSPEOperation.PSPEPromote",    "level":3, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }
4 { "method":"System.Transactions.TransactionStateDelegatedNonMSDTC.EnterState", "level":4, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }
5 { "method":"System.Transactions.EnlistableStates.PromotedToken",               "level":5, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }
6 { "method":"System.Transactions.Transaction.GetPromotedToken",                 "level":6, "line":0, "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51" }


0  { "method":"System.RuntimeMethodHandle.InvokeMethod",                                                     "assembly":"System.Private.CoreLib, Version=5.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e",    "level":0,"line":0}
1  { "method":"System.Data.SqlClient.SqlInternalConnection.EnlistNonNull",                                   "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":1,"line":0}
2  { "method":"System.Data.ProviderBase.DbConnectionPool.PrepareConnection",                                 "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":2,"line":0}
3  { "method":"System.Data.ProviderBase.DbConnectionPool.TryGetConnection",                                  "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":3,"line":0}
4  { "method":"System.Data.ProviderBase.DbConnectionPool.TryGetConnection",                                  "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":4,"line":0}
5  { "method":"System.Data.ProviderBase.DbConnectionFactory.TryGetConnection",                               "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":5,"line":0}
6  { "method":"System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal",                     "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":6,"line":0}
7  { "method":"System.Data.SqlClient.SqlConnection.TryOpen",                                                 "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":7,"line":0}
8  { "method":"System.Data.SqlClient.SqlConnection.Open",                                                    "assembly":"System.Data.SqlClient, Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",     "level":8,"line":0}
9  { "method":"System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch",                "assembly":"EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089",           "level":9,"line":0}
10 { "method":"System.Data.Entity.Infrastructure.Interception.DbConnectionDispatcher.Open",                  "assembly":"EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089",           "level":10,"line":0}
11 { "method":"System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy+<>c__DisplayClass2_0.<Execute>b__0", "assembly":"EntityFramework.SqlServer, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089", "level":11,"line":0}
12 { "method":"System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute",                            "assembly":"EntityFramework.SqlServer, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089", "level":12,"line":0}
13 { "method":"System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute",                            "assembly":"EntityFramework.SqlServer, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089", "level":13,"line":0}
14 { "method":"System.Data.Entity.Core.EntityClient.EntityConnection.Open",                                  "assembly":"EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089",           "level":14,"line":0}

We found the same stack trace under a Windows environment as well

Windows x64

0 { "method":"System.Transactions.TransactionStatePSPEOperation.get_Status",     "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":0,"line":0 }
1 { "method":"System.Transactions.TransactionInformation.get_Status",            "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":1,"line":0 }
2 { "method":"System.Data.SqlClient.SqlDelegatedTransaction.Promote",            "assembly":"System.Data.SqlClient,     Version=4.6.1.2, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a", "level":2,"line":0 }
3 { "method":"System.Transactions.TransactionStatePSPEOperation.PSPEPromote",    "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":3,"line":0 }
4 { "method":"System.Transactions.TransactionStateDelegatedNonMSDTC.EnterState", "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":4,"line":0 }
5 { "method":"System.Transactions.EnlistableStates.PromotedToken",               "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":5,"line":0 }
6 { "method":"System.Transactions.Transaction.GetPromotedToken",                 "assembly":"System.Transactions.Local, Version=5.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51", "level":6,"line":0 }

Configuration

• Runtime Linux x64 (first stack trace), Windows x64 (second trace)
• dotnet 5.0.203

Regression?

• Not sure if this is a regression

Related

• first I opened an issue here, BUG: TransactionStatePSPEOperation throws exception in valid enviroment runtime#55337, but after some investigation I think the bug is from this repo with that mentioned if where a getter is called on Transaction.TransactionInformation.Status

[cheenamalhotra]

Hi @ionmincu

Thanks for sharing details. I'm working on a PR to address this.

[ionmincu]

@cheenamalhotra any updates on this?

[ionmincu]

@cheenamalhotra any updates on this?

Any ideea on how can I get better insights into this issue?

[cheenamalhotra]

Hi @ionmincu

Sorry I was diverted to other activities, I created PR #1216 that should fix this issue, would you be willing to try and let us know if this change works for you?

[ionmincu]

@cheenamalhotra
Thank you,

Aparently we are using System.Data.SqlClient, I'm trying to do a migration to Microsoft.Data.SqlClient, if you could make a nuget package for branch this I think I could test it out.

[cheenamalhotra]

Thanks, that would be helpful.
You can find package for this PR validation here: Published Artifacts

[ionmincu]

@cheenamalhotra using https://www.nuget.org/packages/ErikEJ.EntityFramework.SqlServer/6.4.0 package I was unable to reproduce the bug in Microsoft.Data.SqlClient version 2.1.3, but our way of reproducing this is just running some integration tests and sometimes this issue appears.

[cheenamalhotra]

I understand this can be hard to reproduce. If you know of the test case that fails for you, you could capture logs and try to force the situation. That can help identify reproducible scenario.

If it's related to concurrency, I'd recommend increasing load to make it fail more often.

[ionmincu]

I tried running our integration tests countless times on smaller vms even and it does not seem to reproduce.
Unfortunately there is no specific test case that this fails on, it fails randomly on some builds (i would say about 10-15% on the builds with smaller vms and SDS).

I will try to repro on MDS with even smaller VMs and reduce cpu time to sql server.

Also regarding SQL Server we have seen this on SQL Azure and SQL Sever 2019 on linux Docker.

[ionmincu]

@cheenamalhotra I could not repro this on Microsoft.Data.SqlClient version 2.1.3 with sql server limited cpu (artificially via docker).
When running with 0.25 CPUs we get 20-40 lock timeout operations caused by

DECLARE @result int;
EXEC @result = sp_getapplock @Resource, @LockMode, @LockOwner, @LockTimeout;
SELECT @result

-- values
@LockMode = Exclusive
@LockOwner = Transaction

When running with 0.1 CPU we get quite a few operation timeouts, but no TransactionPSPE in logs 😢

[ionmincu]

@cheenamalhotra after we switched to Microsoft.Data.SqlClient using ErikEJ.EntityFramework.SqlServer entity framework adapter, we are seeing the error A LOT LESS, like less than 1% of the time. But it is still there for some reason. I noticed you fixed it in #1216 (thank you). If it helps here is the stacktrace with MDS without the fix.

Inner exception System.Reflection.TargetInvocationException handled at System.Data.Entity.Core.EntityClient.EntityConnection.Open:
   at System.RuntimeMethodHandle.InvokeMethod                                                                 (System.Private.CoreLib,           Version=5.0.0.0,     Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.Data.SqlClient.SqlInternalConnection.EnlistNonNull                                            (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.ProviderBase.DbConnectionPool.PrepareConnection                                          (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.ProviderBase.DbConnectionPool.TryGetConnection                                           (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.ProviderBase.DbConnectionPool.TryGetConnection                                           (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection                                        (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal                              (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen                                                          (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at Microsoft.Data.SqlClient.SqlConnection.Open                                                             (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch                            (EntityFramework,                  Version=6.0.0.0,     Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Infrastructure.Interception.DbConnectionDispatcher.Open                              (EntityFramework,                  Version=6.0.0.0,     Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy+<>c__DisplayClass2_0.<Execute>b__0             (ErikEJ.EntityFramework.SqlServer, Version=6.0.0.0,     Culture=neutral, PublicKeyToken=3f85300590faaa00: /_/src/ErikEJ.EntityFramework.SqlServer/DefaultSqlExecutionStrategy.cs:33)
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute                                        (ErikEJ.EntityFramework.SqlServer, Version=6.0.0.0,     Culture=neutral, PublicKeyToken=3f85300590faaa00: /_/src/ErikEJ.EntityFramework.SqlServer/DefaultSqlExecutionStrategy.cs:52)
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute                                        (ErikEJ.EntityFramework.SqlServer, Version=6.0.0.0,     Culture=neutral, PublicKeyToken=3f85300590faaa00: /_/src/ErikEJ.EntityFramework.SqlServer/DefaultSqlExecutionStrategy.cs:26)
   at System.Data.Entity.Core.EntityClient.EntityConnection.Open                                              (EntityFramework,                  Version=6.0.0.0,     Culture=neutral, PublicKeyToken=b77a5c561934e089)
Inner exception System.Transactions.TransactionException handled at System.RuntimeMethodHandle.InvokeMethod:
   at System.Transactions.TransactionStatePSPEOperation.get_Status                                            (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs:4402)
   at System.Transactions.TransactionInformation.get_Status                                                   (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionInformation.cs:98)
   at Microsoft.Data.SqlClient.SqlDelegatedTransaction.Promote                                                (Microsoft.Data.SqlClient,         Version=2.0.20168.4, Culture=neutral, PublicKeyToken=23ec7fc2d6eaa4a5)
   at System.Transactions.TransactionStatePSPEOperation.PSPEPromote                                           (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs:4483)
   at System.Transactions.TransactionStateDelegatedNonMSDTC.EnterState                                        (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs:4321)
   at System.Transactions.EnlistableStates.PromotedToken                                                      (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionState.cs:661)
   at System.Transactions.Transaction.GetPromotedToken                                                        (System.Transactions.Local,        Version=5.0.0.0,     Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51: /_/src/libraries/System.Transactions.Local/src/System/Transactions/Transaction.cs:475)

[ErikEJ]

@ionmincu I think this was only fixed in 3.0.1 , and unless you have done something special, ErikEJ.EntityFramework.SqlServer uses 2.1.3 at the moment. Maybe I should update to 3.0.1?

[ionmincu]

I know it was fixed in 3.0.1 but only the error handling not necessary the underlying problem itself that's why I posted the stacktrace, maybe it helps. And yeah I'm not sure why it says Microsoft.Data.SqlClient, Version=2.0.20168.4