diff --git a/README.md b/README.md index 3742022..8281121 100644 --- a/README.md +++ b/README.md @@ -89,7 +89,7 @@ Pass `Logger` on `StreamOptions` (or `ClientBuilder.Logger(...)`) to receive str | `client.initialized` | INFO | Once, at `BaseClient` construction | | `http.request.sent` | DEBUG | Before every request is sent | | `http.response.received` | DEBUG | After any HTTP response, including 4xx/5xx | -| `http.request.failed` | ERROR | Only on a transport failure (no HTTP response received) | +| `http.request.failed` | ERROR or DEBUG | ERROR on a final transport failure (no HTTP response received); DEBUG instead, with a `{RetryAttempt}` field, on any attempt that [Retry](#retry-policy) will retry. Never emitted for a final/non-retried 429 (already covered by `http.response.received`). | .NET's `ILogger` uses PascalCase message-template placeholders (`{Method}`, `{StatusCode}`, ...). Each maps to a canonical snake_case field name used identically across all GetStream SDKs: @@ -116,16 +116,37 @@ Pass `Logger` on `StreamOptions` (or `ClientBuilder.Logger(...)`) to receive str | | `{Body}` | `body` (redacted; only present when `LogBodies=true`) | | `http.request.failed` | `{Method}` | `method` | | | `{Path}` | `path` | -| | `{ErrorType}` | `error.type` | -| | `{DurationMs}` | `duration_ms` | -| | `{Message}` | `error.message` (redacted) | +| | `{ErrorType}` | `error.type` (transport failures only; never present on a retried 429 — see below) | +| | `{DurationMs}` | `duration_ms` (transport failures only) | +| | `{Message}` | `error.message` (redacted; transport failures only) | +| | `{RetryAttempt}` | `retry.attempt` (1-indexed; present only when this attempt will be retried) | -`error.type` is one of `connection_reset`, `timeout`, `dns_failure`, `tls_handshake_failed`, `unknown` (see `GetStreamTransportException.ErrorType`). +`error.type` is one of `connection_reset`, `timeout`, `dns_failure`, `tls_handshake_failed`, `unknown` (see `GetStreamTransportException.ErrorType`) — a closed transport-only enum. A retried HTTP 429 has no transport error at all, so its `http.request.failed` DEBUG line carries only `{Method}`, `{Path}`, `{RetryAttempt}`: never `{ErrorType}`. **Redaction (always on, no opt-out):** query values for `api_key`/`api_secret`/`token` (case-insensitive) become ``; top-level JSON body keys `api_secret`/`token`/`password` become `` (shallow, key names are preserved). No header values are ever logged. `error.message` is additionally scrubbed for any `api_key=`/`api_secret=`/`token=` value appearing anywhere in the free-form transport-exception text. **Bodies are not logged by default.** Set `StreamOptions.LogBodies = true` (or `ClientBuilder.LogBodies(true)`) to opt in; body content is still key-redacted as above. Enabling it emits exactly one WARN line at construction. +## Retry Policy + +Auto-retry is opt-in and off by default: with no `Retry` configured, the client performs exactly one attempt and errors surface unchanged. + +```csharp +var client = new StreamClient(new StreamOptions +{ + ApiKey = "...", + ApiSecret = "...", + Retry = new RetryConfig { Enabled = true, MaxAttempts = 3, MaxBackoff = TimeSpan.FromSeconds(30) }, +}); +``` + +When enabled: +- Only `GET`/`HEAD` requests are retried. Writes (`POST`/`PUT`/`PATCH`/`DELETE`) never are. +- Only HTTP 429 (rate limit) and transport-layer failures (connection reset, timeout, DNS, TLS) are retried; any other 4xx/5xx is never retried. +- A 429 marked `unrecoverable` by the backend is never retried. +- `MaxAttempts` is the total attempt budget including the initial request (default `3`: 1 initial + 2 retries). +- The delay before each retry honors a `Retry-After` response header when present, clamped to `MaxBackoff`; otherwise it's full jitter over `[0, min(MaxBackoff, 2^attempt seconds)]`. + ## Release Process Releases use two paths, both handled by `.github/workflows/release.yml`: diff --git a/src/Client.cs b/src/Client.cs index 21dff9d..8e5807a 100644 --- a/src/Client.cs +++ b/src/Client.cs @@ -22,6 +22,7 @@ public class BaseClient : IClient private readonly Microsoft.Extensions.Logging.ILogger? _logger; private readonly bool _userHttpClient; private readonly bool _logBodies; + private readonly RetryConfig? _retry; protected string ApiKey; protected string ApiSecret; protected string BaseUrl; @@ -60,6 +61,7 @@ public BaseClient(StreamOptions opts) BaseUrl = opts.BaseUrl; _logger = opts.Logger; _logBodies = opts.LogBodies; + _retry = opts.Retry; if (opts.HttpClient != null) { @@ -129,6 +131,11 @@ private void LogInitialized(StreamOptions opts) } } + /// + /// CHA-2959 retry loop wrapping . Retries are opt-in + /// via (disabled by default: exactly one attempt, errors surface + /// unchanged). See / for the policy. + /// public async Task> MakeRequestAsync( string method, string path, @@ -138,6 +145,98 @@ public async Task> MakeRequestAsync(method, url, requestBody, cancellationToken); + } + catch (GetStreamException ex) + { + stopwatch.Stop(); + var willRetry = ShouldRetry(ex, method, attempt); + + // CHA-2957/CHA-2959: failure logging lives here (not in SendOnceAsync) because only the + // loop knows whether this attempt will retry (DEBUG) or is final (ERROR). CROSS-SDK RULE: + // ErrorType is a closed transport-only enum, so a retried 429 logs through a separate + // template that omits the {ErrorType} placeholder entirely; a final/non-retried 429 logs + // nothing here (unchanged: it was already logged via http.response.received). + if (ex is GetStreamTransportException transportEx) + { + if (willRetry) + { + _logger?.LogDebug("http.request.failed {Method} {Path} {ErrorType} {DurationMs} {Message} {RetryAttempt}", + method, logPath, transportEx.ErrorType, stopwatch.ElapsedMilliseconds, + LogRedaction.RedactMessage(transportEx.Message), attempt + 1); + } + else + { + _logger?.LogError("http.request.failed {Method} {Path} {ErrorType} {DurationMs} {Message}", + method, logPath, transportEx.ErrorType, stopwatch.ElapsedMilliseconds, + LogRedaction.RedactMessage(transportEx.Message)); + } + } + else if (willRetry && ex is GetStreamRateLimitException) + { + _logger?.LogDebug("http.request.failed {Method} {Path} {RetryAttempt}", method, logPath, attempt + 1); + } + + if (!willRetry) throw; + + await Task.Delay(RetryDelay(ex, attempt), cancellationToken); + } + } + } + + /// CHA-2959: true when the retry policy is enabled and this failed attempt should be retried. + internal bool ShouldRetry(GetStreamException ex, string method, int attempt) + { + if (_retry is not { Enabled: true }) return false; + if (method != "GET" && method != "HEAD") return false; + if (attempt + 1 >= _retry.MaxAttempts) return false; + + return ex switch + { + GetStreamRateLimitException rl => !rl.Unrecoverable, + GetStreamTransportException => true, + _ => false, + }; + } + + /// + /// CHA-2959: delay before the next attempt. Honors Retry-After (clamped to ) + /// when present and positive; otherwise full jitter over [0, min(MaxBackoff, 2^attempt seconds)]. + /// Only called after returned true, so _retry is non-null here. + /// + internal TimeSpan RetryDelay(GetStreamException ex, int attempt) + { + if (ex is GetStreamRateLimitException { RetryAfter: { } retryAfter } && retryAfter > TimeSpan.Zero) + { + return retryAfter < _retry!.MaxBackoff ? retryAfter : _retry.MaxBackoff; + } + + // Exponent clamped to 30 so the shift never wraps (long shift counts are masked mod 64 in C#). + var ceilTicks = Math.Min(_retry!.MaxBackoff.Ticks, TimeSpan.TicksPerSecond << Math.Min(attempt, 30)); + return ceilTicks <= 0 ? TimeSpan.Zero : TimeSpan.FromTicks((long)(Random.Shared.NextDouble() * ceilTicks)); + } + + /// + /// Builds and sends a single HTTP attempt: fresh (a sent request + /// cannot be reused across retries), logs http.request.sent/http.response.received, + /// and throws on transport failure or non-2xx without logging http.request.failed itself + /// -- that is the retry loop's job (see ). + /// + private async Task> SendOnceAsync( + string method, + string url, + TRequest? requestBody, + CancellationToken cancellationToken) + { var request = new HttpRequestMessage(new HttpMethod(method), url); // Add authentication headers @@ -168,8 +267,6 @@ public async Task> MakeRequestAsync> MakeRequestAsync> MakeRequestAsync> MakeRequestAsyncDebug( string method, string path, diff --git a/src/ClientBuilder.cs b/src/ClientBuilder.cs index 28afae4..f434f88 100644 --- a/src/ClientBuilder.cs +++ b/src/ClientBuilder.cs @@ -38,6 +38,7 @@ public class ClientBuilder private System.Net.Http.HttpClient? _httpClient; private ILogger? _logger; private bool _logBodies; + private RetryConfig? _retry; /// /// Set the API key @@ -105,6 +106,9 @@ public ClientBuilder EnvPath(string path) /// Opt-in body logging (DEBUG events); shallow secret-key redaction still applies. Default false. public ClientBuilder LogBodies(bool enabled) { _logBodies = enabled; return this; } + /// Opt-in auto-retry policy (default: disabled, no retries). + public ClientBuilder Retry(RetryConfig retry) { _retry = retry; return this; } + /// /// Create a client builder that loads configuration from environment variables /// @@ -216,6 +220,7 @@ private StreamOptions BuildStreamOptions() HttpClient = _httpClient, Logger = _logger, LogBodies = _logBodies, + Retry = _retry, }; } diff --git a/src/RetryConfig.cs b/src/RetryConfig.cs new file mode 100644 index 0000000..6933c14 --- /dev/null +++ b/src/RetryConfig.cs @@ -0,0 +1,20 @@ +using System; + +namespace GetStream +{ + /// + /// Opt-in auto-retry policy. Disabled by default: the client performs exactly one attempt and surfaces errors unchanged. + /// When enabled, only GET/HEAD requests failing with HTTP 429 or a transport error are retried, and never when the backend marked the error unrecoverable. + /// + public class RetryConfig + { + /// Master switch. Default false. + public bool Enabled { get; set; } + + /// Total attempt budget including the initial request. Default 3 (1 initial + 2 retries). + public int MaxAttempts { get; set; } = 3; + + /// Cap applied to every wait between attempts, including Retry-After hints. Default 30s. + public TimeSpan MaxBackoff { get; set; } = TimeSpan.FromSeconds(30); + } +} diff --git a/src/StreamOptions.cs b/src/StreamOptions.cs index 4708b17..3dde480 100644 --- a/src/StreamOptions.cs +++ b/src/StreamOptions.cs @@ -41,5 +41,8 @@ public class StreamOptions /// Opt-in body logging on the DEBUG events; known-secret keys stay redacted. Default false. public bool LogBodies { get; set; } + + /// Opt-in auto-retry policy. Null (or Enabled=false) means no retries. + public RetryConfig? Retry { get; set; } } } diff --git a/tests/RetryTests.cs b/tests/RetryTests.cs new file mode 100644 index 0000000..341a703 --- /dev/null +++ b/tests/RetryTests.cs @@ -0,0 +1,267 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Net; +using System.Net.Http; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using GetStream; +using Microsoft.Extensions.Logging; +using NUnit.Framework; + +namespace GetStream.Tests +{ + [TestFixture] + public class RetryTests + { + private sealed class ScriptedHandler : HttpMessageHandler + { + private readonly Queue> _steps; + public int Calls { get; private set; } + + public ScriptedHandler(params Func[] steps) => _steps = new Queue>(steps); + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken ct) + { + Calls++; + return Task.FromResult(_steps.Dequeue()()); + } + } + + private sealed class ThrowOnceHandler : HttpMessageHandler + { + public int Calls { get; private set; } + + protected override Task SendAsync(HttpRequestMessage request, CancellationToken ct) + { + Calls++; + if (Calls == 1) throw new HttpRequestException("reset"); + return Task.FromResult(Json(HttpStatusCode.OK, "{}")); + } + } + + // Captures the raw message template (via the "{OriginalFormat}" state entry) alongside the + // named field values, so tests can assert which placeholders a log line does/doesn't carry -- + // not just substring-match the rendered text. + private sealed class RecordingLogger : ILogger + { + public readonly List<(LogLevel Level, string Template, Dictionary Fields)> Entries = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + var template = string.Empty; + var fields = new Dictionary(); + if (state is IEnumerable> kvps) + { + foreach (var kv in kvps) + { + if (kv.Key == "{OriginalFormat}") template = kv.Value?.ToString() ?? string.Empty; + else fields[kv.Key] = kv.Value; + } + } + Entries.Add((logLevel, template, fields)); + } + + public List<(LogLevel Level, string Template, Dictionary Fields)> Named(string ev) => + Entries.Where(e => e.Template.StartsWith(ev)).ToList(); + } + + private static HttpResponseMessage Json(HttpStatusCode status, string body, string? retryAfter = null) + { + var resp = new HttpResponseMessage(status) { Content = new StringContent(body, Encoding.UTF8, "application/json") }; + if (retryAfter != null) resp.Headers.TryAddWithoutValidation("Retry-After", retryAfter); + return resp; + } + + private static BaseClient Client(HttpMessageHandler handler, RetryConfig? retry = null, ILogger? logger = null) => + new BaseClient(new StreamOptions + { + ApiKey = "key", + ApiSecret = "secret-that-is-long-enough-for-hmac-sha256", + HttpClient = new HttpClient(handler) { BaseAddress = new Uri("http://localhost") }, + Retry = retry, + Logger = logger, + }); + + private static RetryConfig Enabled(int maxAttempts = 3, double maxBackoffMs = 1) => + new RetryConfig { Enabled = true, MaxAttempts = maxAttempts, MaxBackoff = TimeSpan.FromMilliseconds(maxBackoffMs) }; + + private static Task>> Get(BaseClient c) => + c.MakeRequestAsync>("GET", "/api/v2/app", null, null, null); + + private static Task>> Head(BaseClient c) => + c.MakeRequestAsync>("HEAD", "/api/v2/app", null, null, null); + + private static Task>> Post(BaseClient c) => + c.MakeRequestAsync>("POST", "/api/v2/x", null, null, null); + + [Test] + public void DisabledByDefault_SingleAttempt() + { + var handler = new ScriptedHandler(() => Json(HttpStatusCode.TooManyRequests, "{}", "1")); + var client = Client(handler); + Assert.ThrowsAsync(() => Get(client)); + Assert.That(handler.Calls, Is.EqualTo(1)); + } + + [Test] + public async Task EnabledGet_RetriesThenSucceeds() + { + var handler = new ScriptedHandler( + () => Json(HttpStatusCode.TooManyRequests, "{}"), + () => Json(HttpStatusCode.OK, "{}")); + var client = Client(handler, Enabled()); + await Get(client); + Assert.That(handler.Calls, Is.EqualTo(2)); + } + + [Test] + public async Task EnabledHead_RetriesThenSucceeds() + { + var handler = new ScriptedHandler( + () => Json(HttpStatusCode.TooManyRequests, "{}"), + () => Json(HttpStatusCode.OK, "{}")); + var client = Client(handler, Enabled()); + await Head(client); + Assert.That(handler.Calls, Is.EqualTo(2)); + } + + [Test] + public void EnabledPost_NeverRetried() + { + var handler = new ScriptedHandler(() => Json(HttpStatusCode.TooManyRequests, "{}")); + var client = Client(handler, Enabled()); + Assert.ThrowsAsync(() => Post(client)); + Assert.That(handler.Calls, Is.EqualTo(1)); + } + + [Test] + public void ServerError_NeverRetried() + { + var handler = new ScriptedHandler(() => Json(HttpStatusCode.InternalServerError, "{\"code\":1,\"message\":\"boom\"}")); + var client = Client(handler, Enabled()); + Assert.ThrowsAsync(() => Get(client)); + Assert.That(handler.Calls, Is.EqualTo(1)); + } + + [Test] + public void Unrecoverable429_NeverRetried() + { + var handler = new ScriptedHandler(() => Json(HttpStatusCode.TooManyRequests, "{\"code\":9,\"message\":\"nope\",\"unrecoverable\":true}")); + var client = Client(handler, Enabled()); + Assert.ThrowsAsync(() => Get(client)); + Assert.That(handler.Calls, Is.EqualTo(1)); + } + + [Test] + public async Task TransportError_Retried() + { + var handler = new ThrowOnceHandler(); + var client = Client(handler, Enabled()); + await Get(client); + Assert.That(handler.Calls, Is.EqualTo(2)); + } + + [Test] + public void Exhaustion_SurfacesLastError() + { + var handler = new ScriptedHandler( + () => Json(HttpStatusCode.TooManyRequests, "{}"), + () => Json(HttpStatusCode.TooManyRequests, "{}"), + () => Json(HttpStatusCode.TooManyRequests, "{}")); + var client = Client(handler, Enabled(maxAttempts: 3)); + Assert.ThrowsAsync(() => Get(client)); + Assert.That(handler.Calls, Is.EqualTo(3)); + } + + [Test] + public void RetryDelay_ClampsAndJitters() + { + var client = Client(new ScriptedHandler(), new RetryConfig { Enabled = true, MaxAttempts = 3, MaxBackoff = TimeSpan.FromSeconds(30) }); + var rateLimited = new GetStreamRateLimitException("rl", 429, 9, new Dictionary(), false, "{}", TimeSpan.FromSeconds(600)); + Assert.That(client.RetryDelay(rateLimited, 0), Is.EqualTo(TimeSpan.FromSeconds(30))); + + var transport = new GetStreamTransportException("timeout", "timeout"); + for (var attempt = 0; attempt < 3; attempt++) + { + var ceil = TimeSpan.FromTicks(Math.Min(TimeSpan.FromSeconds(30).Ticks, TimeSpan.TicksPerSecond << attempt)); + for (var i = 0; i < 50; i++) + { + var d = client.RetryDelay(transport, attempt); + Assert.That(d, Is.InRange(TimeSpan.Zero, ceil)); + } + } + } + + // -- Logging integration (CHA-2957/CHA-2959 reconciliation) -------------------------- + + [Test] + public async Task TransportRetry_DebugLogCarriesErrorTypeAndRetryAttempt() + { + var logger = new RecordingLogger(); + var client = Client(new ThrowOnceHandler(), Enabled(), logger); + await Get(client); + + var failed = logger.Named("http.request.failed"); + Assert.That(failed, Has.Count.EqualTo(1)); + var (level, template, fields) = failed[0]; + Assert.That(level, Is.EqualTo(LogLevel.Debug)); + Assert.That(template, Does.Contain("{ErrorType}")); + Assert.That(template, Does.Contain("{RetryAttempt}")); + Assert.That(fields["RetryAttempt"], Is.EqualTo(1)); + Assert.That(fields["ErrorType"], Is.EqualTo("unknown")); + } + + [Test] + public async Task RateLimitRetry_DebugLogCarriesRetryAttemptButNoErrorType() + { + var handler = new ScriptedHandler( + () => Json(HttpStatusCode.TooManyRequests, "{}"), + () => Json(HttpStatusCode.OK, "{}")); + var logger = new RecordingLogger(); + var client = Client(handler, Enabled(), logger); + await Get(client); + + var failed = logger.Named("http.request.failed"); + Assert.That(failed, Has.Count.EqualTo(1)); + var (level, template, fields) = failed[0]; + Assert.That(level, Is.EqualTo(LogLevel.Debug)); + Assert.That(template, Does.Not.Contain("{ErrorType}")); + Assert.That(template, Does.Not.Contain("rate_limited")); + Assert.That(fields.ContainsKey("RetryAttempt"), Is.True); + Assert.That(fields["RetryAttempt"], Is.EqualTo(1)); + Assert.That(fields.ContainsKey("ErrorType"), Is.False); + } + + [Test] + public void Disabled_TransportFailure_LogsSingleErrorWithAllFields() + { + var logger = new RecordingLogger(); + var client = Client(new ThrowOnceHandler(), retry: null, logger: logger); + Assert.ThrowsAsync(() => Get(client)); + + var failed = logger.Named("http.request.failed"); + Assert.That(failed, Has.Count.EqualTo(1)); + var (level, template, fields) = failed[0]; + Assert.That(level, Is.EqualTo(LogLevel.Error)); + Assert.That(template, Does.Contain("{ErrorType}")); + Assert.That(fields.ContainsKey("RetryAttempt"), Is.False); + } + + [Test] + public void Disabled_RateLimit_LogsNoFailed() + { + var handler = new ScriptedHandler(() => Json(HttpStatusCode.TooManyRequests, "{}")); + var logger = new RecordingLogger(); + var client = Client(handler, retry: null, logger: logger); + Assert.ThrowsAsync(() => Get(client)); + + Assert.That(logger.Named("http.request.failed"), Is.Empty); + Assert.That(logger.Named("http.response.received"), Has.Count.EqualTo(1)); + } + } +}