【C#】FakeTimeProvider と FakeLogger を試す

.NET 8 の目玉のひとつに時間抽象化があり、それを利用したFakeTimeProviderが提供された。 (.NET 8～)
また、同様に Fake を冠するロガーとして、FakeLoggerが提供された。 (.NET 8～)

前者はMicrosoft.Extensions.TimeProvider.Testingパッケージ、後者はMicrosoft.Extensions.Diagnostics.Testingパッケージが必要で、導入は NuGet から可。

今回、時間経過を利用したクラスを設定し、これらを試してみたいと思う。

なお、.NET blog に今回のふたつに Metric をあわせて解説する参考記事があるため、はじめに紹介。
・Fake It Til You Make It...To Production - .NET Blog

以下の画像は、笑ってしまった上記参考記事の機械翻訳

今回扱うオブジェクト
FakeTimeProvider
FakeLogger

今回扱うオブジェクト

まず、ILoggerと、時間抽象化の核となるTimeProviderを持たせる。

public class FakeSandbox(
    ILogger<FakeSandbox> logger,
    TimeProvider timeProvider)
{
    private readonly ILogger<FakeSandbox> logger = logger;
    private readonly TimeProvider timeProvider = timeProvider;
}

内容については、種類のあるミッションのインプットを受け、時間経過により資源を受け取るというものを考える。

// ミッションの種類
public enum MissionKind { None, A, B, C };

public int Resource { get; private set; } = 0; // 資源
public MissionKind Ongoing { get; private set; } = MissionKind.None; // 進行中ミッション
public ITimer? Timer { get; private set; } // 進行タイマー

// ミッションに応じた必要経過時間取得
private static TimeSpan GetDueTime(MissionKind kind) => kind switch
{
    MissionKind.A => TimeSpan.FromSeconds(10),
    MissionKind.B => TimeSpan.FromHours(3),
    MissionKind.C => TimeSpan.FromHours(8),
    _ => throw new InvalidOperationException()
};

// ミッションに応じた資源獲得
private void AddResourceAmount(MissionKind kind)
{
    var amount = kind switch
    {
        MissionKind.A => 1,
        MissionKind.B => 1200,
        MissionKind.C => 4000,
        _ => throw new InvalidOperationException()
    };
    Resource += amount;
}

// 種類の入力を受けてミッション開始
public async ValueTask<bool> TryStartAsync(Task<MissionKind> inputTask)
{
    if (Ongoing is not MissionKind.None)
    {
        logger.LogInformation("already have ongoing mission {ongoing}", Ongoing);
        return false;
    }

    Ongoing = await inputTask;

    Timer = timeProvider.CreateTimer(OnFinished, this,
        GetDueTime(Ongoing), Timeout.InfiniteTimeSpan);

    logger.LogInformation("start mission {ongoing}", Ongoing);
    return true;
}

// 終了時コールバック
private static void OnFinished(object? state)
{
    if (state is not FakeSandbox self) return;

    self.AddResourceAmount(self.Ongoing);
    self.logger.LogInformation("changed resource amount to {amount}", self.Resource);
    self.logger.LogInformation("finished mission {ongoing}", self.Ongoing);
    self.Ongoing = MissionKind.None;
    self.Timer?.Dispose();
}

時間経過を確認するタイマーは、TimeProviderクラスのCreateTimerメソッドで生成している。
・TimeProvider.CreateTimer(TimerCallback, Object, TimeSpan, TimeSpan) メソッド (System) | Microsoft Learn

これは、dueTime 後に period 間隔で、state を引数としたコールバックを発火させる。
今回は経過時間後に一度発火すればいいので、period にはInfiniteTimeSpan（周期発火無効）を設定し、各ミッションに応じた必要経過時間を dueTime とした。

さて、必要経過時間が10秒間のミッションAについて、リアル時間を経過させてログを見てみる。

TimeProvider.Systemから標準のTimeProviderインスタンスを得ることができるのでそれを用いる。

using Microsoft.Extensions.Logging; // ※ ロガー用に Microsoft.Extensions.Logging.Console パッケージ使用

