Retry attempts are logged at Debug, so a long retry sequence is invisible at Information level

[rolandbanks]

Summary

ODataClient retries a failing request several times, each attempt bounded only by HttpClient.Timeout, and logs every one of those attempts at Debug. At the default Information level a caller sees nothing until the final failure — by which time many minutes, or an hour, have passed with no indication that anything was wrong.

What happened

A report job's UpdateAsync call against an unresponsive API took roughly an hour before surfacing anything. The only log line produced in that time was the final one:

[Error] Report Job ID #57686: failure to update via API due to:
"The request was canceled due to the configured HttpClient.Timeout of 300 seconds elapsing."
   at PanoramicData.OData.Client.ODataClient.TrySendRequestAsync(HttpRequestMessage request, Int32 retryCount, CancellationToken cancellationToken)
   at PanoramicData.OData.Client.ODataClient.SendWithRetryAsync(HttpRequestMessage request, CancellationToken cancellationToken)

One 300-second timeout does not take an hour. The client was retrying — and it knew it was, because SendAttemptAsync logs the attempt number on every pass:

LoggerMessages.SendingRequest(_logger, requestToSend.Method, requestToSend.RequestUri, retryCount + 1);

That message is declared as:

[LoggerMessage(
    EventId = 14,
    Level = LogLevel.Debug,
    Message = "SendWithRetryAsync - Sending {Method} request to {Url} (attempt {Attempt})")]

Debug. So the one piece of information that would have explained the hour was being produced, with an attempt counter attached, and discarded.

Why Debug is the wrong level for this one

Debug is right for "what the client is doing" — headers added, request built, response received. This is different in kind: it is "your call has not failed, and is going to take up to another HttpClient.Timeout per remaining attempt". That is a fact about elapsed wall-clock time that the caller cannot obtain any other way. During the wait there is no CPU, no exception, and no completed request to observe.

Diagnosing it took thread dumps, socket sampling and database forensics, and the answer was in a Debug line the whole time.

Suggested change

1. SendingRequest to Information when retryCount > 0. The first attempt is routine and can stay at Debug; a retry is not routine and is the thing worth surfacing. That keeps normal traffic quiet - one line per retry, and only when something is already going wrong.
2. Include cumulative elapsed time, not just the attempt number. "Attempt 9" is much more informative as "attempt 9, 2,400,000ms elapsed", and only the client can compute it.
3. Consider Warning on the final attempt before giving up.

Related

panoramicdata/LogicMonitor.Api had the same defect in its rate-limit backoff and it was fixed the same day — see LogicMonitor.Api issue #38 and PR #39. Same shape, same consequence, different package: a client that waits and retries invisibly leaves callers unable to distinguish patience from a hang.