Watcher: Reduce logging noise when watcher might be stopped (elastic/x-pack-elasticsearch#1685)

Only log an entry when an actual stop is executed instead of
always logging.

Also added a reason to stop watcher to the methods, so that
debug logs will yield that information.

Original commit: elastic/x-pack-elasticsearch@8efaed0e9a

plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleService.java

@@ -51,7 +51,7 @@ public class WatcherLifeCycleService extends AbstractComponent implements Cluste
         clusterService.addLifecycleListener(new LifecycleListener() {
             @Override
             public void beforeStop() {
-                stop();
+                stop("stopping before shutting down");
             }
         });
         watcherMetaData = new WatcherMetaData(!settings.getAsBoolean("xpack.watcher.start_immediately", true));
@@ -61,8 +61,8 @@ public class WatcherLifeCycleService extends AbstractComponent implements Cluste
         start(clusterService.state(), true);
     }
 
-    public void stop() {
+    public void stop(String reason) {
-        watcherService.stop();
+        watcherService.stop(reason);
     }
 
     private synchronized void start(ClusterState state, boolean manual) {
@@ -115,8 +115,7 @@ public class WatcherLifeCycleService extends AbstractComponent implements Cluste
 
         boolean currentWatcherStopped = watcherMetaData != null && watcherMetaData.manuallyStopped() == true;
         if (currentWatcherStopped) {
-            logger.debug("watcher manually marked to shutdown in cluster state update, shutting down");
+            executor.execute(() -> this.stop("watcher manually marked to shutdown in cluster state update, shutting down"));
-            executor.execute(this::stop);
         } else {
             if (watcherService.state() == WatcherState.STARTED && event.state().nodes().getLocalNode().isDataNode()) {
                 DiscoveryNode localNode = event.state().nodes().getLocalNode();

plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherService.java

@@ -141,14 +141,14 @@ public class WatcherService extends AbstractComponent {
     /**
      * Stops the watcher service and it's subservices. Should only be called, when watcher is stopped manually
      */
-    public void stop() {
+    public void stop(String reason) {
         WatcherState currentState = state.get();
         if (currentState == WatcherState.STOPPING || currentState == WatcherState.STOPPED) {
             logger.trace("watcher is already in state [{}] not stopping", currentState);
         } else {
             try {
                 if (state.compareAndSet(WatcherState.STARTED, WatcherState.STOPPING)) {
-                    logger.debug("stopping watch service...");
+                    logger.debug("stopping watch service, reason [{}]", reason);
                     triggerService.stop();
                     executionService.stop();
                     state.set(WatcherState.STOPPED);

plugin/src/test/java/org/elasticsearch/xpack/monitoring/test/MonitoringIntegTestCase.java

@@ -198,7 +198,8 @@ public abstract class MonitoringIntegTestCase extends ESIntegTestCase {
     @After
     public void tearDown() throws Exception {
         if (watcherEnabled != null && watcherEnabled) {
-            internalCluster().getInstance(WatcherLifeCycleService.class, internalCluster().getMasterName()).stop();
+            internalCluster().getInstances(WatcherLifeCycleService.class)
+                    .forEach(w -> w.stop("tearing down watcher as part of monitoring test case"));
         }
         stopMonitoringService();
         super.tearDown();

plugin/src/test/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleServiceTests.java

@@ -89,13 +89,13 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
         when(watcherService.validate(clusterState)).thenReturn(true);
         lifeCycleService.clusterChanged(new ClusterChangedEvent("any", clusterState, previousClusterState));
         verify(watcherService, times(1)).start(clusterState);
-        verify(watcherService, never()).stop();
+        verify(watcherService, never()).stop(anyString());
 
         // Trying to start a second time, but that should have no affect.
         when(watcherService.state()).thenReturn(WatcherState.STARTED);
         lifeCycleService.clusterChanged(new ClusterChangedEvent("any", clusterState, previousClusterState));
         verify(watcherService, times(1)).start(clusterState);
-        verify(watcherService, never()).stop();
+        verify(watcherService, never()).stop(anyString());
     }
 
     public void testStartWithStateNotRecoveredBlock() throws Exception {
@@ -121,18 +121,19 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
         when(watcherService.state()).thenReturn(WatcherState.STOPPED);
         lifeCycleService.start();
         verify(watcherService, times(1)).start(any(ClusterState.class));
-        verify(watcherService, never()).stop();
+        verify(watcherService, never()).stop(anyString());
 
         when(watcherService.state()).thenReturn(WatcherState.STARTED);
-        lifeCycleService.stop();
+        String reason = randomAlphaOfLength(10);
+        lifeCycleService.stop(reason);
         verify(watcherService, times(1)).start(any(ClusterState.class));
-        verify(watcherService, times(1)).stop();
+        verify(watcherService, times(1)).stop(eq(reason));
 
         // Starting via cluster state update, we shouldn't start because we have been stopped manually.
         when(watcherService.state()).thenReturn(WatcherState.STOPPED);
         lifeCycleService.clusterChanged(new ClusterChangedEvent("any", clusterState, clusterState));
         verify(watcherService, times(2)).start(any(ClusterState.class));
-        verify(watcherService, times(1)).stop();
+        verify(watcherService, times(1)).stop(eq(reason));
 
         // no change, keep going
         clusterState  = ClusterState.builder(new ClusterName("my-cluster"))
@@ -141,7 +142,7 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
         when(watcherService.state()).thenReturn(WatcherState.STARTED);
         lifeCycleService.clusterChanged(new ClusterChangedEvent("any", clusterState, clusterState));
         verify(watcherService, times(2)).start(any(ClusterState.class));
-        verify(watcherService, times(1)).stop();
+        verify(watcherService, times(1)).stop(eq(reason));
 
         ClusterState previousClusterState = ClusterState.builder(new ClusterName("my-cluster"))
                 .nodes(new DiscoveryNodes.Builder().masterNodeId("node_1").localNodeId("node_1").add(newNode("node_1")))
@@ -150,7 +151,7 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
         when(watcherService.state()).thenReturn(WatcherState.STOPPED);
         lifeCycleService.clusterChanged(new ClusterChangedEvent("any", clusterState, previousClusterState));
         verify(watcherService, times(3)).start(any(ClusterState.class));
-        verify(watcherService, times(1)).stop();
+        verify(watcherService, times(1)).stop(eq(reason));
     }
 
     public void testManualStartStopClusterStateNotValid() throws Exception {
@@ -163,7 +164,7 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
 
         lifeCycleService.start();
         verify(watcherService, never()).start(any(ClusterState.class));
-        verify(watcherService, never()).stop();
+        verify(watcherService, never()).stop(anyString());
     }
 
     public void testManualStartStopWatcherNotStopped() throws Exception {
@@ -176,7 +177,7 @@ public class WatcherLifeCycleServiceTests extends ESTestCase {
         lifeCycleService.start();
         verify(watcherService, never()).validate(any(ClusterState.class));
         verify(watcherService, never()).start(any(ClusterState.class));
-        verify(watcherService, never()).stop();
+        verify(watcherService, never()).stop(anyString());
     }
 
     public void testNoLocalShards() throws Exception {