Helix Job Monitor stops status updates while result-upload drain can run for hours

[mmitche]

Description

The Helix Job Monitor can spend hours draining Azure DevOps test-result uploads after all Helix jobs have completed, while the normal ℹ️ Status heartbeat stops entirely. This makes a very slow or stuck upload indistinguishable from a hung monitor and provides no indication of which uploads remain or what phase they are in.

Example: runtime build 1542847, first Monitor Helix Jobs attempt

Raw log timeline

All times are UTC from the raw AzDO log:

• 15:45:24 - monitor starts using Microsoft.DotNet.Helix.JobMonitor 11.0.0-beta.26404.8 (Arcade commit 35ea7e6192f7ab5fddd068ea9ce3f5e3d5491298).
• 19:30:16.155 - last aggregate status: 31 processed / 41 completed jobs and 1763 processed / 2958 completed work items.
• 19:30:16.157 - Waiting for 10 pending test result upload(s) to complete.
• 19:30:18 - one of those uploads completes.
• 20:02:47, 20:16:52, 20:37:26, 20:50:07 - four more uploads complete. Their total upload-processing durations were approximately 180, 187, 203, and 207 minutes.
• No further monitor output occurs until 21:07:31, when AzDO cancels the operation. Five uploads never reported completion.

The five jobs still lacking a test results ... processed line at cancellation were:

• Libraries Test Run checked coreclr windows x86 Debug (47f2f958-37c8-4662-922b-7f48d3abad94), processing since 17:27:36
• ios-arm64 Release AllSubsets_CoreCLR_Smoke (208fe8d1-d1e1-447a-b181-51162b422338), since 17:28:42
• Libraries Test Run checked coreclr windows x64 Release (f92dc6d3-0b17-4f34-9a9c-232c6f915565), since 17:34:29
• Libraries Test Run checked coreclr osx arm64 Debug (4ce2007f-3914-4c9d-af2a-0674e80815ef), since 18:17:28
• osx-arm64 release Installer_Build_And_Test (e2fd1085-9828-4a73-9456-ab9cb75188a4), since 18:25:48

The last status line is only 2 ms before TestResultUploadQueue.DrainAsync logs its pending count. DrainAsync then awaits Task.WhenAll(_pending) and does not invoke StatusReporter, so the absence of status updates is deterministic rather than an AzDO log-loss issue.

Version / possible existing fix

This build's monitor package points to Arcade commit 35ea7e6 from August 4. #17256, Fix Helix test result upload retries, merged on August 6 after this monitor invocation had started. It adds retries for transient Azure DevOps transport failures, HttpClient timeout cancellations, and 5xx/429 responses, so it may mitigate the underlying upload problem once consumed.

However, the merged implementation still logs only once before Task.WhenAll in DrainAsync; it does not provide a heartbeat or identify long-running uploads. Therefore the observability problem remains even if #17256 fixes this particular transport failure.

Expected behavior

While draining result uploads, the monitor should periodically report progress, including at minimum:

• pending upload count and elapsed drain time;
• names/IDs and elapsed time of uploads still pending;
• ideally the current phase for each upload (download Helix results, create test run, publish result batches/attachments, complete test run);
• warnings or bounded behavior when an individual operation or the overall drain exceeds an expected duration.

This would make it possible to distinguish slow Azure DevOps ingestion, throttling/retries, and a genuinely stuck request, and would preserve the monitor's normal status heartbeat through its final phase.

[mmitche]

A second, stronger reproduction occurred in runtime build 1543373.

This is on the post-#17256 monitor

The restore log shows Microsoft.DotNet.Helix.JobMonitor 11.0.0-beta.26406.8. The package nuspec identifies Arcade commit 2cf38de4, and that commit contains the merge of #17256. Therefore the upload retry fix did not eliminate this broader failure mode.

Raw log timeline (UTC)

• 21:24:53 - monitor starts.
• 23:56:07.568 - final aggregate status: 24 processed / 66 completed / 0 running / 0 waiting jobs.
• 23:56:07.570 - Waiting for 42 pending test result upload(s) to complete.
• During the drain, 26 additional test results ... processed messages appear.
• 05:53:07 - last upload completion message.
• 06:19:56 - monitor times out after 535 minutes total, listing 17 unfinished or unprocessed jobs (16 reported status=finished, one status=running).

The drain itself lasted 383.8 minutes (6h 23m 49s). There was no aggregate status update during that entire period. Even after the final completion message there was another 26.8 minutes of silence before timeout.

Additional diagnostic color

The cancellation stacks show that “uploading results” is not necessarily blocked in an Azure DevOps HTTP call. At least two remaining jobs were still inside:

LocalTestResultsReader.ReadResultFileAsync
XDocument.LoadAsync

while parsing local testResults.xml files. This strengthens the need to expose each pending job's phase (download, local parse, AzDO publish, attachments, test-run completion) rather than reporting all work as a single opaque upload.

The current implementation also starts one fire-and-forget Task.Run per completed Helix job. In this build, 42 job-level uploads were still active when the main polling loop ended; each can fan out work-item upload tasks which then contend on the shared _uploadSemaphore. The very large fan-out may itself contribute to the multi-hour drain and is worth measuring/bounding.

Finally, timeout cancellation produced a secondary cleanup race:

System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.Threading.SemaphoreSlim'.
  at SemaphoreSlim.Release(...)
  at AzureDevOpsService...UploadWorkItemAsync(...) line 441

This indicates AzureDevOpsService.Dispose() can dispose _uploadSemaphore while in-flight upload tasks are unwinding and releasing it. The timeout also emitted many misleading Failed to parse test results file warnings whose underlying exception was simply TaskCanceledException from monitor cancellation.

So this reproduction suggests three related improvements:

1. Periodic drain heartbeat with pending count, names, elapsed time, and current phase.
2. Bounded/observable job-level upload concurrency rather than an unbounded fire-and-forget task per Helix job.
3. Orderly cancellation/disposal so upload tasks finish unwinding before shared services are disposed, without reporting expected cancellation as parse failures.

[mmitche]

The main issue discovered here is that the default upload behavior for attachments changed. It was just failed tests, now it's everything. Which is a lot. Changing that back.

/cc @agocke