System.Security.Cryptography.Tests timing out in the CI

[tarekgh]

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-64365-merge-bf31f3469b0e48fbb4/System.Security.Cryptography.Tests/1/console.3897f734.log?sv=2019-07-07&se=2022-02-16T17%3A44%3A22Z&sr=c&sp=rl&sig=5YFpNB90cUSCQM53WKijNhCJtNGb%2BH1agUVjQQE%2BOTg%3D
https://dev.azure.com/dnceng/public/_build/results?buildId=1575063&view=logs&jobId=bf603221-817a-5f42-894a-9eb35c3c7f97&j=bf603221-817a-5f42-894a-9eb35c3c7f97&t=c8a637da-bfd7-5afe-0aba-62ddf378e6cc

C:\h\w\BC140AED\w\AFD60969\e>"C:\h\w\BC140AED\p\dotnet.exe" exec --runtimeconfig System.Security.Cryptography.Tests.runtimeconfig.json --depsfile System.Security.Cryptography.Tests.deps.json xunit.console.dll System.Security.Cryptography.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing  
  Discovering: System.Security.Cryptography.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Security.Cryptography.Tests (found 2322 of 2332 test cases)
  Starting:    System.Security.Cryptography.Tests (parallel test collections = on, max threads = 2)
    System.Security.Cryptography.Tests.AesCcmIsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
    System.Security.Cryptography.Encryption.Aes.Tests.AesModeTests.Windows7DoesNotSupportCFB128 [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Tests.AesGcmIsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
    System.Security.Cryptography.Rsa.Tests.KeyGeneration.GenerateMaxKey [SKIP]
      Condition(s) not met: "IsStressModeEnabled"
    System.Security.Cryptography.Encryption.Des.Tests.DesContractTests.Windows7DoesNotSupportCFB [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Encryption.TripleDes.Tests.TripleDESContractTests.Windows7DoesNotSupportCFB64 [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Tests.ChaCha20Poly1305IsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
  Finished:    System.Security.Cryptography.Tests
=== TEST EXECUTION SUMMARY ===
   System.Security.Cryptography.Tests  Total: 5993, Errors: 0, Failed: 0, Skipped: 7, Time: 24.172s
['System.Security.Cryptography.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

[ghost]

Tagging subscribers to this area: @dotnet/area-system-security, @vcsjones
See info in area-owners.md if you want to be subscribed.

Issue Details

---

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-64365-merge-bf31f3469b0e48fbb4/System.Security.Cryptography.Tests/1/console.3897f734.log?sv=2019-07-07&se=2022-02-16T17%3A44%3A22Z&sr=c&sp=rl&sig=5YFpNB90cUSCQM53WKijNhCJtNGb%2BH1agUVjQQE%2BOTg%3D
https://dev.azure.com/dnceng/public/_build/results?buildId=1575063&view=logs&jobId=bf603221-817a-5f42-894a-9eb35c3c7f97&j=bf603221-817a-5f42-894a-9eb35c3c7f97&t=c8a637da-bfd7-5afe-0aba-62ddf378e6cc

C:\h\w\BC140AED\w\AFD60969\e>"C:\h\w\BC140AED\p\dotnet.exe" exec --runtimeconfig System.Security.Cryptography.Tests.runtimeconfig.json --depsfile System.Security.Cryptography.Tests.deps.json xunit.console.dll System.Security.Cryptography.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing  
  Discovering: System.Security.Cryptography.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Security.Cryptography.Tests (found 2322 of 2332 test cases)
  Starting:    System.Security.Cryptography.Tests (parallel test collections = on, max threads = 2)
    System.Security.Cryptography.Tests.AesCcmIsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
    System.Security.Cryptography.Encryption.Aes.Tests.AesModeTests.Windows7DoesNotSupportCFB128 [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Tests.AesGcmIsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
    System.Security.Cryptography.Rsa.Tests.KeyGeneration.GenerateMaxKey [SKIP]
      Condition(s) not met: "IsStressModeEnabled"
    System.Security.Cryptography.Encryption.Des.Tests.DesContractTests.Windows7DoesNotSupportCFB [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Encryption.TripleDes.Tests.TripleDESContractTests.Windows7DoesNotSupportCFB64 [SKIP]
      Condition(s) not met: "IsWindows7"
    System.Security.Cryptography.Tests.ChaCha20Poly1305IsSupportedTests.CtorThrowsPNSEIfNotSupported [SKIP]
      Condition(s) not met: "RuntimeSaysIsNotSupported"
  Finished:    System.Security.Cryptography.Tests
=== TEST EXECUTION SUMMARY ===
   System.Security.Cryptography.Tests  Total: 5993, Errors: 0, Failed: 0, Skipped: 7, Time: 24.172s
['System.Security.Cryptography.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

Author:	tarekgh
Assignees:	-
Labels:	area-System.Security, untriaged
Milestone:	-

[bartonjs]

A workaround is in progress.

[fanyang-mono]

This has happened again for rolling build #20220308.49 on lane Libraries Test Run release coreclr windows x86 Release. This is the link to the build https://dev.azure.com/dnceng/public/_build/results?buildId=1652032&view=logs&j=457f7e88-dfa2-5bd9-f871-fdf124c2477d&t=bfe52dfb-2099-5c7f-ee52-70a1d81c544e

[fanyang-mono]

Should we disable the test for now? It seems that the workaround mentioned on Jan 27th hasn't arrived yet. And I saw this being hit on rolling build quite often.

[bartonjs]

@fanyang-mono The specific problem that this issue is looking at is the tests finishing in a reasonable amount of time, then the process hanging after printing results, and thus timing out in Helix (it also was only for Windows 11 (maybe also 10?), IIRC):

   System.Security.Cryptography.Tests  Total: 5993, Errors: 0, Failed: 0, Skipped: 7, Time: 24.172s
['System.Security.Cryptography.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

The work item you linked to shows two failures, both of which have console logs that show success, but neither of which include the message of the command timing out and being killed by the runner.

The test causing the original problem to appear has been deactivated. If there's anything more here, it would be a separate thing to track and resolve.

[ilonatommy]

Still exisiting: #66694

[ilonatommy]

@bartonjs could you please look into this log? It's a bit different than the previous one and the issue is still persisting.
If you decide you can't fix it relatively fast, please disable this one.

[fanyang-mono]

@bartonjs I see. Thanks for the clarification.

[fanyang-mono]

@bartonjs could you please look into this log? It's a bit different than the previous one and the issue is still persisting. If you decide you can't fix it relatively fast, please disable this one.

This one is an out-of-memory issue. Please create a separate issue.

[fanyang-mono]

This exact timing out issue is still happening on build #20220317.13 CI lane Build windows x64 Release AllSubsets_Mono
https://dev.azure.com/dnceng/public/_build/results?buildId=1670042&view=logs&j=585f1246-0618-5d47-ff3e-08c83309e2d2&t=5e10daf8-cc46-5bd4-2ab7-d28eafd857b5

[bartonjs]

Hm. That certainly is an "after finishing the process hung"-looking console log. Unfortunately, it's not reproing on my machine, which means it's hard to figure out what tests we're running that Windows has regressed.

[vcsjones]

Is it possible for us to get a mini dump when a test run is killed for timing out?

[danmoseley]

Using this query

TestResults
| join kind=inner WorkItems on WorkItemId
| join kind=inner Jobs on JobId
//| where Method == "ModulesAreDisposedWhenProcessIsDisposed"
//| where Type == "System.Text.Json.SourceGeneration.Tests.MetadataWithPerTypeAttributeContextTests" and Method == "RoundTripCollectionsDictionary"
| where WorkItemFriendlyName  == "System.Security.Cryptography.Tests"
//| where Finished >= now(-20d)
| where Status == "Timeout"
//| where Message contains "2019-08"
//| where QueueName == "windows.11.amd64.clientpre.open"
//| where Message startswith "System.ArgumentNullException : Value cannot be null. (Parameter 'package"
| project //Type, 
Method,
  Pipeline = tostring(parse_json(Properties).DefinitionName),
  Pipeline_Configuration = tostring(parse_json(Properties).configuration),
  OS = QueueName,
  Container = tostring(parse_json(Properties).operatingSystem), 
  Arch = tostring(parse_json(Properties).architecture),
 Finished,
 Build, ConsoleUri
  //Duration,
 // Method,
 // Build = tostring(parse_json(Properties).BuildNumber),
,Message,StackTrace

I see a bunch of hangs in ReadAsync_CancelPendingTask_ThrowsCancellationException until 4/7 when fixed by #66694. Zero hangs since.