Failure in RunThreadLocalTest5_Dispose

[danmoseley]

https://dev.azure.com/dnceng/public/_build/results?buildId=1271572&view=ms.vss-test-web.build-test-results-tab&runId=37617006&resultId=187161&paneView=debug
net6.0-Linux-Debug-x64-Mono_release-(Fedora.34.Amd64.Open)[email protected]/dotnet-buildtools/prereqs:fedora-34-helix-20210728124700-4f64125

Not much to go on. Suggestion: assert the return value here is true. Then next failure we will know whether it timed out (suggesting possibly it needs to wait more than 60 sec) or something else.

https://github.com/danmoseley/runtimelab/blob/3483068cf9a7adb7a24e9d2b6b21679ae5d2b2ff/src/libraries/System.Threading/tests/ThreadLocalTests.cs#L131-L139

            SpinWait.SpinUntil(() =>
            {
                GC.Collect();
                GC.WaitForPendingFinalizers();
                GC.Collect();
                return mres.IsSet;
            }, ThreadTestHelpers.UnexpectedTimeoutMilliseconds);


            Assert.True(mres.IsSet);

Assert.True() Failure
Expected: True
Actual:   False


Stack trace
   at System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose() in /_/src/libraries/System.Threading/tests/ThreadLocalTests.cs:line 139
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/mono/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 370

Runfo Tracking Issue: System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose

Build	Definition	Kind	Run Name	Console	Core Dump	Test Results	Run Client
1444163	runtime	Rolling	net7.0-Linux-Release-x64-Mono_release-RedHat.7.Amd64.Open	console.log			runclient.py
1432003	runtime	PR 60682	net6.0-Linux-Debug-x64-Mono_release-SLES.15.Amd64.Open	console.log			runclient.py
1427196	runtime	PR 60553	net7.0-OSX-Debug-x64-Mono_release-OSX.1015.Amd64.Open	console.log			runclient.py
1410737	runtime	PR 60200	net7.0-OSX-Debug-x64-Mono_release-OSX.1015.Amd64.Open	console.log			runclient.py

Build Result Summary

Day Hit Count	Week Hit Count	Month Hit Count
1	1	4

[ghost]

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

Issue Details

---

https://dev.azure.com/dnceng/public/_build/results?buildId=1271572&view=ms.vss-test-web.build-test-results-tab&runId=37617006&resultId=187161&paneView=debug
net6.0-Linux-Debug-x64-Mono_release-(Fedora.34.Amd64.Open)[email protected]/dotnet-buildtools/prereqs:fedora-34-helix-20210728124700-4f64125

Not much to go on. Suggestion: assert the return value here is true. Then next failure we will know whether it timed out (suggesting possibly it needs to wait more than 60 sec) or something else.
https://github.com/danmoseley/runtimelab/blob/3483068cf9a7adb7a24e9d2b6b21679ae5d2b2ff/src/libraries/System.Threading/tests/ThreadLocalTests.cs#L131

Assert.True() Failure
Expected: True
Actual:   False


Stack trace
   at System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose() in /_/src/libraries/System.Threading/tests/ThreadLocalTests.cs:line 139
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/mono/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 370

Author:	danmoseley
Assignees:	-
Labels:	area-System.Threading
Milestone:	-

[danmoseley]

cc @kouvel

[kouvel]

This could have timed out due to #55796 depending on the order in which tests ran on the same thread, will see if it fails again after the fix

[danmoseley]

@kouvel what do you think of changing all the SpinWait.SpinUntil(.. , timeout) in our tests to assert the return value? Some do already. Of course not those that just do SpinWait.SpinUntil(() => false, ...)

That might make future failures easier to reason about.

[kouvel]

In this case it seems clear to me that it would have timed out, as that's the only way the assertion would have failed. I'd prefer using the wait helpers in ThreadTestHelpers instead for this sort of stuff, but that's probably newer than these tests.

[ViktorHofer]

Failed again in https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-58314-merge-0e292e5745a3493ca8/System.Threading.Tests/1/console.393c4276.log?sv=2019-07-07&se=2021-09-19T14%3A59%3A48Z&sr=c&sp=rl&sig=fhlRR2MVDyQ61ZP7Byme1Bfr3ES2bafCwufZRGPOWOE%3D.

Build: https://dev.azure.com/dnceng/public/_build/results?buildId=1328371&view=ms.vss-test-web.build-test-results-tab&runId=38984868&resultId=187108&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

  Discovering: System.Threading.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Threading.Tests (found 206 of 239 test cases)
  Starting:    System.Threading.Tests (parallel test collections = on, max threads = 2)
    System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest8_Values_NegativeCases [SKIP]
      Condition(s) not met: "IsPreciseGcSupported"
    System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose [FAIL]
      Assert.True() Failure
      Expected: True
      Actual:   False
      Stack Trace:
        /_/src/libraries/System.Threading/tests/ThreadLocalTests.cs(139,0): at System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose()
        /_/src/mono/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs(370,0): at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
    System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest7_WeakReference [SKIP]
      Condition(s) not met: "IsPreciseGcSupported"
  Finished:    System.Threading.Tests
=== TEST EXECUTION SUMMARY ===
   System.Threading.Tests  Total: 474, Errors: 0, Failed: 1, Skipped: 2, Time: 70.472s

[danmoseley]

@kouvel another hit: #59194

[VincentBu]

Failed again in: runtime 20211008.6

Failed test:

net7.0-Linux-Release-x64-Mono_release-(Debian.10.Amd64.Open)[email protected]/dotnet-buildtools/prereqs:debian-10-helix-amd64-20210304164434-56c6673
System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose

Error message:

Assert.True() Failure
Expected: True
Actual:   False


Stack trace
   at System.Threading.Tests.ThreadLocalTests.RunThreadLocalTest5_Dispose() in /_/src/libraries/System.Threading/tests/ThreadLocalTests.cs:line 139
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/mono/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 370

[krwq]

@kouvel ping, can you please disable the test while investigation is pending? If you can't repro please add some extra diagnostic to a test so that it can be actionable or closer to actionable on next hit

[kouvel]

Looks like the test is failing on Mono, probably due to conservative GC, #60892 is fixing that