Hard Cases in Unit Testing: Async Code, Time, Exceptions, Logging and Background Services

Version note: The code in this post was built and run with .NET 10, xUnit.net v3 4.0.2, Microsoft.Extensions.TimeProvider.Testing 10.11.0 and Microsoft.Extensions.Diagnostics.Testing 10.11.0.

Predict First

When an order is handed to the courier, Bookstore sends a notification to the courier company's API (Application Programming Interface). The courier service returns 503 now and then, so the notification is tried at most four times with exponential backoff. Time is taken from outside through TimeProvider, as in post 09:

public static class Backoff
{
    // 1 s, 2 s, 4 s, ... capped at 30 s
    public static TimeSpan For(int attempt) =>
        TimeSpan.FromSeconds(Math.Min(30, Math.Pow(2, attempt - 1)));
}

public sealed partial class ShipmentNotifier(
    ICourierClient courier, TimeProvider time, ILogger<ShipmentNotifier> logger)
{
    public const int MaxAttempts = 4;

    public async Task NotifyAsync(ShipmentNotice notice, CancellationToken ct)
    {
        for (int attempt = 1; ; attempt++)
        {
            try
            {
                await courier.SendAsync(notice, ct);
                return;
            }
            catch (HttpRequestException ex) when (attempt < MaxAttempts)
            {
                LogRetry(notice.OrderNumber, attempt, ex.Message);
                await Task.Delay(Backoff.For(attempt), time, ct);
            }
            catch (HttpRequestException ex)
            {
                LogGaveUp(ex, notice.OrderNumber, attempt);
                throw new ShipmentNotificationException(notice.OrderNumber, attempt, ex);
            }
        }
    }

    [LoggerMessage(Level = LogLevel.Warning, Message = "Courier call for {OrderNumber} failed on attempt {Attempt}: {Reason}")]
    private partial void LogRetry(string orderNumber, int attempt, string reason);

    [LoggerMessage(Level = LogLevel.Critical, Message = "Giving up on shipment notice for {OrderNumber} after {Attempts} attempts")]
    private partial void LogGaveUp(Exception ex, string orderNumber, int attempts);
}

The test uses a fake courier service that fails on the first call and succeeds on the second, plus a FakeTimeProvider:

[Fact(Timeout = 2000)]
public async Task Naive_await_never_finishes()
{
    ScriptedCourier courier = new(failuresBeforeSuccess: 1);
    ShipmentNotifier sut = new(courier, time, NullLogger<ShipmentNotifier>.Instance);

    await sut.NotifyAsync(Notice, TestContext.Current.CancellationToken);

    Assert.Single(courier.Delivered);
}

With a real clock this test would take 1 second. How long does it take with FakeTimeProvider?

The Answer: It Never Finishes

failed (canceled) Bookstore.Notifications.Tests.ShipmentNotifierTests.Naive_await_never_finishes (2s 004ms)
  Xunit.MicrosoftTestingPlatform.XunitException: Test execution timed out after 2000 milliseconds

FakeTimeProvider's clock does not move on its own. The first call failed, the service started waiting with Task.Delay(1 s, time), and that wait lasts until someone advances the clock. The test, meanwhile, waits for the service to finish with await, so nobody is left to advance the clock. Without Timeout, this test would hang in CI (Continuous Integration) forever; this is the situation we had in mind in post 02 when we stressed passing TestContext.Current.CancellationToken. The rule for testing with a fake clock is: start the operation, advance the clock, then await. This post covers that rule and the other hard corners of unit testing: retry, exceptions, logs, cancellation and background services.

Advancing Time: Start, Advance, Await

[Fact]
public async Task Transient_failure_is_retried_after_one_second()
{
    ScriptedCourier courier = new(failuresBeforeSuccess: 1);
    ShipmentNotifier sut = new(courier, time, NullLogger<ShipmentNotifier>.Instance);

    Task notifying = sut.NotifyAsync(Notice, TestContext.Current.CancellationToken);
    Assert.False(notifying.IsCompleted);

    time.Advance(TimeSpan.FromMilliseconds(999));
    Assert.False(notifying.IsCompleted);

    time.Advance(TimeSpan.FromMilliseconds(1));
    await notifying;

    Assert.Equal(2, courier.Calls);
    Assert.Single(courier.Delivered);
}

The Task returned by NotifyAsync is held in a variable, not awaited. At this point the service has made its first attempt and set up a timer bound to the fake clock. After advancing 999 ms the task is still not finished; advancing one more millisecond fires the timer, the second attempt succeeds and the task completes. The test takes milliseconds of real time and verifies the boundary exactly: the wait is not shorter than 1 second.

