Azure Linux 3 System.Net.* and System.Security.* tests timing out

[ManickaP]

Info copied from dotnet/runtime#114013 and dotnet/runtime#114004

Happens only on Azure Linux 3, started happening in great numbers on 28.3. (27.3. was infra rollout). EDIT started on 24.3. Monday

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=996594
Build error leg or test failing: System.Net.Security.Tests.WorkItemExecution
Pull request: dotnet/runtime#113905

Error Message

'System.Net.Security.Tests' END OF WORK ITEM LOG: Command timed out, and was killed
'System.Net.WebSockets.Client.Tests' END OF WORK ITEM LOG: Command timed out, and was killed
'System.Net.Security.Unit.Tests' END OF WORK ITEM LOG: Command timed out, and was killed

Fill the error message using step by step known issues guidance.

{
  "ErrorMessage": "",
  "ErrorPattern": "'System\\..*\\.Tests' END OF WORK ITEM LOG: Command timed out, and was killed",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=996594
Error message validated: ['System\.*\.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 3/28/2025 3:36:01 PM UTC

Report

Build	Definition	Test	Pull Request
997166	dotnet/runtime	System.Net.WebSockets.Client.Tests.WorkItemExecution	dotnet/runtime#114003
996594	dotnet/runtime	System.Net.WebSockets.Client.Tests.WorkItemExecution	dotnet/runtime#113905

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
2	2	2

[karelz]

As per @ManickaP info above, it was triggered on 3/28, right after infra roll out.
@markwilkie @riarenas can you help us find someone from infra to help find out what caused it?

cc @JulieLeeMSFT

@dotnet/dnceng

[markwilkie]

@dougbu - any ideas?

adding @hoyosjs as he has some context as well.

[dougbu]

@dougbu - any ideas?

other than noting the 1 month hit count is rather low for this specific message, I don't have much. it's possible the problem was transient but it's also possible jobs are hitting other issues and failing b/4 they time out

[hoyosjs]

It's looping for a while in the same AL3 D2_v4 VM that test use with the same payload as one of the reported failures and I've never repro'd one of these timeouts. Timeouts have mostly been limited to networking tests, so I am not confident it's not a test/product issue as opposed to an image issue. Oddly enough, Known Issues is running less hits than it should. I corrected the pattern.

[ManickaP]

It's much more than 2 occurences.

WorkItems
| where FriendlyName startswith "System." and Status == "Timeout" and Queued >= datetime(2025, 3, 18)//and QueueName has "azurelinux.3." 
| summarize count() by QueueName

QueueName	count()
azurelinux.3.amd64.open.rt	4570
ubuntu.2204.amd64.open.svc	1212
windows.10.amd64.serverrs5.open.svc	554

Compared to the numbers from 5 days ago: dotnet/runtime#114004 (comment) it doubled on AzureLinux 3

The table in the description is likely not up to date.

Also this is not just Networking, but also System.Security tests. So it seems it's connected to something with crypto on that distro. @wfurt mentioned that it has unique version of OpenSSL. EDIT: it uses SymCrypt instead of libcrypto, see https://learn.microsoft.com/en-us/azure/azure-linux/intro-azure-linux#whats-new-with-azure-linux-30.

[ManickaP]

Would it be possible to figure out exact versions of the distro and OpenSSL and crypto libraries from the beginning of last week and last Wednesday/Thursday?

[karelz]

cc @krwq @bartonjs as it impacts also System.Security -- looks like busted OpenSSL on the distro.

I would recommend 2 parallel efforts:

1. Try to roll back infra changes that might have caused it. Unclear what it is. Perhaps new distro roll out or something like that? @dotnet/dnceng any thoughts what could be tried here?
2. Networking team should look at dump to see what is wrong. Even if we roll back bad distro / OpenSSL, we will have to pursue proper fix in there / workaround in our tests. @ManickaP are we able to investigate a dump at this moment? What do we need from whom if not?

[ManickaP]

So the numbers of timeouts per day:

WorkItems
| where FriendlyName startswith "System." and Status == "Timeout" and QueueName has "azurelinux.3."
| summarize count() by startofday(Queued)

Queued	count
2025-03-18T00:00:00Z	145
2025-03-24T00:00:00Z	244
2025-03-25T00:00:00Z	618
2025-03-26T00:00:00Z	513
2025-03-27T00:00:00Z	548
2025-03-28T00:00:00Z	495
2025-03-29T00:00:00Z	423
2025-03-30T00:00:00Z	383
2025-03-31T00:00:00Z	646
2025-04-01T00:00:00Z	560
2025-04-02T00:00:00Z	159

So the first isolated occurrence was on 18.3. and then it started globally on Monday 24.3.

[ManickaP]

More investigation:

• it never happens in docker image running on AZL3 (we only have alpine, but all the timeouts come from an empty DockerTag)

WorkItems
| where FriendlyName startswith "System." and QueueName has "azurelinux.3." and startofday(Queued) > datetime(2025, 3, 18)
| join kind=inner Jobs on JobId
| summarize count() by DockerTag, Status

DockerTag	Status	count_
mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.21-helix-amd64	Pass	113,440
mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.21-helix-amd64	Error	4,749
mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.21-helix-amd64	InfraRetry	26
mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.21-helix-amd64	BadExit	848
mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.21-helix-amd64	None	7
	Pass	177,004
	Error	3,910
	BadExit	825
	InfraRetry	18
	Timeout	4,637
	None	19

• there doesn't seem to be update of any OpenSSL and SymCrypt packages in packages.microsoft.com during that time:

  • SymCrypt 10.2. https://packages.microsoft.com/azurelinux/3.0/prod/base/x86_64/Packages/s/
  • OpenSSL 13.3. https://packages.microsoft.com/azurelinux/3.0/prod/base/x86_64/Packages/o/

• if it's caused by changes in runtime repo then based on pipeline runs on main branch: https://dev.azure.com/dnceng-public/public/_build?definitionId=129&_a=summary&branchFilter=331

  • it must have been between 24.3. 9:00 and 21:00, which corresponds to this list of commits: dotnet/runtime@5bce78d...f17c21c

[jkotas]

are we able to investigate a dump at this moment?

Have you been able to capture a dump to investigate? If not, I can help you with that.

[ManickaP]

Status from yesterday: I got dumps from dotnet/runtime#114145.

• I found revocation responder on one of the call stacks, but it's still not clear if it's the culprit.
• I didn't find anything crypto related on any of the call stacks: no OpenSSL, no SslStream and/or friends, no crypto lib.

I'll continue looking into dumps during today and leave a new update at the end of the day (at the latest).