Move grace period event edge from timer to event diff calculator

Ensures that event is only emitted when we're actually publishing a
state containing the state transition. Emitting events in the timer
code is fragile when it does not modify any state, risking emitting
the same event an unbounded amount of times if the condition keeps
holding for each timer cycle.

6 files changed, 50 insertions, 18 deletions

diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateGenerator.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateGenerator.java
index 26fdddb01e5..74f3cc276a5 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateGenerator.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateGenerator.java
@@ -132,7 +132,7 @@ public class ClusterStateGenerator {
         final Map<Node, NodeStateReason> nodeStateReasons = new HashMap<>();
 
         for (final NodeInfo nodeInfo : cluster.getNodeInfo()) {
-            final NodeState nodeState = computeEffectiveNodeState(nodeInfo, params);
+            final NodeState nodeState = computeEffectiveNodeState(nodeInfo, params, nodeStateReasons);
             workingState.setNodeState(nodeInfo.getNode(), nodeState);
         }
 
@@ -159,7 +159,10 @@ public class ClusterStateGenerator {
         baseline.setDescription(wanted.getDescription());
     }
 
-    private static NodeState computeEffectiveNodeState(final NodeInfo nodeInfo, final Params params) {
+    private static NodeState computeEffectiveNodeState(final NodeInfo nodeInfo,
+                                                       final Params params,
+                                                       Map<Node, NodeStateReason> nodeStateReasons)
+    {
         final NodeState reported = nodeInfo.getReportedState();
         final NodeState wanted   = nodeInfo.getWantedState();
         final NodeState baseline = reported.clone();
@@ -171,7 +174,7 @@ public class ClusterStateGenerator {
             baseline.setStartTimestamp(0);
         }
         if (nodeInfo.isStorage()) {
-            applyStorageSpecificStateTransforms(nodeInfo, params, reported, wanted, baseline);
+            applyStorageSpecificStateTransforms(nodeInfo, params, reported, wanted, baseline, nodeStateReasons);
         }
         if (baseline.above(wanted)) {
             applyWantedStateToBaselineState(baseline, wanted);
@@ -181,7 +184,8 @@ public class ClusterStateGenerator {
     }
 
     private static void applyStorageSpecificStateTransforms(NodeInfo nodeInfo, Params params, NodeState reported,
-                                                            NodeState wanted, NodeState baseline)
+                                                            NodeState wanted, NodeState baseline,
+                                                            Map<Node, NodeStateReason> nodeStateReasons)
     {
         if (reported.getState() == State.INITIALIZING) {
             if (timedOutWithoutNewInitProgress(reported, nodeInfo, params)
@@ -195,7 +199,7 @@ public class ClusterStateGenerator {
             }
         }
         // TODO ensure that maintenance cannot override Down for any other cases
-        if (withinTemporalMaintenancePeriod(nodeInfo, baseline, params) && wanted.getState() != State.DOWN) {
+        if (withinTemporalMaintenancePeriod(nodeInfo, baseline, nodeStateReasons, params) && wanted.getState() != State.DOWN) {
             baseline.setState(State.MAINTENANCE);
         }
     }
@@ -244,13 +248,18 @@ public class ClusterStateGenerator {
      */
     private static boolean withinTemporalMaintenancePeriod(final NodeInfo nodeInfo,
                                                            final NodeState baseline,
+                                                           Map<Node, NodeStateReason> nodeStateReasons,
                                                            final Params params)
     {
         final Integer transitionTime = params.transitionTimes.get(nodeInfo.getNode().getType());
         if (transitionTime == 0 || !baseline.getState().oneOf("sd")) {
             return false;
         }
-        return nodeInfo.getTransitionTime() + transitionTime > params.currentTimeInMillis;
+        if (nodeInfo.getTransitionTime() + transitionTime > params.currentTimeInMillis) {
+            return true;
+        }
+        nodeStateReasons.put(nodeInfo.getNode(), NodeStateReason.NODE_NOT_BACK_UP_WITHIN_GRACE_PERIOD);
+        return false;
     }
 
     private static void takeDownGroupsWithTooLowAvailability(final ClusterState workingState,
diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventDiffCalculator.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventDiffCalculator.java
index cadc065dd51..2f065a9ba75 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventDiffCalculator.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventDiffCalculator.java
@@ -31,6 +31,7 @@ public class EventDiffCalculator {
         ClusterStateBundle fromState;
         ClusterStateBundle toState;
         long currentTime;
+        long maxMaintenanceGracePeriodTimeMs;
 
         public Params cluster(ContentCluster cluster) {
             this.cluster = cluster;
@@ -48,6 +49,10 @@ public class EventDiffCalculator {
             this.currentTime = time;
             return this;
         }
+        public Params maxMaintenanceGracePeriodTimeMs(long timeMs) {
+            this.maxMaintenanceGracePeriodTimeMs = timeMs;
+            return this;
+        }
     }
 
     public static Params params() { return new Params(); }
@@ -58,17 +63,20 @@ public class EventDiffCalculator {
         final AnnotatedClusterState fromState;
         final AnnotatedClusterState toState;
         final long currentTime;
+        final long maxMaintenanceGracePeriodTimeMs;
 
         PerStateParams(ContentCluster cluster,
                        Optional<String> bucketSpace,
                        AnnotatedClusterState fromState,
                        AnnotatedClusterState toState,
-                       long currentTime) {
+                       long currentTime,
+                       long maxMaintenanceGracePeriodTimeMs) {
             this.cluster = cluster;
             this.bucketSpace = bucketSpace;
             this.fromState = fromState;
             this.toState = toState;
             this.currentTime = currentTime;
+            this.maxMaintenanceGracePeriodTimeMs = maxMaintenanceGracePeriodTimeMs;
         }
     }
 
@@ -86,7 +94,8 @@ public class EventDiffCalculator {
                 Optional.empty(),
                 params.fromState.getBaselineAnnotatedState(),
                 params.toState.getBaselineAnnotatedState(),
-                params.currentTime);
+                params.currentTime,
+                params.maxMaintenanceGracePeriodTimeMs);
     }
 
     private static void emitWholeClusterDiffEvent(final PerStateParams params, final List<Event> events) {
@@ -137,11 +146,10 @@ public class EventDiffCalculator {
         final NodeState nodeTo = toState.getNodeState(n);
         if (!nodeTo.equals(nodeFrom)) {
             final NodeInfo info = cluster.getNodeInfo(n);
-            events.add(createNodeEvent(info, String.format("Altered node state in cluster state from '%s' to '%s'",
-                            nodeFrom.toString(true), nodeTo.toString(true)), params));
-
             NodeStateReason prevReason = params.fromState.getNodeStateReasons().get(n);
             NodeStateReason currReason = params.toState.getNodeStateReasons().get(n);
+            // Add specific reason events for node edge _before_ the actual transition event itself.
+            // This makes the timeline of events more obvious.
             if (isGroupDownEdge(prevReason, currReason)) {
                 events.add(createNodeEvent(info, "Group node availability is below configured threshold", params));
             } else if (isGroupUpEdge(prevReason, currReason)) {
@@ -150,7 +158,12 @@ public class EventDiffCalculator {
                 events.add(createNodeEvent(info, "Node may have merges pending", params));
             } else if (isMayHaveMergesPendingDownEdge(prevReason, currReason)) {
                 events.add(createNodeEvent(info, "Node no longer has merges pending", params));
+            } else if (isMaintenanceGracePeriodExceededDownEdge(prevReason, currReason, nodeFrom, nodeTo)) {
+                events.add(createNodeEvent(info, String.format("Exceeded implicit maintenance mode grace period of " +
+                        "%d milliseconds. Marking node down.", params.maxMaintenanceGracePeriodTimeMs), params));
             }
+            events.add(createNodeEvent(info, String.format("Altered node state in cluster state from '%s' to '%s'",
+                    nodeFrom.toString(true), nodeTo.toString(true)), params));
         }
     }
 
@@ -178,6 +191,14 @@ public class EventDiffCalculator {
         return prevReason == NodeStateReason.MAY_HAVE_MERGES_PENDING && currReason != NodeStateReason.MAY_HAVE_MERGES_PENDING;
     }
 
+    private static boolean isMaintenanceGracePeriodExceededDownEdge(NodeStateReason prevReason, NodeStateReason currReason,
+                                                                    NodeState prevState, NodeState currState) {
+        return (prevReason != NodeStateReason.NODE_NOT_BACK_UP_WITHIN_GRACE_PERIOD &&
+                currReason == NodeStateReason.NODE_NOT_BACK_UP_WITHIN_GRACE_PERIOD &&
+                prevState.getState() == State.MAINTENANCE &&
+                currState.getState() == State.DOWN);
+    }
+
     private static boolean clusterHasTransitionedToUpState(ClusterState prevState, ClusterState currentState) {
         return prevState.getClusterState() != State.UP && currentState.getClusterState() == State.UP;
     }
@@ -207,7 +228,8 @@ public class EventDiffCalculator {
                 Optional.of(bucketSpace),
                 fromDerivedState,
                 toDerivedState,
-                params.currentTime);
+                params.currentTime,
+                params.maxMaintenanceGracePeriodTimeMs);
     }
 
 }
diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java
index 364184331a8..b4965fbff7b 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java
@@ -928,7 +928,8 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd
                         .cluster(cluster)
                         .fromState(fromState)
                         .toState(toState)
-                        .currentTimeMs(timeNowMs));
+                        .currentTimeMs(timeNowMs)
+                        .maxMaintenanceGracePeriodTimeMs(options.storageNodeMaxTransitionTimeMs()));
         for (Event event : deltaEvents) {
             eventLog.add(event, isMaster);
         }
diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetControllerOptions.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetControllerOptions.java
index f49b626d347..5e9e91e1cb6 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetControllerOptions.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetControllerOptions.java
@@ -157,6 +157,10 @@ public class FleetControllerOptions implements Cloneable {
         this.maxDeferredTaskVersionWaitTime = maxDeferredTaskVersionWaitTime;
     }
 
+    public long storageNodeMaxTransitionTimeMs() {
+        return maxTransitionTime.getOrDefault(NodeType.STORAGE, 10_000);
+    }
+
     public FleetControllerOptions clone() {
         try {
             // TODO: This should deep clone
diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateReason.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateReason.java
index 7a6be664ec8..3f550724cef 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateReason.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateReason.java
@@ -6,8 +6,8 @@ public enum NodeStateReason {
     // FIXME some of these reasons may be unnecessary as they are reported implicitly by reported/wanted state changes
     NODE_TOO_UNSTABLE,
     WITHIN_MAINTENANCE_GRACE_PERIOD,
+    NODE_NOT_BACK_UP_WITHIN_GRACE_PERIOD,
     FORCED_INTO_MAINTENANCE,
     GROUP_IS_DOWN,
     MAY_HAVE_MERGES_PENDING
-
 }
diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java
index 3f38ea6c018..3c19f70d1e2 100644
--- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java
+++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java
@@ -305,10 +305,6 @@ public class StateChangeHandler {
         if (nodeStillUnavailableAfterTransitionTimeExceeded(
                 currentTime, node, currentStateInSystem, lastReportedState))
         {
-            eventLog.add(NodeEvent.forBaseline(node, String.format(
-                        "%d milliseconds without contact. Marking node down.",
-                        currentTime - node.getTransitionTime()),
-                    NodeEvent.Type.CURRENT, currentTime), isMaster);
             triggeredAnyTimers = true;
         }