There is a detail to watch here: the fake courier throws its exception synchronously, so NotifyAsync returns to the caller after setting up the first Task.Delay. In the real world, when an await point gets in between, calling Advance without making sure the timer has been set up makes the test depend on timing. I ran these tests 15 times in a row, and all 10 tests passed every time; because they are deterministic. The C# Async Programlama (C# Async Programming) series explains the mechanics of async/await in detail; what matters here is that the code has reached the point where it waits before the test advances the clock.

Retry, Backoff and Cancellation

Retry logic has two separate questions, and testing them separately makes things easier. The first is the wait durations: a pure function that needs no time.

[Theory]
[InlineData(1, 1)]
[InlineData(2, 2)]
[InlineData(3, 4)]
[InlineData(6, 30)]
[InlineData(10, 30)]
public void Backoff_doubles_up_to_30_seconds(int attempt, int expectedSeconds) =>
    Assert.Equal(TimeSpan.FromSeconds(expectedSeconds), Backoff.For(attempt));

The second is the flow: how many attempts, when to give up, what happens on giving up. For this we advance the fake clock by each wait:

[Fact]
public async Task Gives_up_after_four_attempts_with_a_critical_log()
{
    ScriptedCourier courier = new(failuresBeforeSuccess: int.MaxValue);
    FakeLogger<ShipmentNotifier> logger = new();
    ShipmentNotifier sut = new(courier, time, logger);

    Task notifying = sut.NotifyAsync(Notice, TestContext.Current.CancellationToken);
    time.Advance(TimeSpan.FromSeconds(1));
    time.Advance(TimeSpan.FromSeconds(2));
    time.Advance(TimeSpan.FromSeconds(4));

    ShipmentNotificationException ex =
        await Assert.ThrowsAsync<ShipmentNotificationException>(() => notifying);
    Assert.Equal("BS-1042", ex.OrderNumber);
    Assert.IsType<HttpRequestException>(ex.InnerException);
    Assert.Equal(4, courier.Calls);
    FakeLogRecord last = logger.LatestRecord;
    Assert.Equal(LogLevel.Critical, last.Level);
    Assert.Equal("Giving up on shipment notice for BS-1042 after 4 attempts", last.Message);
}

[Fact]
public async Task Cancellation_during_backoff_stops_retrying()
{
    ScriptedCourier courier = new(failuresBeforeSuccess: int.MaxValue);
    ShipmentNotifier sut = new(courier, time, NullLogger<ShipmentNotifier>.Instance);
    using CancellationTokenSource cts = new();

    Task notifying = sut.NotifyAsync(Notice, cts.Token);
    cts.Cancel();

    await Assert.ThrowsAnyAsync<OperationCanceledException>(() => notifying);
    Assert.Equal(1, courier.Calls);
}

With a real clock, the "gives up after four attempts" test would take 1 + 2 + 4 = 7 seconds; ten retry tests, a one-minute suite. With a fake clock, milliseconds. The cancellation test works the same way: the token is cancelled while the service is waiting, and Task.Delay ends immediately with TaskCanceledException; the second attempt is never made. We used ThrowsAnyAsync<OperationCanceledException>, because the cancellation arrives as TaskCanceledException (a subtype); as we saw in post 02, ThrowsAsync requires the exact type.

Exceptions and Logs: Asserting at the Right Level

In the test above, the exception is verified at three levels: the type (ShipmentNotificationException), data that is meaningful to the business (OrderNumber), and the cause (the type of InnerException). We did not verify the full text of the message. An exception message is usually text that goes to logs and error screens and changes over time; tying the test to it means a red test for a typo fix. The rule: verify what lets the caller make decisions based on the exception (type, properties, inner exception), not the text meant for humans to read. Verifying the message "A shipped order cannot be cancelled." in post 02 was an exception: there the message becomes an API response and is part of the contract.

The same logic applies to logs. The service writes a warning on every retry and a critical log when it gives up. The test verifies only the critical one, because it is the source of an alert: the operations team learns from this log that the courier notification has failed completely. Verifying the warnings one by one would lock the retry count into log lines. FakeLogger's LatestRecord and Collector.GetSnapshot() are enough for this. In post 06 we saw why FakeLogger is better than an ILogger mock; here the question is "which log", and the answer is: the one that is part of the behavior.

BackgroundService and Channel<T>

Courier notifications are triggered by events arriving through a Channel<OrderShipped>. Following the Humble Object idea from post 09, the loop is kept thin and handling each message is split into a public method:

// The loop is thin; handling each message is separate and testable
public sealed class ShipmentEventsConsumer(ChannelReader<OrderShipped> events, ShipmentNotifier notifier)
    : BackgroundService
{
    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        await foreach (OrderShipped shipped in events.ReadAllAsync(stoppingToken))
        {
            await HandleAsync(shipped, stoppingToken);
        }
    }

    public Task HandleAsync(OrderShipped shipped, CancellationToken ct) =>
        notifier.NotifyAsync(new ShipmentNotice(shipped.OrderNumber, shipped.Email, shipped.TrackingCode), ct);
}

