Merge pull request #18 from thedmi/fix/no-early-timers

Fix: Don't fire timers early

sources/Capsule.Core/DefaultSynchronizerFactory.cs

@@ -1,9 +1,21 @@
-namespace Capsule;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+
+namespace Capsule;
 
 public class DefaultSynchronizerFactory(
     ICapsuleQueueFactory queueFactory,
-    ICapsuleInvocationLoopFactory invocationLoopFactory) : ICapsuleSynchronizerFactory
+    ICapsuleInvocationLoopFactory invocationLoopFactory,
+    ILoggerFactory loggerFactory) : ICapsuleSynchronizerFactory
 {
+    [Obsolete("Use overload with logger factory parameter instead")]
+    public DefaultSynchronizerFactory(
+        ICapsuleQueueFactory queueFactory,
+        ICapsuleInvocationLoopFactory invocationLoopFactory) : this(
+        queueFactory,
+        invocationLoopFactory,
+        new NullLoggerFactory()) { }
+
     public ICapsuleSynchronizer Create(object capsuleImpl, ICapsuleHost host)
     {
         var capsuleType = capsuleImpl.GetType();
@@ -20,12 +32,12 @@ public ICapsuleSynchronizer Create(object capsuleImpl, ICapsuleHost host)
         return synchronizer;
     }
 
-    private static void ApplyFeatures(object capsuleImpl, CapsuleSynchronizer synchronizer)
+    private void ApplyFeatures(object capsuleImpl, CapsuleSynchronizer synchronizer)
     {
         // If the implementation uses timers, inject the timer service
         if (capsuleImpl is CapsuleFeature.ITimers t)
         {
-            t.Timers = new TimerService(synchronizer);
+            t.Timers = new TimerService(synchronizer, loggerFactory.CreateLogger<TimerService>());
         }
 
         // If the implementation requires initialization, ensure this is the first call in the invocation queue

sources/Capsule.Core/TimerService.cs

@@ -1,4 +1,6 @@
-namespace Capsule;
+using Microsoft.Extensions.Logging;
+
+namespace Capsule;
 
 /// <summary>
 /// A timer service for use in capsule implementations. Typically injected through <see cref="CapsuleFeature.ITimers"/>.
@@ -11,9 +13,10 @@
 /// <param name="delayProvider">Optional delay provider for testing. Should be left null in non-test contexts.</param>
 internal class TimerService(
     ICapsuleSynchronizer synchronizer,
+    ILogger<TimerService> logger,
     Func<TimeSpan, CancellationToken, Task>? delayProvider = null) : ITimerService
 {
-    private readonly Func<TimeSpan, CancellationToken, Task> _delayProvider = delayProvider ?? Task.Delay;
+    private readonly Func<TimeSpan, CancellationToken, Task> _delayProvider = delayProvider ?? DefaultDelayImpl;
 
     // Internal for unit test access
     internal readonly TaskCollection TimerTasks = [];
@@ -36,6 +39,11 @@ public TimerReference StartSingleShot(TimeSpan timeout, Func<Task> callback)
         TimerTasks.Add(timerTask);
         Timers.Add(timerReference);
 
+        logger.LogDebug(
+            "Timer with timeout {Timeout} started & registered, {TimerCount} timers are now pending",
+            timeout,
+            Timers.Count);
+
         return timerReference;
 
         async Task EnqueueCallbackDelayed()
@@ -44,11 +52,19 @@ async Task EnqueueCallbackDelayed()
             {
                 await _delayProvider(timeout, cts.Token).ConfigureAwait(false);
 
-                if (!cts.IsCancellationRequested)
+                if (cts.IsCancellationRequested)
+                {
+                    logger.LogDebug(
+                        "Timer with timeout {Timeout} was cancelled and the associated callback dropped",
+                        timeout);
+                }
+                else
                 {
-                    // We're in a "free floating" task, so awaiting the result doesn't make sense here. Instead,
-                    // we ensure exceptions are handled by the invocation loop.
                     await synchronizer.EnqueueReturn(callback).ConfigureAwait(false);
+
+                    logger.LogDebug(
+                        "Timer with timeout {Timeout} has fired and its callback enqueued",
+                        timeout);
                 }
             }
             catch (OperationCanceledException) { }
@@ -77,4 +93,11 @@ private async Task ClearElapsedTimersAsync()
 
         Timers.RemoveAll(t => completed.Contains(t.TimerTask));
     }
+
+    /// <summary>
+    /// The default delay implementation uses Task.Delay but adds 1ms to the delay. The added delay ensures that timers
+    /// never fire early (under normal circumstances).
+    /// </summary>
+    private static async Task DefaultDelayImpl(TimeSpan delay, CancellationToken cancellationToken) =>
+        await Task.Delay(delay + TimeSpan.FromMilliseconds(1), cancellationToken).ConfigureAwait(false);
 }

sources/Capsule.Test/AutomatedTests/UnitTests/TestRuntime.cs

@@ -13,7 +13,7 @@ public static CapsuleRuntimeContext Create()
             host,
             new DefaultSynchronizerFactory(
                 new DefaultQueueFactory(),
-                new DefaultInvocationLoopFactory(
-                    loggerFactory.CreateLogger<ICapsuleInvocationLoop>())));
+                new DefaultInvocationLoopFactory(loggerFactory.CreateLogger<ICapsuleInvocationLoop>()),
+                loggerFactory));
     }
 }

