Suppress extremely chatty TimerScheduler debug messages (akkadotnet#7102

)

* Suppress extremely chatty TimerScheduler debug messages

* Move configuration to Settings class.

* Update API approval list

src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt

@@ -1712,6 +1712,7 @@ namespace Akka.Actor
         public bool DebugEventStream { get; }
         public bool DebugLifecycle { get; }
         public bool DebugRouterMisconfiguration { get; }
+        public bool DebugTimerScheduler { get; }
         public bool DebugUnhandledMessage { get; }
         public int DefaultVirtualNodesFactor { get; }
         public bool EmitActorTelemetry { get; }

src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt

@@ -1710,6 +1710,7 @@ namespace Akka.Actor
         public bool DebugEventStream { get; }
         public bool DebugLifecycle { get; }
         public bool DebugRouterMisconfiguration { get; }
+        public bool DebugTimerScheduler { get; }
         public bool DebugUnhandledMessage { get; }
         public int DefaultVirtualNodesFactor { get; }
         public bool EmitActorTelemetry { get; }

src/core/Akka.Tests/Actor/Scheduler/TimerSchedulerDebugSpec.cs

@@ -0,0 +1,103 @@
+// -----------------------------------------------------------------------
+//  <copyright file="TimerSchedulerSettings.cs" company="Akka.NET Project">
+//      Copyright (C) 2013-2024 .NET Foundation <https://github.com/akkadotnet/akka.net>
+//  </copyright>
+// -----------------------------------------------------------------------
+
+using System;
+using System.Diagnostics;
+using System.Threading;
+using System.Threading.Tasks;
+using Akka.Actor;
+using Akka.Configuration;
+using Akka.TestKit;
+using FluentAssertions.Extensions;
+using Xunit;
+using Xunit.Abstractions;
+using Debug = Akka.Event.Debug;
+
+namespace Akka.Tests.Actor.Scheduler;
+
+internal sealed class TimerTestActor: UntypedActor, IWithTimers
+{
+    protected override void OnReceive(object message)
+    {
+        switch (message)
+        {
+            case "startTimer":
+                Timers.StartSingleTimer("test", "test", 1.Seconds());
+                break;
+            case "test":
+                break;
+            default:
+                Unhandled(message);
+                break;
+        }
+    }
+
+    public ITimerScheduler Timers { get; set; }
+}
+
+public class TimerSchedulerDebug: TestKit.Xunit2.TestKit
+{
+    public TimerSchedulerDebug(ITestOutputHelper output) : base("akka.actor.debug.log-timers = true", null, output)
+    {
+    }
+
+    [Fact]
+    public void ShouldHonorDebugFlag()
+    {
+        Sys.EventStream.Subscribe(TestActor, typeof(Debug));
+        var timerActor = Sys.ActorOf<TimerTestActor>();
+        timerActor.Tell("startTimer");
+
+        FishForMessage(msg => msg is Debug dbg && dbg.Message.ToString()!.StartsWith("Start timer ["));
+    }
+}
+
+public class TimerSchedulerSuppressDebug: TestKit.Xunit2.TestKit
+{
+    public TimerSchedulerSuppressDebug(ITestOutputHelper output) : base("akka.actor.debug.log-timers = false", null, output)
+    {
+    }
+
+    [Fact]
+    public async Task ShouldHonorSuppressDebugFlag()
+    {
+        Sys.EventStream.Subscribe(TestActor, typeof(Debug));
+        var timerActor = Sys.ActorOf<TimerTestActor>();
+        timerActor.Tell("startTimer");
+
+        await ExpectNoMsgAsync(
+            predicate: msg => msg is Debug dbg && dbg.Message.ToString()!.StartsWith("Start timer ["), 
+            timeout: 1.Seconds());
+    }
+
+    private async Task ExpectNoMsgAsync(
+        Predicate<object> predicate, 
+        TimeSpan? timeout = null,
+        CancellationToken cancellationToken = default)
+    {
+        var deadline = DateTime.Now + (timeout ?? 3.Seconds());
+        var offset = 0.Seconds();
+
+        while (DateTime.Now < deadline)
+        {
+            var stopwatch = Stopwatch.StartNew();
+            var (success, envelope) = await TryReceiveOneAsync(timeout - offset, cancellationToken);
+            stopwatch.Stop();
+            offset += stopwatch.Elapsed;
+
+            if(!success)
+                continue;
+
+            var message = envelope.Message;
+            if (!predicate(message)) 
+                continue;
+
+            Assertions.Fail("Expected no message to match predicate, received {0} instead.", message);
+            break;
+        }
+    }
+
+}

src/core/Akka/Actor/Scheduler/TimerScheduler.cs