[Fact]
public async Task Handling_one_event_sends_one_notice()
{
    await CreateConsumer().HandleAsync(
        new OrderShipped("BS-1042", "ada@example.com", "TRK-77"), TestContext.Current.CancellationToken);

    Assert.Equal("TRK-77", Assert.Single(courier.Delivered).TrackingCode);
}

[Fact]
public async Task Worker_drains_the_channel_until_it_is_completed()
{
    ShipmentEventsConsumer consumer = CreateConsumer();
    await channel.Writer.WriteAsync(new("BS-1", "ada@example.com", "TRK-1"), TestContext.Current.CancellationToken);
    await channel.Writer.WriteAsync(new("BS-2", "alan@example.com", "TRK-2"), TestContext.Current.CancellationToken);
    channel.Writer.Complete();

    await consumer.StartAsync(TestContext.Current.CancellationToken);
    await consumer.ExecuteTask!.WaitAsync(TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken);

    Assert.Equal(["BS-1", "BS-2"], courier.Delivered.Select(n => n.OrderNumber));
}

The first test tests message handling itself, independent of the loop. The second tests the loop's contract: everything written to the channel is processed in order, and the loop ends when the writer completes. The key is channel.Writer.Complete(): on a completed channel, ReadAllAsync yields the remaining messages and ends, so ExecuteTask completes and the test does not have to say "wait a bit, then look". WaitAsync(TimeSpan.FromSeconds(5), ...) is a safety net: if there is a bug in the loop, the test fails in 5 seconds instead of hanging. The general design of background work is covered in the Background Job'lar ve Scheduled Job'lar (Background Jobs and Scheduled Jobs) series; here we only look at the testable form.

async void and Fire-and-Forget

Two async forms cannot be tested. An async void method has no return value; the caller cannot know when it finishes, and an exception thrown inside it goes not to the caller but to the synchronization context (and, if there is none, can crash the process). Do not write async void except for event handlers; as we saw in post 02, xUnit v3 rejects async void test methods at compile time. Fire-and-forget, a task started with _ = SendAsync(...) and never awaited, has the same problem: the test sees the service return but cannot see whether the work is done; the assert either runs too early, or a "wait a bit" gets added. The fix is in the design: put the work on a queue or a channel and test its consumer separately as above, or return the task and let the caller await it.

In Production

In production, retry is usually not your own loop but a resilience library (Polly or Microsoft.Extensions.Http.Resilience). If you configure them to take a TimeProvider, the same fake clock technique works. The system design side of retry, backoff and jitter is in the "Reliability Pattern'leri" (Reliability Patterns) post of the System Design series.

Give tests an upper time limit. An async test hangs if the thing it waits for never happens. With Timeout, WaitAsync, or --timeout at the MTP (Microsoft Testing Platform) level, every run should have an upper bound; a hung CI job is more expensive than a failing test.

Do not mix the fake clock with the real one. Microsoft's FakeTimeProvider documentation warns about this too: if one place in a test uses TimeProvider.System and another uses the fake clock, the behavior becomes unpredictable. Pass the same instance everywhere the code takes a TimeProvider.

Common Pitfalls

Waiting with Thread.Sleep and Task.Delay. A test that says "wait 500 ms for the background job to finish" is both slow and fails on a slow CI machine. Instead of waiting, wait for the signal that it has finished: the returned Task, a completed channel, a TaskCompletionSource.

Waiting on async code synchronously with .Result and .Wait(). It blocks the thread; in environments with a synchronization context it leads to the classic deadlock, and in tests running in parallel it needlessly consumes the thread pool. Make the test method async Task and await.

Tests tied to the real clock. Writing a "token expires after 30 minutes" test with a real clock is impossible, and writing a "1-second timeout" test with a real clock is slow and brittle. A fake clock through TimeProvider makes both take milliseconds and deterministic.

Verifying every log line. Log texts change often; verify only the logs that are part of the behavior (those that raise alerts or are needed for auditing).

A Small Experiment

★☆☆ Fix the Naive_await_never_finishes test with the "start, advance, await" order from Transient_failure_is_retried_after_one_second. What did the test's duration become?

★★☆ Add jitter to Backoff.For (a random extra of 0 to 250 ms on the wait). Take the randomness from a function supplied from outside instead of Random, and update both Backoff_doubles_up_to_30_seconds and Gives_up_after_four_attempts_with_a_critical_log so that they stay deterministic.

★★★ Add a behavior to ShipmentEventsConsumer so that when handling a message ends with ShipmentNotificationException, the loop does not stop but moves on to the next message. Describe it with a test first: of three messages, the middle one always fails, and the first and third are delivered.

In the next post we extend the limits of example-based tests: approving large outputs as snapshots with Verify, and testing properties that "hold for every input" with FsCheck.