From b07771aa8426ffdc4159e343847e95fb726538ac Mon Sep 17 00:00:00 2001
From: Sergey Popov <sergppv@gmail.com>
Date: Thu, 23 Mar 2023 20:10:27 +0300
Subject: [PATCH] log send time in verbose heartbeat messages #6496. (#6548)

---
 .../ClusterHeartbeatReceiverSpec.cs           | 23 ++++++++++++++++++-
 src/core/Akka.Cluster/ClusterHeartbeat.cs     | 15 ++++++------
 2 files changed, 29 insertions(+), 9 deletions(-)

diff --git a/src/core/Akka.Cluster.Tests/ClusterHeartbeatReceiverSpec.cs b/src/core/Akka.Cluster.Tests/ClusterHeartbeatReceiverSpec.cs
index 1bd6446b128..52c707b7af7 100644
--- a/src/core/Akka.Cluster.Tests/ClusterHeartbeatReceiverSpec.cs
+++ b/src/core/Akka.Cluster.Tests/ClusterHeartbeatReceiverSpec.cs
@@ -32,10 +32,12 @@ public ClusterHeartbeatReceiverLegacySpec(ITestOutputHelper output) : base(outpu
     public abstract class ClusterHeartbeatReceiverBase : AkkaSpec
     {
         private static Config Config(bool useLegacyHeartbeat) => $@"
+akka.loglevel=DEBUG
+akka.cluster.debug.verbose-heartbeat-logging = on
 akka.actor.provider = cluster
 akka.cluster.use-legacy-heartbeat-message = {(useLegacyHeartbeat ? "true" : "false")}
 ";
-
+        
         protected ClusterHeartbeatReceiverBase(ITestOutputHelper output, bool useLegacyHeartbeat)
             : base(Config(useLegacyHeartbeat), output)
         {
@@ -49,5 +51,24 @@ public async Task ClusterHeartbeatReceiver_should_respond_to_heartbeats_with_sam
             heartbeater.Tell(new Heartbeat(Cluster.Get(Sys).SelfAddress, 1, 2));
             await ExpectMsgAsync<HeartbeatRsp>(new HeartbeatRsp(Cluster.Get(Sys).SelfUniqueAddress, 1, 2));
         }
+        
+        [Fact]
+        public async Task ClusterHeartbeatReceiver_should_write_correct_debug_messages_on_heartbeat()
+        {
+            var heartbeater = Sys.ActorOf(ClusterHeartbeatReceiver.Props(Cluster.Get(Sys)));
+
+            EventFilter.Debug(contains: "- Sequence number [2]")
+                .ExpectOne(() => heartbeater.Tell(new Heartbeat(Cluster.Get(Sys).SelfAddress, 2, 3)));
+        }
+        
+        [Fact]
+        public async Task ClusterHeartbeatSender_should_write_correct_debug_messages_on_heartbeat_rsp()
+        {
+            var heartbeater = Sys.ActorOf(Props.Create(() => new ClusterHeartbeatSender(Cluster.Get(Sys))));
+            heartbeater.Tell(new ClusterEvent.CurrentClusterState());
+            
+            EventFilter.Debug(contains: "- Sequence number [2] - Creation time [3]")
+                .ExpectOne(() => heartbeater.Tell(new HeartbeatRsp(Cluster.Get(Sys).SelfUniqueAddress, 2, 3)));
+        }
     }
 }
diff --git a/src/core/Akka.Cluster/ClusterHeartbeat.cs b/src/core/Akka.Cluster/ClusterHeartbeat.cs
index 0c099803925..7413c3a6867 100644
--- a/src/core/Akka.Cluster/ClusterHeartbeat.cs
+++ b/src/core/Akka.Cluster/ClusterHeartbeat.cs
@@ -8,6 +8,7 @@
 using System;
 using System.Collections.Generic;
 using System.Collections.Immutable;
+using System.Globalization;
 using System.Linq;
 using Akka.Actor;
 using Akka.Event;
@@ -43,8 +44,7 @@ protected override void OnReceive(object message)
             switch (message)
             {
                 case ClusterHeartbeatSender.Heartbeat hb:
-                    // TODO log the sequence nr once serializer is enabled
-                    if(VerboseHeartbeat) _cluster.CurrentInfoLogger.LogDebug("Heartbeat from [{0}]", hb.From);
+                    if (VerboseHeartbeat) _cluster.CurrentInfoLogger.LogDebug($"Heartbeat from [{hb.From}] - Sequence number [{hb.SequenceNr.ToString(CultureInfo.InvariantCulture)}]");
                     Sender.Tell(new ClusterHeartbeatSender.HeartbeatRsp(_cluster.SelfUniqueAddress,
                         hb.SequenceNr, hb.CreationTimeNanos));
                     break;
@@ -58,7 +58,6 @@ public static Props Props(Cluster getCluster)
         {
             return Akka.Actor.Props.Create(() => new ClusterHeartbeatReceiver(getCluster));
         }
-
     }
 
     /// <summary>
@@ -248,7 +247,8 @@ private void CheckTickInterval()
                     "Previous heartbeat was sent [{1}] ms ago, expected interval is [{2}] ms. This may cause failure detection " +
                     "to mark members as unreachable. The reason can be thread starvation, e.g. by running blocking tasks on the " +
                     "default dispatcher, CPU overload, or GC.",
-                    _cluster.SelfAddress, (now - _tickTimestamp).TotalMilliseconds, _cluster.Settings.HeartbeatInterval.TotalMilliseconds);
+                    _cluster.SelfAddress, (now - _tickTimestamp).TotalMilliseconds.ToString(CultureInfo.InvariantCulture), 
+                    _cluster.Settings.HeartbeatInterval.TotalMilliseconds.ToString(CultureInfo.InvariantCulture));
             }
             
             _tickTimestamp = DateTime.UtcNow;
@@ -258,8 +258,8 @@ private void DoHeartbeatRsp(HeartbeatRsp rsp)
         {
             if (_cluster.Settings.VerboseHeartbeatLogging)
             {
-                // TODO: log response time and validate sequence nrs once serialisation of sendTime is released
-                _log.Debug("Cluster Node [{0}] - Heartbeat response from [{1}]", _cluster.SelfAddress, rsp.From.Address);
+                _log.Debug("Cluster Node [{0}] - Heartbeat response from [{1}] - Sequence number [{2}] - Creation time [{3}]", _cluster.SelfAddress, rsp.From.Address,
+                    rsp.SequenceNr.ToString(CultureInfo.InvariantCulture), rsp.CreationTimeNanos.ToString(CultureInfo.InvariantCulture));
             }
             _state = _state.HeartbeatRsp(rsp.From);
         }
@@ -768,5 +768,4 @@ public int Compare(UniqueAddress x, UniqueAddress y)
         }
         #endregion
     }
-}
-
+}
\ No newline at end of file