static async Task Main(string[] args)
{
    using var lf = LoggerFactory.Create(builder => builder.AddConsole());
    FakeSandbox fs = new(
        lf.CreateLogger<FakeSandbox>(),
        TimeProvider.System);

    var inputTask = Task.Run(() =>
    {
        while(true)
        {
            var input = Console.ReadLine();
            if(Enum.TryParse(typeof(FakeSandbox.MissionKind), input, true, out var kind))
            {
                return (FakeSandbox.MissionKind)kind;
            }
        }
    });
    await fs.TryStartAsync(inputTask);

    Console.ReadKey(); // 雑待機
}

Aを入力から10秒、完了のログが表示された。

ミッションAの必要経過時間は10秒だったけれど、ミッションCとなれば8時間。
Cの確認には、8時間待つしかない……？

`FakeTimeProvider`

時間抽象化を行っていれば、擬似的に時間を経過させることができる。
TimeProviderにFakeTimeProviderを設定し、Advance(TimeSpan)メソッドを利用する。

テストを行ってみる。

using Microsoft.VisualStudio.TestTools.UnitTesting;
using Microsoft.Extensions.Logging.Testing;
using Microsoft.Extensions.Time.Testing;
using FluentAssertions; // 利便のためアサートには FluentAssertions 利用

[TestMethod()]
public async Task TryStartAsyncTest()
{
    var logger = new FakeLogger<FakeSandbox>();
    var timeProvider = new FakeTimeProvider();
    var m = new FakeSandbox(logger, timeProvider);
    int desiredResourceAmount = 4000;

    //
    var isTry1Succeeded = await m.TryStartAsync(Task.FromResult(FakeSandbox.MissionKind.C));
    var isTry2Succeeded = await m.TryStartAsync(Task.FromResult(FakeSandbox.MissionKind.A));
    //
    isTry1Succeeded.Should().Be(true);
    isTry2Succeeded.Should().Be(false);

    //
    timeProvider.Advance(TimeSpan.FromHours(1)); // 1H経過
    timeProvider.Advance(TimeSpan.FromHours(2)); // 1H+2Hで3H経過
    var a0 = m.Resource;
    timeProvider.Advance(TimeSpan.FromHours(5)); // さらに+5Hで8H経過
    var a1 = m.Resource;
    //
    a0.Should().Be(0);
    a1.Should().Be(desiredResourceAmount);
}

FakeTimeProviderにより、数時間先の状態を瞬時にテストすることができた。

なお、FakeTimeProviderには今回使ったAdvance以外に、SetUtcNowメソッド、SetLocalTimeZoneメソッド、AutoAdvanceAmountプロパティといったメンバーも用意されている。

`FakeLogger`

FakeLoggerは、ログをFakeLogRecordとしてメモリ内に保持する。

デバッガを見ると瞭然。

Collector 下にログ情報を保持する FakeLogRecord が並んでいる

終了ログが適切なタイミングで記録されているかの確認をテストに組み込んでみる。

timeProvider.Advance(TimeSpan.FromHours(1)); // 1H
var r1 = logger.LatestRecord;
timeProvider.Advance(TimeSpan.FromHours(2)); // 3H
var a0 = m.Resource;
var r2 = logger.LatestRecord;
timeProvider.Advance(TimeSpan.FromHours(5)); // 8H
var a1 = m.Resource;
var r3 = logger.LatestRecord;
//
a0.Should().Be(0);
a1.Should().Be(desiredResourceAmount);
r1.Message.StartsWith("finished mission").Should().Be(false);
r2.Message.StartsWith("finished mission").Should().Be(false);
r3.Message.StartsWith("finished mission").Should().Be(true);
logger.Collector.Count.Should().Be(4);

終了ログが8時間経過後に記録され、望ましいログ件数となっていることをテストできた。

また、各ログのパラメータが個別に取れるため、それを利用することもできる。

他に、CollectorプロパティからGetSnapshotメソッドでスナップショットを取ることができる。

簡単に触っただけではあるけれど、時間抽象化といった仕組みだけでなく、FakeTimeProviderやFakeLoggerといった具体的な利用ツールが提供されているのはありがたいと感じた。

てくメモ

trivial な notes

【C#】FakeTimeProvider と FakeLogger を試す

今回扱うオブジェクト

`FakeTimeProvider`

`FakeLogger`