diff --git a/csharp/src/RetryHttpHandler.cs b/csharp/src/RetryHttpHandler.cs index 4bd39c83..fd4fdd48 100644 --- a/csharp/src/RetryHttpHandler.cs +++ b/csharp/src/RetryHttpHandler.cs @@ -22,6 +22,7 @@ */ using System; +using System.Collections.Generic; using System.IO; using System.Net; using System.Net.Http; @@ -142,10 +143,6 @@ protected override async Task SendAsync( attemptCount++; lastTransportException = ex; - activity?.SetTag("http.retry.attempt", attemptCount); - activity?.SetTag("http.retry.transport_error", ex.GetType().Name); - activity?.SetTag("http.retry.transport_error_message", ex.Message); - int transportWaitSeconds = CalculateBackoffWithJitter(currentBackoffSeconds); lastErrorMessage = $"Transport error ({ex.GetType().Name}: {ex.Message}). Using exponential backoff of {transportWaitSeconds} seconds. Attempt {attemptCount}."; @@ -161,6 +158,19 @@ protected override async Task SendAsync( } totalTransportErrorRetrySeconds += transportWaitSeconds; + // Issue #479: emit a per-retry event BEFORE we sleep so the + // trace makes the retry visible even if the process dies + // during the delay. The event is self-contained — it carries + // the per-retry detail that used to be written as overwritten + // span tags (attempt number, error type via reason, error message). + activity?.AddEvent("retry.attempt", new List> + { + new("http.retry.attempt_number", attemptCount), + new("http.retry.delay_ms", (long)transportWaitSeconds * 1000L), + new("http.retry.reason", $"transport_error_{ex.GetType().Name}"), + new("http.retry.error_message", ex.Message) + }); + await Task.Delay(TimeSpan.FromSeconds(transportWaitSeconds), cancellationToken); currentBackoffSeconds = Math.Min(currentBackoffSeconds * 2, _maxBackoffSeconds); continue; @@ -183,12 +193,14 @@ protected override async Task SendAsync( HttpStatusCode statusCode = response.StatusCode; bool isTooManyRequests = statusCode == (HttpStatusCode)429; - // Log this retry attempt - activity?.SetTag("http.retry.attempt", attemptCount); - activity?.SetTag("http.response.status_code", (int)statusCode); - int waitSeconds; + // Issue #479: derive a reason string the retry.attempt + // event below will carry. We thread it alongside the + // existing lastErrorMessage so the event tag and the + // exception text stay consistent. + string retryReason; + // Check for Retry-After header if (response.Headers.TryGetValues("Retry-After", out var retryAfterValues)) { @@ -199,12 +211,14 @@ protected override async Task SendAsync( // Use the Retry-After value waitSeconds = retryAfterSeconds; lastErrorMessage = $"Service temporarily unavailable (HTTP {(int)statusCode}). Using server-specified retry after {waitSeconds} seconds. Attempt {attemptCount}."; + retryReason = $"retry_after_{(int)statusCode}"; } else { // Invalid Retry-After value, use exponential backoff waitSeconds = CalculateBackoffWithJitter(currentBackoffSeconds); lastErrorMessage = $"Service temporarily unavailable (HTTP {(int)statusCode}). Invalid Retry-After header, using exponential backoff of {waitSeconds} seconds. Attempt {attemptCount}."; + retryReason = $"retry_after_{(int)statusCode}_invalid_header"; } } else @@ -212,6 +226,7 @@ protected override async Task SendAsync( // No Retry-After header, use exponential backoff waitSeconds = CalculateBackoffWithJitter(currentBackoffSeconds); lastErrorMessage = $"Service temporarily unavailable (HTTP {(int)statusCode}). Using exponential backoff of {waitSeconds} seconds. Attempt {attemptCount}."; + retryReason = $"retry_after_{(int)statusCode}_no_header"; } // Dispose the response before retrying @@ -246,6 +261,22 @@ protected override async Task SendAsync( totalServiceUnavailableRetrySeconds += waitSeconds; } + // Issue #479: emit a retry.attempt event BEFORE Task.Delay + // below. This lives on the SendAsync activity (created by + // TraceActivityAsync above) so a single completed activity + // carries all its retry attempts as ordered events. The event is + // self-contained — it carries the per-retry detail that used to be + // written as overwritten span tags (attempt number, status code). + // Attribute keys are namespaced to match the driver's telemetry + // vocabulary (http.retry.* / OTel http.response.status_code). + activity?.AddEvent("retry.attempt", new List> + { + new("http.retry.attempt_number", attemptCount), + new("http.retry.delay_ms", (long)waitSeconds * 1000L), + new("http.retry.reason", retryReason), + new("http.response.status_code", (int)statusCode) + }); + // Wait for the calculated time await Task.Delay(TimeSpan.FromSeconds(waitSeconds), cancellationToken); diff --git a/csharp/test/Unit/RetryHttpHandlerTest.cs b/csharp/test/Unit/RetryHttpHandlerTest.cs index 61399f74..fdee6afc 100644 --- a/csharp/test/Unit/RetryHttpHandlerTest.cs +++ b/csharp/test/Unit/RetryHttpHandlerTest.cs @@ -22,7 +22,10 @@ */ using System; +using System.Collections.Generic; +using System.Diagnostics; using System.IO; +using System.Linq; using System.Net; using System.Net.Http; using System.Net.Sockets; @@ -665,6 +668,144 @@ public async Task TransportError_PerRequestTimeoutIsRetried() Assert.Equal(2, mockHandler.RequestCount); // 1 timeout + 1 success } + // --------------------------------------------------------------------- + // Retry telemetry tests (issue #479) + // + // The RetryHttpHandler runs on every HTTP send and retries on + // Retry-After (503/429) responses and on transient transport errors — + // but historically it emitted zero per-attempt telemetry. A customer + // reading their own driver logs asking "did my failure retry then + // succeed, or did it fail without any retry?" could not answer from + // the trace alone. + // + // The fix (around the retry loop) is to emit a `retry.attempt` event + // for each *retry* (i.e. not the first try) on the wrapping SendAsync + // activity, carrying attempt_number/delay_ms/reason. The target + // consumer is the user reading local driver logs, so dashboard-shaped + // summary tags are intentionally not emitted. + // + // These tests capture the activity emitted by RetryHttpHandler via an + // ActivityListener attached to the MockActivityTracer's source name + // ("TestSource"), then assert on its Events. + // --------------------------------------------------------------------- + + /// + /// Captures Activity objects emitted by an ActivitySource for in-test + /// assertions on tags and events. + /// + private sealed class ActivityCapture : IDisposable + { + private readonly ActivityListener _listener; + private readonly object _lock = new(); + private readonly List _stopped = new(); + + public ActivityCapture(string sourceName) + { + _listener = new ActivityListener + { + ShouldListenTo = source => source.Name == sourceName, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => + { + lock (_lock) { _stopped.Add(activity); } + } + }; + ActivitySource.AddActivityListener(_listener); + } + + public IReadOnlyList StoppedActivities + { + get { lock (_lock) { return _stopped.ToArray(); } } + } + + public void Dispose() => _listener.Dispose(); + } + + /// + /// Issue #479: when the first attempt succeeds, no `retry.attempt` + /// events fire. + /// + [Fact] + public async Task RetryTelemetry_NoRetry_EmitsNoEvents_Issue479() + { + using var capture = new ActivityCapture("TestSource"); + var mockHandler = new MockHttpMessageHandler(new HttpResponseMessage(HttpStatusCode.OK)); + var retryHandler = new RetryHttpHandler(mockHandler, new MockActivityTracer(), 5, 5, true, true); + + await new HttpClient(retryHandler).GetAsync("http://test.com"); + + Activity sendAsync = capture.StoppedActivities.Single(a => a.OperationName == "SendAsync"); + Assert.DoesNotContain(sendAsync.Events, e => e.Name == "retry.attempt"); + } + + /// + /// Issue #479: each retry triggered by a Retry-After response emits a + /// `retry.attempt` event with attempt_number / delay_ms / reason. The + /// reason string must reference the status code so 429 throttles are + /// distinguishable from 503s. + /// + [Theory] + [InlineData(HttpStatusCode.ServiceUnavailable, "503")] + [InlineData((HttpStatusCode)429, "429")] + public async Task RetryTelemetry_RetryAfter_EmitsAttemptEvents_Issue479(HttpStatusCode status, string expectedReasonSubstring) + { + using var capture = new ActivityCapture("TestSource"); + + var mockHandler = new MockHttpMessageHandler(new HttpResponseMessage(status) + { + Headers = { { "Retry-After", "1" } } + }); + mockHandler.SetResponseAfterRetryCount(2, new HttpResponseMessage(HttpStatusCode.OK)); + + var retryHandler = new RetryHttpHandler(mockHandler, new MockActivityTracer(), 10, 10, true, true); + await new HttpClient(retryHandler).GetAsync("http://test.com"); + + Activity sendAsync = capture.StoppedActivities.Single(a => a.OperationName == "SendAsync"); + var events = sendAsync.Events.Where(e => e.Name == "retry.attempt").ToList(); + Assert.Equal(2, events.Count); + + for (int i = 0; i < events.Count; i++) + { + var tags = events[i].Tags.ToDictionary(t => t.Key, t => t.Value); + Assert.Equal(i + 1, Convert.ToInt32(tags["http.retry.attempt_number"])); + Assert.True(Convert.ToInt64(tags["http.retry.delay_ms"]) >= 1000); // Retry-After: 1 → 1000ms + Assert.Contains(expectedReasonSubstring, (string)tags["http.retry.reason"]!); + Assert.Equal((int)status, Convert.ToInt32(tags["http.response.status_code"])); // OTel semantic-convention name + } + } + + /// + /// Issue #479: a retry triggered by a transient transport error emits a + /// `retry.attempt` event carrying the per-retry detail that used to be written + /// as overwritten span tags — attempt_number, reason, and error_message. + /// + [Fact] + public async Task RetryTelemetry_TransportError_EmitsAttemptEventWithErrorDetail_Issue479() + { + using var capture = new ActivityCapture("TestSource"); + + var mockHandler = new MockHttpMessageHandler(new HttpResponseMessage(HttpStatusCode.OK)); + // Throw a transient transport error for the first 2 attempts, then succeed. + mockHandler.SetExceptionForRequestCount(2, new HttpRequestException("Connection refused")); + + var retryHandler = new RetryHttpHandler(mockHandler, new MockActivityTracer(), 10, 10, true, true, + transportErrorRetryEnabled: true, httpRequestTimeoutSeconds: 0); + await new HttpClient(retryHandler).GetAsync("http://test.com"); + + Activity sendAsync = capture.StoppedActivities.Single(a => a.OperationName == "SendAsync"); + var events = sendAsync.Events.Where(e => e.Name == "retry.attempt").ToList(); + Assert.Equal(2, events.Count); // 2 transport failures → 2 retry events + + for (int i = 0; i < events.Count; i++) + { + var tags = events[i].Tags.ToDictionary(t => t.Key, t => t.Value); + Assert.Equal(i + 1, Convert.ToInt32(tags["http.retry.attempt_number"])); + Assert.True(Convert.ToInt64(tags["http.retry.delay_ms"]) >= 1000); // backoff is Math.Max(1, ...) seconds → ≥ 1000ms + Assert.StartsWith("transport_error_", (string)tags["http.retry.reason"]!); + Assert.Equal("Connection refused", (string)tags["http.retry.error_message"]!); + } + } + /// /// Mock HttpMessageHandler for testing the RetryHttpHandler. ///