Test failure System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

[v-wenyuxu]

Failed in: runtime-coreclr libraries-pgo 20230806.1

Failed tests:

net8.0-windows-Release-x86-CoreCLR_checked-fullpgo_random_gdv_methodprofiling_only-Windows.10.Amd64.Open
    - System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

Error message:

Assert.Equal() Failure
Expected: 00:02:00
Actual:   00:01:00

Stack trace:

   at System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get() in /_/src/libraries/System.Transactions.Local/tests/TransactionManagerTest.cs:line 15
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

[ghost]

Tagging subscribers to this area: @roji, @ajcvickers
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Failed in: runtime-coreclr libraries-pgo 20230806.1

Failed tests:

net8.0-windows-Release-x86-CoreCLR_checked-fullpgo_random_gdv_methodprofiling_only-Windows.10.Amd64.Open
    - System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

Error message:

Assert.Equal() Failure
Expected: 00:02:00
Actual:   00:01:00

Stack trace:

   at System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get() in /_/src/libraries/System.Transactions.Local/tests/TransactionManagerTest.cs:line 15
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

Author:	v-wenyuxu
Assignees:	-
Labels:	arch-x86, area-System.Transactions, os-windows, blocking-clean-ci-optional
Milestone:	-

[AaronRobinsonMSFT]

Work was recently done in these Invoker paths.

/cc @steveharter

[v-wenyuxu]

Failed again in: runtime-coreclr libraries-jitstress 20240103.5

Failed tests:

net9.0-windows-Release-x86-CoreCLR_checked-jitstress1_tiered-Windows.10.Amd64.Open
    - System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

Error message:

Assert.Equal() Failure: Values differ
Expected: 00:02:00
Actual:   00:01:00

Stack trace:

   at System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get() in /_/src/libraries/System.Transactions.Local/tests/TransactionManagerTest.cs:line 15
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

[VincentBu]

Failed in: runtime-coreclr libraries-pgo 20240211.1

Failed tests:

net9.0-linux-Release-x64-CoreCLR_checked-fullpgo_random_gdv_methodprofiling_only-Ubuntu.2204.Amd64.Open
    - System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

Error message:

 Assert.Equal() Failure: Values differ
Expected: 00:02:00
Actual:   00:01:00

Stack trace:

    at System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get() in /_/src/libraries/System.Transactions.Local/tests/TransactionManagerTest.cs:line 15
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

[BruceForstall]

@AndyAyersMS Looks like it mostly fails in PGO stress?

[AndyAyersMS]

The test is

        [Fact]
        public void DefaultTimeout_MaxTimeout_Set_Get()
        {
            TimeSpan tsDefault = TimeSpan.Parse("00:02:00");
            TransactionManager.DefaultTimeout = tsDefault;
            Assert.Equal(tsDefault, TransactionManager.DefaultTimeout);

where the initial value of the default timeout is 01:00.

The property getter/setter is nontrivial

runtime/src/libraries/System.Transactions.Local/src/System/Transactions/TransactionManager.cs

Lines 292 to 344 in eece6a6

	public static TimeSpan DefaultTimeout
	{
	get
	{
	TransactionsEtwProvider etwLog = TransactionsEtwProvider.Log;
	if (etwLog.IsEnabled())
	{
	etwLog.MethodEnter(TraceSourceType.TraceSourceBase, "TransactionManager.get_DefaultTimeout");
	}
	if (!s_defaultTimeoutValidated)
	{
	LazyInitializer.EnsureInitialized(ref s_defaultTimeoutTicks, ref s_defaultTimeoutValidated, ref s_classSyncObject, () => ValidateTimeout(DefaultSettingsSection.Timeout).Ticks);
	if (Interlocked.Read(ref s_defaultTimeoutTicks) != DefaultSettingsSection.Timeout.Ticks)
	{
	if (etwLog.IsEnabled())
	{
	etwLog.ConfiguredDefaultTimeoutAdjusted();
	}
	}
	}
	if (etwLog.IsEnabled())
	{
	etwLog.MethodExit(TraceSourceType.TraceSourceBase, "TransactionManager.get_DefaultTimeout");
	}
	return new TimeSpan(Interlocked.Read(ref s_defaultTimeoutTicks));
	}
	set
	{
	TransactionsEtwProvider etwLog = TransactionsEtwProvider.Log;
	if (etwLog.IsEnabled())
	{
	etwLog.MethodEnter(TraceSourceType.TraceSourceBase, "TransactionManager.set_DefaultTimeout");
	}
	Interlocked.Exchange(ref s_defaultTimeoutTicks, ValidateTimeout(value).Ticks);
	if (Interlocked.Read(ref s_defaultTimeoutTicks) != value.Ticks)
	{
	if (etwLog.IsEnabled())
	{
	etwLog.ConfiguredDefaultTimeoutAdjusted();
	}
	}
	s_defaultTimeoutValidated = true;
	if (etwLog.IsEnabled())
	{
	etwLog.MethodExit(TraceSourceType.TraceSourceBase, "TransactionManager.set_DefaultTimeout");
	}
	}
	}

The original PR #71703 noted there was a potential problem with tearing reads on a 32 bit platform, I wonder if it is still there but just harder to observe, and these tests manage to delay execution just the right way (on occasion).

FYI @mconnew in case this is a latent test issue.

[v-wenyuxu]

Failed in: runtime-coreclr libraries-pgo 20240310.1

Failed tests:

net9.0-windows-Release-x64-CoreCLR_checked-jitosr_stress_random-Windows.10.Amd64.Open
    - System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get

Error message:

 Assert.Equal() Failure: Values differ
Expected: 00:02:00
Actual:   00:01:00

Stack trace:

   at System.Transactions.Tests.TransactionManagerTest.DefaultTimeout_MaxTimeout_Set_Get() in /_/src/libraries/System.Transactions.Local/tests/TransactionManagerTest.cs:line 15
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

[AndyAyersMS]

Seems to no longer be a problem.