Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log send time and sqNbr in verbose cluster heartbeat messages #6496. #6548

Merged
merged 1 commit into from
Mar 23, 2023
Merged

Log send time and sqNbr in verbose cluster heartbeat messages #6496. #6548

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 22 additions & 1 deletion src/core/Akka.Cluster.Tests/ClusterHeartbeatReceiverSpec.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand All @@ -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)));
}
}
}
15 changes: 7 additions & 8 deletions src/core/Akka.Cluster/ClusterHeartbeat.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand All @@ -58,7 +58,6 @@ public static Props Props(Cluster getCluster)
{
return Akka.Actor.Props.Create(() => new ClusterHeartbeatReceiver(getCluster));
}

}

/// <summary>
Expand Down Expand Up @@ -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),
Copy link
Contributor Author

@F0b0s F0b0s Mar 23, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Usage of CultureInfo.InvariantCulture here may be breaking changes, because without ToString logger calls object.ToString() which should use current culture.
Not sure do we need to use InvariantCulture here.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

InvariantCulture is the right call - won't be a breaking change for anyone (we don't consider updates to the content of log messages to be breaking changes.)

_cluster.Settings.HeartbeatInterval.TotalMilliseconds.ToString(CultureInfo.InvariantCulture));
}

_tickTimestamp = DateTime.UtcNow;
Expand All @@ -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));
Aaronontheweb marked this conversation as resolved.
Show resolved Hide resolved
}
_state = _state.HeartbeatRsp(rsp.From);
}
Expand Down Expand Up @@ -768,5 +768,4 @@ public int Compare(UniqueAddress x, UniqueAddress y)
}
#endregion
}
}

}