Hang/timeout in tests for Browser wasm Release AllSubsets_Mono

[danmoseley]

2020-08-07T16:57:55.4437411Z   Sending Job to Ubuntu.1804.Amd64.Open...
2020-08-07T17:02:10.6813852Z   Sent Helix Job e7fed000-94bb-45ab-950e-2403ad3753b5
2020-08-07T17:02:11.7013998Z   Waiting for completion of job e7fed000-94bb-45ab-950e-2403ad3753b5 on Ubuntu.1804.Amd64.Open
2020-08-07T17:30:35.4257384Z   Job e7fed000-94bb-45ab-950e-2403ad3753b5 on Ubuntu.1804.Amd64.Open is completed with 209 finished work items.
2020-08-07T17:30:36.1014417Z   Stopping Azure Pipelines Test Run -Browser-Release-wasm-Mono_Release-Ubuntu.1804.Amd64.Open
2020-08-07T17:30:36.3391733Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/5.0.0-beta.20374.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(76,5): error : Work item e7fed000-94bb-45ab-950e-2403ad3753b5/System.Runtime.Tests in job e7fed000-94bb-45ab-950e-2403ad3753b5 has failed. [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2020-08-07T17:30:36.3393772Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/5.0.0-beta.20374.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(76,5): error : Failure log: https://helix.dot.net/api/2019-06-17/jobs/e7fed000-94bb-45ab-950e-2403ad3753b5/workitems/System.Runtime.Tests/console [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2020-08-07T17:30:36.3483318Z ##[error].packages/microsoft.dotnet.helix.sdk/5.0.0-beta.20374.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(76,5): error : (NETCORE_ENGINEERING_TELEMETRY=Test) Work item e7fed000-94bb-45ab-950e-2403ad3753b5/System.Runtime.Tests in job e7fed000-94bb-45ab-950e-2403ad3753b5 has failed.
Failure log: https://helix.dot.net/api/2019-06-17/jobs/e7fed000-94bb-45ab-950e-2403ad3753b5/workitems/System.Runtime.Tests/console
2020-08-07T17:30:36.3509024Z 
2020-08-07T17:30:36.3509528Z Build FAILED.
2020-08-07T17:30:36.3509769Z 
2020-08-07T17:30:36.3511286Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/5.0.0-beta.20374.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(76,5): error : Work item e7fed000-94bb-45ab-950e-2403ad3753b5/System.Runtime.Tests in job e7fed000-94bb-45ab-950e-2403ad3753b5 has failed. [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2020-08-07T17:30:36.3513185Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/5.0.0-beta.20374.1/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(76,5): error : Failure log: https://helix.dot.net/api/2019-06-17/jobs/e7fed000-94bb-45ab-950e-2403ad3753b5/workitems/System.Runtime.Tests/console [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2020-08-07T17:30:36.3514081Z     0 Warning(s)
2020-08-07T17:30:36.3514365Z     1 Error(s)
2020-08-07T17:30:36.3514602Z 
2020-08-07T17:30:36.3514876Z Time Elapsed 00:32:49.13
2020-08-07T17:30:36.3803881Z ##[error]Build failed (exit code '1').
2020-08-07T17:30:36.3839022Z 
2020-08-07T17:30:36.3881917Z ##[error]Bash exited with code '1'.
2020-08-07T17:30:36.4332912Z ##[section]Finishing: Send to Helix

https://helix.dot.net/api/2019-06-17/jobs/e7fed000-94bb-45ab-950e-2403ad3753b5/workitems/System.Runtime.Tests/console
https://dev.azure.com/dnceng/public/_build/results?buildId=761619&view=logs&jobId=108d2c4a-8a62-5a58-8dad-8e1042acc93c&j=108d2c4a-8a62-5a58-8dad-8e1042acc93c&t=09a92b4c-3493-52a9-1172-0680b62c9e30

last lines of console

      
[17:18:21] dbug: test[0]
      [PASS] System.Tests.ArrayTests.CreateInstance_Advanced(elementType: typeof(int), lengths: [1], lowerBounds: [0], repeatedValue: 0)
      
Killed

I guess whatever the next test was (not logged) just hung and then it timed out 12 mins later? Can we make it log the test before it starts it, so we have a clue which?

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

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

[danmoseley]

cc @lewing

[safern]

I've noticed System.Runtime tests are huge and they take an average of 9-12 mins. The timeout in helix is 12 minutes. Maybe we should bump the timeout for wasm workitems?

[safern]

Actually looking at the timestamps it looks like a legit hang. It just ran for 3 mins.

[17:15:27] dbug: test[0]
      Arguments: --run,WasmTestRunner.dll,System.Runtime.Tests.dll,-notrait,category=IgnoreForCI,-notrait,category=OuterLoop,-notrait,category=failing

...

[17:18:21] dbug: test[0]
      [PASS] System.Tests.ArrayTests.CreateInstance_Advanced(elementType: typeof(int), lengths: [1], lowerBounds: [0], repeatedValue: 0)

[lewing]

cc @vargaz

[danmoseley]

The main log has

2020-08-07T17:02:11.7013998Z   Waiting for completion of job e7fed000-94bb-45ab-950e-2403ad3753b5 on Ubuntu.1804.Amd64.Open
2020-08-07T17:30:35.4257384Z   Job e7fed000-94bb-45ab-950e-2403ad3753b5 on Ubuntu.1804.Amd64.Open is completed with 209 finished work items.

Hence my assumption is that between the 17:18 and 17:30 timestamp there was a test jammed. (?)

[lewing]

it is likely #40214

[danmoseley]

@lewing another CI hang this time in System.Collections.NonGeneric.Tests

https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-40729-merge-e1632a8cfaf84b54b4/System.Collections.NonGeneric.Tests/console.ea2cd2a6.log?sv=2019-02-02&se=2020-09-01T19%3A56%3A19Z&sr=c&sp=rl&sig=2LL%2FZ2N0oTEL%2Bzz8AVt30UdsfanM%2BU6O%2FViivjmiE1k%3D

[20:13:48] dbug: test[0]
      [PASS] System.Collections.Tests.HashtableBasicTests.IDictionary_NonGeneric_IDictionaryEnumerator_Current_FromStartToFinish(count: 75)
      
[20:13:48] dbug: test[0]
      [PASS] System.Collections.Tests.HashtableBasicTests.IEnumerable_NonGeneric_Enumerator_Current_ReturnsSameValueOnRepeatedCalls(count: 0)
      
[20:13:48] dbug: test[0]
      [PASS] System.Collections.Tests.HashtableBasicTests.IEnumerable_NonGeneric_Enumerator_Current_ReturnsSameValueOnRepeatedCalls(count: 1)
      
[20:13:48] dbug: test[0]
      [PASS] System.Collections.Tests.HashtableBasicTests.IEnumerable_NonGeneric_Enumerator_Current_ReturnsSameValueOnRepeatedCalls(count: 75)
      
[20:13:48] dbug: test[0]
      [PASS] System.Collections.Tests.HashtableBasicTests.ICollection_NonGeneric_CopyTo_ArrayOfIncorrectValueType(count: 0)
      
Killed

There is no dump so I'm not sure how we can tell whether it's #40214.

was in #40729