sources/Capsule.Test/AutomatedTests/UnitTests/TimerServiceTest.cs

@@ -1,4 +1,12 @@
-using Shouldly;
+using System.Diagnostics;
+
+using Capsule.Testing;
+
+using MathNet.Numerics.Statistics;
+
+using Microsoft.Extensions.Logging.Abstractions;
+
+using Shouldly;
 
 namespace Capsule.Test.AutomatedTests.UnitTests;
 
@@ -8,13 +16,14 @@ public class TimerServiceTest
     public async Task Timers_enqueue_the_callback_after_the_timeout_has_elapsed_and_timers_are_cleaned_up()
     {
         var taskCompletionSource = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
-        var synchronizer = new FakeSynchronizer();
+        var synchronizer = new ManualSynchronizer();
 
         var timeSpan = TimeSpan.Zero;
         var cancellationToken = new CancellationToken();
 
         var sut = new TimerService(
             synchronizer,
+            new NullLogger<TimerService>(),
             (ts, ct) =>
             {
                 timeSpan = ts;
@@ -58,10 +67,11 @@ public async Task Timers_enqueue_the_callback_after_the_timeout_has_elapsed_and_
     public async Task Cleanup_is_triggered_even_when_timers_are_cancelled()
     {
         var taskCompletionSource = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
-        var synchronizer = new FakeSynchronizer();
+        var synchronizer = new ManualSynchronizer();
 
         var sut = new TimerService(
             synchronizer,
+            new NullLogger<TimerService>(),
             (_, ct) =>
             {
                 ct.Register((_, t) => taskCompletionSource.SetCanceled(t), null);
@@ -98,7 +108,45 @@ public async Task Cleanup_is_triggered_even_when_timers_are_cancelled()
         sut.Timers.ShouldBeEmpty();
     }
 
-    private class FakeSynchronizer : ICapsuleSynchronizer
+    [Test]
+    public async Task Timers_dont_fire_early()
+    {
+        const int numberOfRuns = 200;
+
+        var synchronizer = new FakeSynchronizer();
+        var sut = new TimerService(synchronizer, new NullLogger<TimerService>());
+
+        var stopwatch = new Stopwatch();
+
+        var runs = new List<double>(numberOfRuns);
+
+        for (var i = 0; i < numberOfRuns; i++)
+        {
+            stopwatch.Reset();
+            stopwatch.Start();
+
+            var timerRef = sut.StartSingleShot(
+                TimeSpan.FromMilliseconds(14),
+                () =>
+                {
+                    var elapsed = stopwatch.Elapsed;
+                    elapsed.ShouldBeGreaterThan(TimeSpan.FromMilliseconds(5));
+                    runs.Add(elapsed.TotalSeconds);
+                    return Task.CompletedTask;
+                });
+
+            await timerRef.TimerTask;
+        }
+
+        Console.WriteLine("Mean: " + runs.Mean());
+        Console.WriteLine("StdDev: " + runs.StandardDeviation());
+        Console.WriteLine("Min: " + runs.Min());
+        Console.WriteLine("Max: " + runs.Max());
+
+        runs.Count.ShouldBe(numberOfRuns);
+    }
+
+    private class ManualSynchronizer : ICapsuleSynchronizer
     {
         public Queue<Func<Task>> InvocationQueue { get; } = new();
 

sources/Capsule.Test/Capsule.Test.csproj

@@ -25,6 +25,7 @@
     <PackageReference Include="CommunityToolkit.Diagnostics" Version="8.2.2" />
     <PackageReference Include="Extensions.Logging.NUnit" Version="1.0.1" />
     <PackageReference Include="JunitXml.TestLogger" Version="3.1.12" />
+    <PackageReference Include="MathNet.Numerics" Version="5.0.0" />
     <PackageReference Include="Microsoft.Extensions.Hosting" Version="6.0.1" />
     <PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.0" />
     <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="8.0.0" />