@@ -78,10 +78,14 @@ public TimerMsgNotInfluenceReceiveTimeout(object key, int generation, TimerSched
         private readonly IActorContext _ctx;
         private readonly Dictionary<object, Timer> _timers = new();
         private readonly AtomicCounter _timerGen = new(0);
+        private readonly bool _logDebug;
+        private readonly ILoggingAdapter _log;
 
         public TimerScheduler(IActorContext ctx)
         {
             _ctx = ctx;
+            _log = _ctx.System.Log;
+            _logDebug = ctx.System.Settings.DebugTimerScheduler;
         }
 
         /// <summary>
@@ -167,15 +171,17 @@ public void Cancel(object key)
         /// </summary>
         public void CancelAll()
         {
-            _ctx.System.Log.Debug("Cancel all timers");
+            if(_logDebug)
+                _log.Debug("Cancel all timers");
             foreach (var timer in _timers)
                 timer.Value.Task.Cancel();
             _timers.Clear();
         }
 
         private void CancelTimer(Timer timer)
         {
-            _ctx.System.Log.Debug("Cancel timer [{0}] with generation [{1}]", timer.Key, timer.Generation);
+            if(_logDebug)
+                _log.Debug("Cancel timer [{0}] with generation [{1}]", timer.Key, timer.Generation);
             timer.Task.Cancel();
             _timers.Remove(timer.Key);
         }
@@ -201,7 +207,9 @@ private void StartTimer(object key, object msg, TimeSpan timeout, TimeSpan initi
                 task = _ctx.System.Scheduler.ScheduleTellOnceCancelable(timeout, _ctx.Self, timerMsg, ActorRefs.NoSender);
 
             var nextTimer = new Timer(key, msg, repeat, nextGen, task);
-            _ctx.System.Log.Debug("Start timer [{0}] with generation [{1}]", key, nextGen);
+
+            if(_logDebug)
+                _log.Debug("Start timer [{0}] with generation [{1}]", key, nextGen);
             _timers[key] = nextTimer;
         }
 
@@ -210,13 +218,15 @@ public object InterceptTimerMsg(ILoggingAdapter log, ITimerMsg timerMsg)
             if (!_timers.TryGetValue(timerMsg.Key, out var timer))
             {
                 // it was from canceled timer that was already enqueued in mailbox
-                log.Debug("Received timer [{0}] that has been removed, discarding", timerMsg.Key);
+                if(_logDebug)
+                    log.Debug("Received timer [{0}] that has been removed, discarding", timerMsg.Key);
                 return null; // message should be ignored
             }
             if (!ReferenceEquals(timerMsg.Owner, this))
             {
                 // after restart, it was from an old instance that was enqueued in mailbox before canceled
-                log.Debug("Received timer [{0}] from old restarted instance, discarding", timerMsg.Key);
+                if(_logDebug)
+                    log.Debug("Received timer [{0}] from old restarted instance, discarding", timerMsg.Key);
                 return null; // message should be ignored
             }
 
@@ -229,11 +239,12 @@ public object InterceptTimerMsg(ILoggingAdapter log, ITimerMsg timerMsg)
             }
 
             // it was from an old timer that was enqueued in mailbox before canceled
-            log.Debug(
-                "Received timer [{0}] from old generation [{1}], expected generation [{2}], discarding",
-                timerMsg.Key,
-                timerMsg.Generation,
-                timer.Generation);
+            if(_logDebug)
+                log.Debug(
+                    "Received timer [{0}] from old generation [{1}], expected generation [{2}], discarding",
+                    timerMsg.Key,
+                    timerMsg.Generation,
+                    timer.Generation);
             return null; // message should be ignored
         }
     }

src/core/Akka/Actor/Settings.cs

@@ -205,6 +205,7 @@ public Settings(ActorSystem system, Config config, ActorSystemSetup setup)
             DebugEventStream = Config.GetBoolean("akka.actor.debug.event-stream", false);
             DebugUnhandledMessage = Config.GetBoolean("akka.actor.debug.unhandled", false);
             DebugRouterMisconfiguration = Config.GetBoolean("akka.actor.debug.router-misconfiguration", false);
+            DebugTimerScheduler = Config.GetBoolean("akka.actor.debug.log-timers");
             Home = Config.GetString("akka.home", "");
             DefaultVirtualNodesFactor = Config.GetInt("akka.actor.deployment.default.virtual-nodes-factor", 0);
 
@@ -425,6 +426,11 @@ public Settings(ActorSystem system, Config config, ActorSystemSetup setup)
         /// </summary>
         /// <value><c>true</c> if [debug lifecycle]; otherwise, <c>false</c>.</value>
         public bool DebugLifecycle { get; private set; }
+
+        /// <summary>
+        ///     Should TimerScheduler emit debug logs
+        /// </summary>
+        public bool DebugTimerScheduler { get; private set; }
 
         /// <summary>
         /// TBD

src/core/Akka/Configuration/akka.conf

@@ -514,6 +514,9 @@ akka {
 
       # enable WARN logging of misconfigured routers
       router-misconfiguration = off
+
+      # enable TimerScheduler debug logging
+      log-timers = false
     }
 
     # Entries for pluggable serializers and their bindings.