Unit testing ILogger with NSubstitute and time information

There are several problems when testing a method like

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        logger.LogInformation("QueueProcessorService started at: {time:g}", timeProvider.GetUtcNow());

        while (!stoppingToken.IsCancellationRequested)
        {
            await processor.TryProcessingAsync(stoppingToken).ConfigureAwait(false);
            await Task.Delay(Constants.QUEUE_POLLING_INTERVAL).ConfigureAwait(false); 
        }

        logger.LogInformation("QueueProcessorService stopped at: {time:g}", timeProvider.GetUtcNow());
    }

and more specifically the logger.LogInformation calls. For one thing, doing a simple

await Task.Delay(Constants.QUEUE_POLLING_INTERVAL).ConfigureAwait(false);

will actually slow down the test for however long the specified interval is. This is unacceptable for any significant value of QUEUE_POLLING_INTERVAL (the production code might only want to check the queue once an hour). This means that we need to use a FakeTimeProvider in the tests, but more importantly we also need to use the TimeProvider in the Task.Delay call:

await Task.Delay(Constants.QUEUE_POLLING_INTERVAL, timeProvider, stoppingToken).ConfigureAwait(false);

Another issue is that trying to match the time will not work (at least with NSubstitute). This unit test will fail:

    [TestMethod("Logs the start and stop time")]
    public async Task LogsStartAndStop()
    {
        var start = new DateTimeOffset(2000, 1, 2, 3, 4, 5, TimeSpan.Zero);
        timeProvider.SetUtcNow(start);
        using (var cts = new CancellationTokenSource())
        {
            await sut.StartAsync(cts.Token).ConfigureAwait(false);

            timeProvider.Advance(TimeSpan.FromHours(1));

            await cts.CancelAsync().ConfigureAwait(false);
        }

        await Task.Delay(10).ConfigureAwait(false);
        logger.Received().LogInformation("QueueProcessorService started at: {time:g}", start);
        logger.Received().LogInformation("QueueProcessorService stopped at: {time:g}", start.AddHours(1));
    }

The error message is:

NSubstitute.Exceptions.ReceivedCallsException: Expected to receive a call matching:
    Log<FormattedLogValues>(Information, 0, QueueProcessorService started at: 01/02/2000 03:04, <null>, Func<FormattedLogValues, Exception, String>)
Actually received no matching calls.
Received 1 non-matching call (non-matching arguments indicated with '*' characters):
    Log<FormattedLogValues>(Information, 0, *QueueProcessorService started at: 01/02/2000 03:04*, <null>, Func<FormattedLogValues, Exception, String>) 

which, when the fluff is ignored, claims that these two strings are not equal:

QueueProcessorService started at: 01/02/2000 03:04
QueueProcessorService started at: 01/02/2000 03:04

Whether the reason is that the LogInformation extension method does some processing and fails to match the arguments exactly or some bug in NSubstitute is irrelevant. The solution I ended up using was to save all (non-extension) logger.Log calls as strings and compare those directly. Since the LogLevel is also important, I ended up with this extension class:

public static class LoggerExtensions
{
    public static readonly Dictionary<LogLevel, List<string>> MESSAGES = new();

    public static void RecordLogMessages<T>(this ILogger<T> logger)
    {
        MESSAGES.Clear();
        logger
            .When(it => it.Log(Arg.Any<LogLevel>(), Arg.Any<EventId>(), Arg.Any<Arg.AnyType>(), Arg.Any<Exception?>(), Arg.Any<Func<Arg.AnyType, Exception?, string>>()))
            .Do(callInfo =>
            {
                var logLevel = (LogLevel)callInfo[0];
                var message = callInfo[2].ToString()!;
                if (!MESSAGES.ContainsKey(logLevel))
                    MESSAGES[logLevel] = [];
                MESSAGES[logLevel].Add(message);
            });
    }
}

and the unit test became

    [TestMethod("Logs the start and stop time")]
    public async Task LogsStartAndStop()
    {
        logger.RecordLogMessages();

        var start = new DateTimeOffset(2000, 1, 2, 3, 4, 5, TimeSpan.Zero);
        timeProvider.SetUtcNow(start);
        using (var cts = new CancellationTokenSource())
        {
            await sut.StartAsync(cts.Token).ConfigureAwait(false);

            timeProvider.Advance(TimeSpan.FromHours(1));

            await cts.CancelAsync().ConfigureAwait(false);
        }

        await Task.Delay(10).ConfigureAwait(false);
        Assert.AreEqual(2, LoggerExtensions.MESSAGES[LogLevel.Information].Count);
        Assert.AreEqual("QueueProcessorService started at: 01/02/2000 03:04", LoggerExtensions.MESSAGES[LogLevel.Information][0]);
        Assert.AreEqual("QueueProcessorService stopped at: 01/02/2000 04:04", LoggerExtensions.MESSAGES[LogLevel.Information][1]);
    }

Unfortunately this did not completely solve the problem. The error message is now

Assert.AreEqual failed. Expected:<2>. Actual:<1>.

The reason is annoying and took me a while to figure out: the Task.Delay call actually throws an exception because cancellation is requested. Fortunately there is a way to solve it: replace ConfigureAwait(false) with ConfigureAwait(ConfigureAwaitOptions.SuppressThrowing). This is the final version of the production code:

    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
    {
        logger.LogInformation("QueueProcessorService started at: {time:g}", timeProvider.GetUtcNow());

        while (!stoppingToken.IsCancellationRequested)
        {
            await processor.TryProcessingAsync(stoppingToken).ConfigureAwait(false);
            await Task.Delay(Constants.QUEUE_POLLING_INTERVAL, timeProvider, stoppingToken).ConfigureAwait(ConfigureAwaitOptions.SuppressThrowing);
        }

        logger.LogInformation("QueueProcessorService stopped at: {time:g}", timeProvider.GetUtcNow());
    }

Hope this helps someone else.

P.S. Note that adding a

[DoNotParallelize]

attribute to the unit test is recommended, because the LoggerExtensions.MESSAGES object is singleton and writing to it from multiple tests at the same time will result in failed tests.