[Microsoft.Extensions.TimeProvider.Testing] FakeTimeProvider does not simulate timers correctly, misses executions

[bara-pweber]

Description

I am working with a non-periodic Timer that re-schedules itself with the ITimer.Change method. I noticed that FakeTimeProvider.Advance only ever executes the timer once, even if I provide a TimeSpan that covers multiple executions.

Reproduction Steps

public class TimerBugRepro
{
    [Fact]
    public void TestWithSystemTime() // Works
    {
        Assert.Equal(2, RunTestWithTimeProvider(TimeProvider.System, () => Thread.Sleep(TimeSpan.FromSeconds(3))));
    }

    [Fact]
    public void TestWithFakeTime() // Fails
    {
        var fakeTime = new FakeTimeProvider();
        Assert.Equal(2, RunTestWithTimeProvider(fakeTime, () => fakeTime.Advance(TimeSpan.FromSeconds(3))));
    }

    private int RunTestWithTimeProvider(TimeProvider timeProvider, Action sleepAction)
    {
        int count = 0;
        ITimer timer = null;
        timer = timeProvider.CreateTimer(
            _ =>
            {
                Interlocked.Increment(ref count);
                timer.Change(TimeSpan.FromSeconds(2), Timeout.InfiniteTimeSpan);
            },
            null,
            Timeout.InfiniteTimeSpan,
            Timeout.InfiniteTimeSpan);

        timer.Change(TimeSpan.FromMilliseconds(1), Timeout.InfiniteTimeSpan); // Both tests work for TimeSpan.Zero

        sleepAction();

        return count;
    }
}

Expected behavior

The FakeTimeProvider.Advance should correctly simulate the behavior for TimeProvider.System + Thread.Sleep.

Actual behavior

The Fake-Timer does not get re-sheduled correctly.

Regression?

No response

Known Workarounds

No response

Configuration

.NET SDK version: 9.0.100
TargetFramework: net8.0
Microsoft.Extensions.TimeProvider.Testing version: 9.0.0
OS: Windows 10 10.0.19045

Other information

No response

[wjgerritsen-0001]

I have made a solution proposal for this problem in #5441, the StepWiseAdvanceTimer will execute all intermediate executions. The current Advance method will just advance the time in one step to the target time, and then execute all pending timers. Reschedules will always be registered after the target time.

[johncrim]

A critical part of this bug is that FakeTimeProvider provides the wrong time in the Timer callback function - so if any TimeProvider methods are used transitively from the Timer callback, they don't return times that are consistent with real time behavior. Eg this fails:

public class FakeTimeProviderTimerBug
{

    [Fact]
    public void TimeShouldMatchExpected_InTimerCallbacks()
    {
        var time = new FakeTimeProvider();
        var timerTimes = new List<DateTimeOffset>();

        var timer = time.CreateTimer((_) => timerTimes.Add(time.GetUtcNow()),
                                     null,
                                     TimeSpan.FromMinutes(1),
                                     TimeSpan.FromMinutes(1));

        var startTime = time.GetUtcNow();
        time.Advance(TimeSpan.FromMinutes(5));

        Assert.Collection(timerTimes,
                          (t) => Assert.Equal(startTime.AddMinutes(1), t),
                          (t) => Assert.Equal(startTime.AddMinutes(2), t),
                          (t) => Assert.Equal(startTime.AddMinutes(3), t),
                          (t) => Assert.Equal(startTime.AddMinutes(4), t),
                          (t) => Assert.Equal(startTime.AddMinutes(5), t));
    }    

}

It fails with:

Assert.Collection() Failure: Item comparison failure
             ↓ (pos 0)
Collection: [2000-01-01T00:05:00.0000000+00:00, 2000-01-01T00:05:00.0000000+00:00, 2000-01-01T00:05:00.0000000+00:00, 2000-01-01T00:05:00.0000000+00:00, 2000-01-01T00:05:00.0000000+00:00]
Error:      Assert.Equal() Failure: Values differ
            Expected: 2000-01-01T00:01:00.0000000+00:00
            Actual:   2000-01-01T00:05:00.0000000+00:00

It's good that the Timer is called the right number of times, but the time needs to reflect when the timer is called.