Broker retry logs an ERR stack trace and a phantom backoff on every job completion (listener's own cancellation treated as a request failure)

[nitrobass24]

Describe the bug

Every time a job completes, the listener logs an ERR-level exception dump against the broker followed by a WARN announcing a 5-15 second backoff. Neither reflects a real failure:

• the exception is the listener cancelling its own in-flight long poll, which it does on every Busy -> Idle transition so it can re-poll with the new status
• the backoff is never actually served. Task.Delay is awaited on the same token that was just cancelled, so it throws immediately and the delay does not elapse

The net effect is a stack trace and a misleading warning per job completion, on every runner, for entirely normal control flow.

Log (one job completion, runner healthy, no network fault)

00:50:32Z INFO  Terminal] Job <name> completed with result: Succeeded
00:50:32Z INFO  BrokerMessageListener] Received job status event. JobState: Online
00:50:32Z WARN  GitHubActionsService] GET request to https://broker.actions.githubusercontent.com/message?sessionId=...&status=Busy&runnerVersion=2.336.0&os=Linux&architecture=X64&disableUpdate=false has been cancelled.
00:50:32Z ERR   BrokerServer] Catch exception during request
00:50:32Z ERR   BrokerServer] System.Threading.Tasks.TaskCanceledException: The operation was canceled.
00:50:32Z ERR   BrokerServer] System.IO.IOException: Unable to read data from the transport connection: Operation canceled.
00:50:32Z ERR   BrokerServer] System.Net.Sockets.SocketException (125): Operation canceled
00:50:32Z WARN  BrokerServer] Back off 14.623 seconds before next retry. 4 attempt left.
00:50:32Z INFO  BrokerMessageListener] Get messages has been cancelled using local token source. Continue to get messages with new status.

Note the last two lines share a timestamp. The listener resumes in the same second the 14.6s backoff was announced. That holds for every occurrence I sampled (12 of 12 consecutive pairs on one runner) — the announced delay is never waited.

Why it happens

BrokerMessageListener polls using a linked token it owns, and handles the cancellation itself:

_getMessagesTokenSource = CancellationTokenSource.CreateLinkedTokenSource(token);
message = await _brokerServer.GetRunnerMessageAsync(..., _getMessagesTokenSource.Token);
...
catch (OperationCanceledException) when (_getMessagesTokenSource.Token.IsCancellationRequested && !token.IsCancellationRequested)
{
    Trace.Info("Get messages has been cancelled using local token source. Continue to get messages with new status.");
    continue;
}

That token is handed straight through BrokerServer.GetRunnerMessageAsync into RetryRequest, whose catch has no cancellation filter (src/Runner.Common/RunnerService.cs):

// TODO: Add handling of non-retriable exceptions: https://github.com/github/actions-broker/issues/122
catch (Exception ex) when (attempt < maxAttempts && (shouldRetry == null || shouldRetry(ex)))
{
    Trace.Error("Catch exception during request");
    Trace.Error(ex);
    var backOff = BackoffTimerHelper.GetRandomBackoff(TimeSpan.FromSeconds(5), TimeSpan.FromSeconds(15));
    Trace.Warning($"Back off {backOff.TotalSeconds} seconds before next retry. {maxAttempts - attempt} attempt left.");
    await Task.Delay(backOff, cancellationToken);   // same token, already cancelled -> throws at once
}

ShouldRetryException in BrokerServer filters only auth and session exceptions, so a cancellation reaches this handler, gets logged as a request failure, and computes a backoff that the very next line discards. The existing TODO above the catch appears to describe this gap.

Volume

Across the current listener logs of a 12-runner fleet: 1,475 job completions, 2,064 of these backoff warnings — at least one per completion, on every runner.

runner-01 completions=126 backoffs=176      runner-07 completions=121 backoffs=170
runner-02 completions=124 backoffs=173      runner-08 completions=129 backoffs=181
runner-03 completions=118 backoffs=170      runner-09 completions=119 backoffs=168
runner-04 completions=128 backoffs=177      runner-10 completions=129 backoffs=177
runner-05 completions=121 backoffs=166      runner-11 completions=122 backoffs=169
runner-06 completions=110 backoffs=159      runner-12 completions=128 backoffs=178

Why it is worth fixing

The signature is indistinguishable from a genuine broker connectivity failure, and it fires constantly on healthy fleets. #3904 collects reports of this exact TaskCanceledException / SocketException (125) pattern, and the discussion there has gone looking for network causes — CNI breakage, pods losing egress, blocked endpoints. Some of those may well be real. But an operator cannot currently tell a real broker fault from the runner cancelling its own request, because both produce the same ERR-level output. Silencing the benign case would make the remaining reports diagnosable.

It also means ERR in these logs does not mean what it says, which undermines using log level for alerting.

Expected behavior

A cancellation originating from the caller's own token should propagate to the caller — which already has a handler for it — rather than being logged as a failed request with a backoff that is never applied.

Suggested fix

A cancellation-specific catch ahead of the general one:

catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested)
{
    throw;
}

The IsCancellationRequested guard is deliberate: HttpClient surfaces a request timeout as TaskCanceledException while the caller's token is not cancelled, and that case is a real failure which must keep retrying.

Happy to open a PR if that shape looks right.

Runner Version and Platform

Runner 2.336.0 (current latest), self-hosted, registered at organisation level.
Linux x64, bare metal, 12 listener processes on one host.

Related: #3904 — same exception signature, discussed there as a connectivity fault.