Cluster event listener that logs all events (#4502)

docs/articles/clustering/cluster-configuration.md

@@ -33,6 +33,20 @@ akka {
 }
 ```
 
+### Cluster Info Logging
+
+You can silence the logging of cluster events at info level with configuration property:
+
+```
+akka.cluster.log-info = off
+```
+
+You can enable verbose logging of cluster events at info level, e.g. for temporary troubleshooting, with configuration property:
+
+```
+akka.cluster.log-info-verbose = on
+```
+
 ## Specifying Minimum Cluster Sizes
 One feature of Akka.Cluster that can be useful in a number of scenarios is the ability to specify a minimum cluster size, i.e. "this cluster must have at least 3 nodes present before it can be considered 'up'."
 

src/core/Akka.API.Tests/CoreAPISpec.ApproveCluster.approved.txt

@@ -197,6 +197,7 @@ namespace Akka.Cluster
         public System.TimeSpan HeartbeatInterval { get; }
         public System.TimeSpan LeaderActionsInterval { get; }
         public bool LogInfo { get; }
+        public bool LogInfoVerbose { get; }
         public int MinNrOfMembers { get; }
         public System.Collections.Immutable.ImmutableDictionary<string, int> MinNrOfMembersOfRole { get; }
         public int MonitoredByNrOfMembers { get; }

src/core/Akka.Cluster.Tests/ClusterLogSpec.cs

@@ -0,0 +1,126 @@
+//-----------------------------------------------------------------------
+// <copyright file="ClusterSpec.cs" company="Akka.NET Project">
+//     Copyright (C) 2009-2020 Lightbend Inc. <http://www.lightbend.com>
+//     Copyright (C) 2013-2020 .NET Foundation <https://github.com/akkadotnet/akka.net>
+// </copyright>
+//-----------------------------------------------------------------------
+
+using System.Linq;
+using Akka.Actor;
+using Akka.Configuration;
+using Akka.TestKit;
+using Akka.Util.Internal;
+using Xunit;
+using Xunit.Abstractions;
+using Xunit.Sdk;
+
+namespace Akka.Cluster.Tests
+{
+    public abstract class ClusterLogSpec : AkkaSpec
+    {
+        public const string Config = @"    
+            akka.cluster {
+              auto-down-unreachable-after = 0s
+              publish-stats-interval = 0s # always, when it happens
+              run-coordinated-shutdown-when-down = off
+            }
+            akka.actor.provider = ""cluster""
+            akka.remote.log-remote-lifecycle-events = off
+            akka.remote.dot-netty.tcp.port = 0
+            akka.loglevel = ""INFO""
+            akka.loggers = [""Akka.TestKit.TestEventListener, Akka.TestKit""]";
+
+        protected const string upLogMessage = " - event MemberUp";
+        protected const string downLogMessage = " - event MemberDowned";
+        protected readonly Address _selfAddress;
+        protected readonly Cluster _cluster;
+
+        internal ClusterReadView ClusterView { get { return _cluster.ReadView; } }
+
+        protected ClusterLogSpec(ITestOutputHelper output, Config config = null)
+            : base(config ?? Config, output)
+        {
+            _selfAddress = Sys.AsInstanceOf<ExtendedActorSystem>().Provider.DefaultAddress;
+            _cluster = Cluster.Get(Sys);
+        }
+
+        protected void AwaitUp()
+        {
+            AwaitCondition(() => ClusterView.IsSingletonCluster);
+            ClusterView.Self.Address.ShouldBe(_selfAddress);
+            ClusterView.Members.Select(m => m.Address).ShouldBe(new Address[] { _selfAddress });
+            AwaitAssert(() => ClusterView.Status.ShouldBe(MemberStatus.Up));
+        }
+        /// <summary>
+        /// The expected log info pattern to intercept after a <see cref="Cluster.Join(Address)"/>.
+        /// </summary>
+        protected void Join(string expected)
+        {
+            EventFilter
+                .Info(contains: expected)
+                .ExpectOne(() => _cluster.Join(_selfAddress));
+        }
+
+        /// <summary>
+        /// The expected log info pattern to intercept after a <see cref="Cluster.Down(Address)"/>.
+        /// </summary>
+        /// <param name="expected"></param>
+        protected void Down(string expected)
+        {
+            EventFilter
+                .Info(contains: expected)
+                .ExpectOne(() => _cluster.Down(_selfAddress));
+        }
+    }
+
+    public class ClusterLogDefaultSpec : ClusterLogSpec
+    {
+        public ClusterLogDefaultSpec(ITestOutputHelper output)
+            : base(output)
+        { }
+
+        [Fact]
+        public void A_cluster_must_log_a_message_when_becoming_and_stopping_being_a_leader()
+        {
+            _cluster.Settings.LogInfo.ShouldBeTrue();
+            _cluster.Settings.LogInfoVerbose.ShouldBeFalse();
+            Join("is the new leader");
+            AwaitUp();
+            Down("is no longer leader");
+        }
+    }
+
+    public class ClusterLogVerboseDefaultSpec : ClusterLogSpec
+    {
+        public ClusterLogVerboseDefaultSpec(ITestOutputHelper output)
+            : base(output)
+        { }
+
+        [Fact]
+        public void A_cluster_must_not_log_verbose_cluster_events_by_default()
+        {
+            _cluster.Settings.LogInfoVerbose.ShouldBeFalse();
+            Intercept<TrueException>(() => Join(upLogMessage));
+            AwaitUp();
+            Intercept<TrueException>(() => Down(downLogMessage));
+        }
+    }
+
+    public class ClusterLogVerboseEnabledSpec : ClusterLogSpec
+    {
+        public ClusterLogVerboseEnabledSpec(ITestOutputHelper output)
+            : base(output, ConfigurationFactory
+                  .ParseString("akka.cluster.log-info-verbose = on")
+                  .WithFallback(ConfigurationFactory.ParseString(Config)))
+        { }
+
+        [Fact]
+        public void A_cluster_must_log_verbose_cluster_events_when_log_info_verbose_is_on()
+        {
+            _cluster.Settings.LogInfoVerbose.ShouldBeTrue();
+            Join(upLogMessage);
+            AwaitUp();
+            Down(downLogMessage);
+        }
+    }
+}

src/core/Akka.Cluster/ClusterDaemon.cs

@@ -993,6 +993,8 @@ namespace Akka.Cluster
             return node.Address + "-" + node.Uid;
         }
 
+        private bool _isCurrentlyLeader;
+
         // note that self is not initially member,
         // and the SendGossip is not versioned for this 'Node' yet
         private Gossip _latestGossip = Gossip.Empty;
@@ -2125,6 +2127,11 @@ namespace Akka.Cluster
             if (_latestGossip.IsLeader(SelfUniqueAddress, SelfUniqueAddress))
             {
                 // only run the leader actions if we are the LEADER
+                if (!_isCurrentlyLeader)
+                {
+                    _cluster.LogInfo("is the new leader among reachable nodes (more leaders may exist)");
+                    _isCurrentlyLeader = true;
+                }
                 const int firstNotice = 20;
                 const int periodicNotice = 60;
                 if (_latestGossip.Convergence(SelfUniqueAddress, _exitingConfirmed))
@@ -2154,6 +2161,11 @@ namespace Akka.Cluster
                     }
                 }
             }
+            else if (_isCurrentlyLeader)
+            {
+                _cluster.LogInfo("is no longer leader");
+                _isCurrentlyLeader = false;
+            }
 
             CleanupExitingConfirmed();
             ShutdownSelfWhenDown();

src/core/Akka.Cluster/ClusterReadView.cs

@@ -153,6 +153,12 @@ namespace Akka.Cluster
                             readView._latestStats = stats;
                         })
                         .With<ClusterEvent.ClusterShuttingDown>(_ => { });
+
+                    // once captured, optional verbose logging of event
+                    if (!(clusterDomainEvent is ClusterEvent.SeenChanged) && _cluster.Settings.LogInfoVerbose)
+                    {
+                        _cluster.LogInfo("event {0}", clusterDomainEvent.GetType().Name);
+                    }
                 });
 
                 Receive<ClusterEvent.CurrentClusterState>(state =>
@@ -164,7 +170,7 @@ namespace Akka.Cluster
             protected override void PreStart()
             {
                 //subscribe to all cluster domain events
-                _cluster.Subscribe(Self, new []{ typeof(ClusterEvent.IClusterDomainEvent) });
+                _cluster.Subscribe(Self, new[] { typeof(ClusterEvent.IClusterDomainEvent) });
             }
 
             protected override void PostStop()

src/core/Akka.Cluster/ClusterSettings.cs

@@ -35,7 +35,8 @@ namespace Akka.Cluster
             if (clusterConfig.IsNullOrEmpty())
                 throw ConfigurationException.NullOrEmptyConfig<ClusterSettings>("akka.cluster");
 
-            LogInfo = clusterConfig.GetBoolean("log-info", false);
+            LogInfoVerbose = clusterConfig.GetBoolean("log-info-verbose", false);
+            LogInfo = LogInfoVerbose || clusterConfig.GetBoolean("log-info", false);
             _failureDetectorConfig = clusterConfig.GetConfig("failure-detector");
             FailureDetectorImplementationClass = _failureDetectorConfig.GetString("implementation-class", null);
             HeartbeatInterval = _failureDetectorConfig.GetTimeSpan("heartbeat-interval", null);
@@ -93,6 +94,11 @@ namespace Akka.Cluster
             AllowWeaklyUpMembers = clusterConfig.GetBoolean("allow-weakly-up-members", false);
         }
 
+        /// <summary>
+        /// Determine whether to log verbose <see cref="Akka.Event.LogLevel.InfoLevel"/> messages for temporary troubleshooting.
+        /// </summary>
+        public bool LogInfoVerbose { get; }
+
         /// <summary>
         /// Determine whether to log <see cref="Akka.Event.LogLevel.InfoLevel"/> messages.
         /// </summary>

src/core/Akka.Cluster/Configuration/Cluster.conf

@@ -102,6 +102,10 @@ akka {
     # Enable/disable info level logging of cluster events
     log-info = on
 
+    # Enable/disable verbose info-level logging of cluster events
+    # for temporary troubleshooting. Defaults to 'off'.
+    log-info-verbose = off
+
     # how long should the node wait before starting the periodic tasks
     # maintenance tasks?
     periodic-tasks-initial-delay = 1s