diff --git a/CHANGELOG.md b/CHANGELOG.md index 25e86038c2..7e49dd7c85 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ - The SDK now logs a `Warning` instead of an `Error` when being ratelimited ([#4927](https://github.com/getsentry/sentry-dotnet/pull/4927)) - Symbolication now works correctly with Android workloads 10.0.102 and later ([#4998](https://github.com/getsentry/sentry-dotnet/pull/4998)) - `libmonosgen` and `libxamarin` frames no longer show as in-app ([#4960](https://github.com/getsentry/sentry-dotnet/pull/4960)) +- The SDK now logs only the first consecutive error when sending envelopes to Spotlight, and uses exponential backoff before subsequent attempts ([#5025](https://github.com/getsentry/sentry-dotnet/pull/5025)) ## 6.2.0-alpha.0 diff --git a/src/Sentry/Http/SpotlightHttpTransport.cs b/src/Sentry/Http/SpotlightHttpTransport.cs index 097847531f..80ad6504d8 100644 --- a/src/Sentry/Http/SpotlightHttpTransport.cs +++ b/src/Sentry/Http/SpotlightHttpTransport.cs @@ -12,6 +12,7 @@ internal class SpotlightHttpTransport : HttpTransport private readonly HttpClient _httpClient; private readonly Uri _spotlightUrl; private readonly ISystemClock _clock; + private readonly ExponentialBackoff _backoff; public SpotlightHttpTransport(ITransport inner, SentryOptions options, HttpClient httpClient, Uri spotlightUrl, ISystemClock clock) : base(options, httpClient) @@ -21,6 +22,7 @@ public SpotlightHttpTransport(ITransport inner, SentryOptions options, HttpClien _spotlightUrl = spotlightUrl; _inner = inner; _clock = clock; + _backoff = new ExponentialBackoff(clock); } protected internal override HttpRequestMessage CreateRequest(Envelope envelope) @@ -38,23 +40,79 @@ public override async Task SendEnvelopeAsync(Envelope envelope, CancellationToke { var sentryTask = _inner.SendEnvelopeAsync(envelope, cancellationToken); - try + if (_backoff.ShouldAttempt()) { - // Send to spotlight - using var processedEnvelope = ProcessEnvelope(envelope); - if (processedEnvelope.Items.Count > 0) + try { - using var request = CreateRequest(processedEnvelope); - using var response = await _httpClient.SendAsync(request, cancellationToken).ConfigureAwait(false); - await HandleResponseAsync(response, processedEnvelope, cancellationToken).ConfigureAwait(false); + // Send to spotlight + using var processedEnvelope = ProcessEnvelope(envelope); + if (processedEnvelope.Items.Count > 0) + { + using var request = CreateRequest(processedEnvelope); + using var response = await _httpClient.SendAsync(request, cancellationToken).ConfigureAwait(false); + await HandleResponseAsync(response, processedEnvelope, cancellationToken).ConfigureAwait(false); + + _backoff.RecordSuccess(); + } + } + catch (Exception e) + { + int failureCount = _backoff.RecordFailure(); + if (failureCount == 1) + { + _options.LogError(e, "Failed sending envelope to Spotlight."); + } } - } - catch (Exception e) - { - _options.LogError(e, "Failed sending envelope to Spotlight."); } // await the Sentry request before returning await sentryTask.ConfigureAwait(false); } + + private class ExponentialBackoff + { + private static readonly TimeSpan InitialRetryDelay = TimeSpan.FromSeconds(1); + private static readonly TimeSpan MaxRetryDelay = TimeSpan.FromSeconds(60); + + private readonly ISystemClock _clock; + + private readonly Lock _lock = new(); + private TimeSpan _retryDelay = InitialRetryDelay; + private DateTimeOffset _retryAfter = DateTimeOffset.MinValue; + private int _failureCount; + + public ExponentialBackoff(ISystemClock clock) + { + _clock = clock; + } + + public bool ShouldAttempt() + { + lock (_lock) + { + return _clock.GetUtcNow() >= _retryAfter; + } + } + + public int RecordFailure() + { + lock (_lock) + { + _failureCount++; + _retryAfter = _clock.GetUtcNow() + _retryDelay; + _retryDelay = TimeSpan.FromTicks(Math.Min(_retryDelay.Ticks * 2, MaxRetryDelay.Ticks)); + return _failureCount; + } + } + + public void RecordSuccess() + { + lock (_lock) + { + _failureCount = 0; + _retryDelay = InitialRetryDelay; + _retryAfter = DateTimeOffset.MinValue; + } + } + } } diff --git a/test/Sentry.Tests/Internals/Http/SpotlightTransportTests.cs b/test/Sentry.Tests/Internals/Http/SpotlightTransportTests.cs index 0669280b4b..c073b9790c 100644 --- a/test/Sentry.Tests/Internals/Http/SpotlightTransportTests.cs +++ b/test/Sentry.Tests/Internals/Http/SpotlightTransportTests.cs @@ -5,37 +5,82 @@ namespace Sentry.Tests.Internals.Http; public class SpotlightTransportTests { + private static readonly DateTimeOffset StartTime = new(2024, 1, 1, 0, 0, 0, TimeSpan.Zero); + + private class Fixture + { + public MockClock Clock { get; } = new(StartTime); + public MockableHttpMessageHandler Handler { get; } = Substitute.For(); + public InMemoryDiagnosticLogger Logger { get; } = new(); + public ITransport InnerTransport { get; } = Substitute.For(); + + private bool _shouldFail; + + public Fixture() + { + InnerTransport.SendEnvelopeAsync(Arg.Any(), Arg.Any()) + .Returns(Task.CompletedTask); + } + + public void ConfigureHandlerToThrow(Exception exception = null) + { + Handler.WhenForAnyArgs(h => h.VerifiableSendAsync(null!, CancellationToken.None)) + .Throw(exception ?? new HttpRequestException("Connection refused")); + } + + public void ConfigureHandlerWithFlag(bool shouldFail = true) + { + _shouldFail = shouldFail; + Handler.VerifiableSendAsync(Arg.Any(), Arg.Any()) + .Returns(_ => + { + if (_shouldFail) throw new HttpRequestException("Connection refused"); + return SentryResponses.GetOkResponse(); + }); + } + + public void SetShouldFail(bool value) => _shouldFail = value; + + public int SpotlightErrorCount() + { + return Logger.Entries.Count(e => + e.Level == SentryLevel.Error && + e.Message == "Failed sending envelope to Spotlight."); + } + + public SpotlightHttpTransport GetSut() + { + var options = new SentryOptions + { + Dsn = ValidDsn, + Debug = true, + DiagnosticLogger = Logger + }; + return new SpotlightHttpTransport( + InnerTransport, + options, + new HttpClient(Handler), + new Uri("http://localhost:8969/stream"), + Clock); + } + } + // Makes sure it'll call both inner transport and spotlight, even if spotlight's request fails. // Inner transport error actually bubbles up instead of Spotlights' [Fact] public async Task SendEnvelopeAsync_SpotlightRequestFailed_InnerTransportFailureBubblesUp() { // Arrange - var httpHandler = Substitute.For(); + var fixture = new Fixture(); var expectedSpotlightTransportException = new Exception("Spotlight request fails"); - httpHandler.WhenForAnyArgs(h => h.VerifiableSendAsync(null, CancellationToken.None)) - .Throw(expectedSpotlightTransportException); - - var innerTransport = Substitute.For(); - var logger = new InMemoryDiagnosticLogger(); - - var sut = new SpotlightHttpTransport( - innerTransport, - new SentryOptions - { - Dsn = ValidDsn, - Debug = true, - DiagnosticLogger = logger - }, - new HttpClient(httpHandler), - new Uri("http://localhost:8969/stream"), - Substitute.For()); + fixture.ConfigureHandlerToThrow(expectedSpotlightTransportException); + var sut = fixture.GetSut(); var envelope = Envelope.FromEvent(new SentryEvent()); var expectedInnerTransportException = new Exception("expected inner transport exception"); var tcs = new TaskCompletionSource(); tcs.SetException(expectedInnerTransportException); - innerTransport.SendEnvelopeAsync(envelope).Returns(tcs.Task); + fixture.InnerTransport.SendEnvelopeAsync(envelope).Returns(tcs.Task); // Act var actualException = await Assert.ThrowsAsync(() => sut.SendEnvelopeAsync(envelope)); @@ -45,10 +90,244 @@ public async Task SendEnvelopeAsync_SpotlightRequestFailed_InnerTransportFailure Assert.Same(expectedInnerTransportException, actualException); // Spotlight request failure logged out to diagnostic logger - logger.Entries.Any(e => + fixture.Logger.Entries.Any(e => e.Level == SentryLevel.Error && e.Message == "Failed sending envelope to Spotlight." && ReferenceEquals(expectedSpotlightTransportException, e.Exception) ).Should().BeTrue(); } + + // Test error handling and backoff logic + // Ref: https://develop.sentry.dev/sdk/foundations/client/integrations/spotlight/#error-handling + + // Spec: Unreachable Server — SDKs "MUST log an error message at least once" + [Fact] + public async Task SendEnvelopeAsync_FirstFailure_LogsError() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // Act + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert + fixture.SpotlightErrorCount().Should().Be(1); + } + + // Spec: Unreachable Server — SDKs "MUST NOT log an error message for every failed envelope" + // Spec: Logging — "MUST avoid logging errors for every failed envelope to prevent log spam" + [Fact] + public async Task SendEnvelopeAsync_SecondFailureAfterBackoff_DoesNotLogAgain() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // Act — first failure (logs error, sets backoff to 1s) + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Advance past backoff so second attempt is made + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(2)); + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — still only one error logged + fixture.SpotlightErrorCount().Should().Be(1); + } + + // Spec: Unreachable Server — SDKs "SHOULD implement exponential backoff retry logic" + // Spec: "Spotlight transmission MUST never block normal Sentry operation." + // Verifies sends are skipped during backoff, but inner transport still runs. + [Fact] + public async Task SendEnvelopeAsync_DuringBackoffPeriod_SkipsSpotlightSend() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // First failure — sets backoff to 1s + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Advance only 500ms (still within 1s backoff) + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromMilliseconds(500)); + fixture.Handler.ClearReceivedCalls(); + + // Act + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — Spotlight HTTP call was NOT made during backoff + await fixture.Handler.DidNotReceiveWithAnyArgs().VerifiableSendAsync(null!, CancellationToken.None); + + // Inner transport was still called for both envelopes + await fixture.InnerTransport.Received(2).SendEnvelopeAsync(Arg.Any(), Arg.Any()); + } + + // Spec: Unreachable Server — SDKs "SHOULD implement exponential backoff retry logic" + // Verifies that after the backoff period expires, Spotlight send is retried on the next envelope. + [Fact] + public async Task SendEnvelopeAsync_AfterBackoffExpires_RetriesSpotlightSend() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // First failure — sets backoff to 1s + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Advance past the 1s backoff + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(1.5)); + fixture.Handler.ClearReceivedCalls(); + + // Act + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — Spotlight HTTP call WAS made after backoff expired + await fixture.Handler.ReceivedWithAnyArgs(1).VerifiableSendAsync(null!, CancellationToken.None); + } + + // Spec: Unreachable Server — SDKs "SHOULD implement exponential backoff retry logic" + // Verifies the doubling sequence: 1s -> 2s -> ... + [Fact] + public async Task SendEnvelopeAsync_ConsecutiveFailures_BackoffDoubles() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // First failure — backoff = 1s + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Advance past 1s, second failure — backoff = 2s + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(1.5)); + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Advance only 1.5s more (total 3s from start, but need 2s from last failure at t=1.5s) + // Last failure was at t=1.5s, backoff=2s, so retryAfter=3.5s + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(3)); + fixture.Handler.ClearReceivedCalls(); + + // Act — should be skipped (3.0 < 3.5) + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — still in backoff, no call made + await fixture.Handler.DidNotReceiveWithAnyArgs().VerifiableSendAsync(null!, CancellationToken.None); + + // Advance past 3.5s — now should retry + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(4)); + fixture.Handler.ClearReceivedCalls(); + + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — call was made + await fixture.Handler.ReceivedWithAnyArgs(1).VerifiableSendAsync(null!, CancellationToken.None); + } + + [Fact] + public async Task SendEnvelopeAsync_BackoffCapsAtSixtySeconds() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + var currentTime = StartTime; + + // Fail repeatedly to escalate backoff: 1, 2, 4, 8, 16, 32, 64->60 + // Each iteration: send (fails at currentTime), then advance clock past the backoff + var expectedDelays = new[] { 1, 2, 4, 8, 16, 32, 60 }; + foreach (var delay in expectedDelays) + { + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + // retryAfter was set to currentTime + delay inside the catch + currentTime += TimeSpan.FromSeconds(delay) + TimeSpan.FromMilliseconds(100); + fixture.Clock.SetUtcNow(currentTime); + } + + // The 7th failure happened at clock = StartTime + sum(1..32) + 6*0.1 = StartTime + 63.6s + // retryDelay capped at 60 (not 64), so retryAfter = StartTime + 63.6 + 60 = StartTime + 123.6s + + // At 123s from start — should still be in backoff + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(123)); + fixture.Handler.ClearReceivedCalls(); + + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + await fixture.Handler.DidNotReceiveWithAnyArgs().VerifiableSendAsync(null!, CancellationToken.None); + + // At 124s from start — should retry (proves cap at 60, not 64) + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(124)); + fixture.Handler.ClearReceivedCalls(); + + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + await fixture.Handler.ReceivedWithAnyArgs(1).VerifiableSendAsync(null!, CancellationToken.None); + } + + // Spec: Logging — "MAY consider logging once per connection failure, then periodically if + // failures persist" + // Verifies that a successful send resets all backoff state (delay, log flag), so the next + // failure is treated as a fresh first failure. + [Fact] + public async Task SendEnvelopeAsync_SuccessAfterFailure_ResetsBackoffState() + { + // Arrange — use a flag to control handler behavior + var fixture = new Fixture(); + fixture.ConfigureHandlerWithFlag(shouldFail: true); + var sut = fixture.GetSut(); + + // First failure — error logged, backoff = 1s + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + fixture.SpotlightErrorCount().Should().Be(1); + + // Advance past backoff, switch to success + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(2)); + fixture.SetShouldFail(false); + + // Success — resets all backoff state + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Switch back to failure + fixture.SetShouldFail(true); + + // Act — fail again immediately (no backoff because state was reset) + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + + // Assert — a second error IS logged (hasLoggedError was reset) + fixture.SpotlightErrorCount().Should().Be(2); + + // Verify backoff reset to 1s (not 2s): advance 1.5s should allow retry + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(4)); + fixture.Handler.ClearReceivedCalls(); + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); + await fixture.Handler.ReceivedWithAnyArgs(1).VerifiableSendAsync(null!, CancellationToken.None); + } + + // Spec: "Spotlight transmission MUST never block normal Sentry operation." + // Spec: Unreachable Server — SDKs "MUST continue normal Sentry operation without interruption" + // Spec: "Spotlight failures MUST NOT affect event capture, transaction recording, or any + // other SDK functionality" + // Verifies inner transport is called for every envelope, even those skipped during backoff. + [Fact] + public async Task SendEnvelopeAsync_SpotlightFails_InnerTransportAlwaysRuns() + { + // Arrange + var fixture = new Fixture(); + fixture.ConfigureHandlerToThrow(); + var sut = fixture.GetSut(); + + // Act — send 3 envelopes: first fails, second during backoff, third after backoff + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); // fails, backoff=1s + + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromMilliseconds(500)); // during backoff + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); // skipped + + fixture.Clock.SetUtcNow(StartTime + TimeSpan.FromSeconds(2)); // after backoff + await sut.SendEnvelopeAsync(Envelope.FromEvent(new SentryEvent())); // retried, fails + + // Assert — inner transport was called for ALL 3 envelopes + await fixture.InnerTransport.Received(3).SendEnvelopeAsync(Arg.Any(), Arg.Any()); + } }