From 83a5e022cb09f5e6c81d93d28569c63442b96e88 Mon Sep 17 00:00:00 2001 From: Alexander Reelsen Date: Mon, 12 Jun 2017 10:24:16 +0200 Subject: [PATCH] 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@8efaed0e9a858d5fd15d4373591803d5718afbc9 --- .../watcher/WatcherLifeCycleService.java | 9 ++++---- .../xpack/watcher/WatcherService.java | 4 ++-- .../test/MonitoringIntegTestCase.java | 3 ++- .../watcher/WatcherLifeCycleServiceTests.java | 21 ++++++++++--------- 4 files changed, 19 insertions(+), 18 deletions(-) diff --git a/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleService.java b/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleService.java index fe4ef4ef5c9..a142cfe4984 100644 --- a/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleService.java +++ b/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() { - watcherService.stop(); + public void stop(String reason) { + 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); + executor.execute(() -> this.stop("watcher manually marked to shutdown in cluster state update, shutting down")); } else { if (watcherService.state() == WatcherState.STARTED && event.state().nodes().getLocalNode().isDataNode()) { DiscoveryNode localNode = event.state().nodes().getLocalNode(); diff --git a/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherService.java b/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherService.java index c7733240c90..9072f17723c 100644 --- a/plugin/src/main/java/org/elasticsearch/xpack/watcher/WatcherService.java +++ b/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); diff --git a/plugin/src/test/java/org/elasticsearch/xpack/monitoring/test/MonitoringIntegTestCase.java b/plugin/src/test/java/org/elasticsearch/xpack/monitoring/test/MonitoringIntegTestCase.java index fdf5e0ad692..37fbc38704a 100644 --- a/plugin/src/test/java/org/elasticsearch/xpack/monitoring/test/MonitoringIntegTestCase.java +++ b/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(); diff --git a/plugin/src/test/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleServiceTests.java b/plugin/src/test/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleServiceTests.java index fbd247b0804..809731071d8 100644 --- a/plugin/src/test/java/org/elasticsearch/xpack/watcher/WatcherLifeCycleServiceTests.java +++ b/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 {