SlowLoggers using single logger

server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java

@@ -43,22 +43,7 @@
 import java.util.concurrent.TimeUnit;
 
 public final class IndexingSlowLog implements IndexingOperationListener {
-    private final Index index;
-    private boolean reformat;
-    private long indexWarnThreshold;
-    private long indexInfoThreshold;
-    private long indexDebugThreshold;
-    private long indexTraceThreshold;
-    /**
-     * How much of the source to log in the slowlog - 0 means log none and
-     * anything greater than 0 means log at least that many <em>characters</em>
-     * of the source.
-     */
-    private int maxSourceCharsToLog;
-
-    private final Logger indexLogger;
-
-    private static final String INDEX_INDEXING_SLOWLOG_PREFIX = "index.indexing.slowlog";
+    public static final String INDEX_INDEXING_SLOWLOG_PREFIX = "index.indexing.slowlog";
     public static final Setting<TimeValue> INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING =
         Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.warn", TimeValue.timeValueNanos(-1),
             TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
@@ -76,6 +61,22 @@ public final class IndexingSlowLog implements IndexingOperationListener {
     public static final Setting<SlowLogLevel> INDEX_INDEXING_SLOWLOG_LEVEL_SETTING =
         new Setting<>(INDEX_INDEXING_SLOWLOG_PREFIX +".level", SlowLogLevel.TRACE.name(), SlowLogLevel::parse, Property.Dynamic,
             Property.IndexScope);
+
+    private final Logger indexLogger;
+    private final Index index;
+
+    private boolean reformat;
+    private long indexWarnThreshold;
+    private long indexInfoThreshold;
+    private long indexDebugThreshold;
+    private long indexTraceThreshold;
+    /*
+     * How much of the source to log in the slowlog - 0 means log none and anything greater than 0 means log at least that many
+     * <em>characters</em> of the source.
+     */
+    private int maxSourceCharsToLog;
+    private SlowLogLevel level;
+
     /**
      * Reads how much of the source to log. The user can specify any value they
      * like and numbers are interpreted the maximum number of characters to log
@@ -92,7 +93,8 @@ public final class IndexingSlowLog implements IndexingOperationListener {
             }, Property.Dynamic, Property.IndexScope);
 
     IndexingSlowLog(IndexSettings indexSettings) {
-        this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index." + indexSettings.getUUID());
+        this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index");
+        Loggers.setLevel(this.indexLogger, SlowLogLevel.TRACE.name());
         this.index = indexSettings.getIndex();
 
         indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING, this::setReformat);
@@ -121,7 +123,7 @@ private void setMaxSourceCharsToLog(int maxSourceCharsToLog) {
     }
 
     private void setLevel(SlowLogLevel level) {
-        Loggers.setLevel(this.indexLogger, level.name());
+        this.level = level;
     }
 
     private void setWarnThreshold(TimeValue warnThreshold) {
@@ -149,13 +151,14 @@ public void postIndex(ShardId shardId, Engine.Index indexOperation, Engine.Index
         if (result.getResultType() == Engine.Result.Type.SUCCESS) {
             final ParsedDocument doc = indexOperation.parsedDoc();
             final long tookInNanos = result.getTook();
-            if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) {
+            // when logger level is more specific than WARN AND event is within threshold it should be logged
+            if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
                 indexLogger.warn( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
-            } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
+            } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
                 indexLogger.info(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
-            } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
+            } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
                 indexLogger.debug(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
-            } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
+            } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
                 indexLogger.trace( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
             }
         }
@@ -258,7 +261,7 @@ int getMaxSourceCharsToLog() {
     }
 
     SlowLogLevel getLevel() {
-        return SlowLogLevel.parse(indexLogger.getLevel().name());
+        return level;
     }
 
 }

server/src/main/java/org/elasticsearch/index/SearchSlowLog.java

@@ -33,8 +33,8 @@
 import org.elasticsearch.search.internal.SearchContext;
 import org.elasticsearch.tasks.Task;
 
-import java.util.Arrays;
 import java.nio.charset.Charset;
+import java.util.Arrays;
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.Map;
@@ -57,7 +57,7 @@ public final class SearchSlowLog implements SearchOperationListener {
     private final Logger queryLogger;
     private final Logger fetchLogger;
 
-    private static final String INDEX_SEARCH_SLOWLOG_PREFIX = "index.search.slowlog";
+    static final String INDEX_SEARCH_SLOWLOG_PREFIX = "index.search.slowlog";
     public static final Setting<TimeValue> INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING =
         Setting.timeSetting(INDEX_SEARCH_SLOWLOG_PREFIX + ".threshold.query.warn", TimeValue.timeValueNanos(-1),
             TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
@@ -87,11 +87,13 @@ public final class SearchSlowLog implements SearchOperationListener {
             Property.IndexScope);
 
     private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));
+    private SlowLogLevel level;
 
     public SearchSlowLog(IndexSettings indexSettings) {
-
-        this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query." + indexSettings.getUUID());
-        this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch." + indexSettings.getUUID());
+        this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query");
+        this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch");
+        Loggers.setLevel(this.fetchLogger, SlowLogLevel.TRACE.name());
+        Loggers.setLevel(this.queryLogger, SlowLogLevel.TRACE.name());
 
         indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
             this::setQueryWarnThreshold);
@@ -124,32 +126,31 @@ public SearchSlowLog(IndexSettings indexSettings) {
     }
 
     private void setLevel(SlowLogLevel level) {
-        Loggers.setLevel(queryLogger, level.name());
-        Loggers.setLevel(fetchLogger, level.name());
+        this.level = level;
     }
 
     @Override
     public void onQueryPhase(SearchContext context, long tookInNanos) {
-        if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
+        if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
             queryLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
+        } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
             queryLogger.info(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
+        } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
             queryLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
+        } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
             queryLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
         }
     }
 
     @Override
     public void onFetchPhase(SearchContext context, long tookInNanos) {
-        if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
+        if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
             fetchLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
+        } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
             fetchLogger.info(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
+        } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
             fetchLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
-        } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
+        } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
             fetchLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
         }
     }
@@ -303,7 +304,6 @@ long getFetchTraceThreshold() {
     }
 
     SlowLogLevel getLevel() {
-        assert queryLogger.getLevel().equals(fetchLogger.getLevel());
-        return SlowLogLevel.parse(queryLogger.getLevel().name());
+        return level;
     }
 }

server/src/main/java/org/elasticsearch/index/SlowLogLevel.java

@@ -21,8 +21,23 @@
 import java.util.Locale;
 
 public enum SlowLogLevel {
-    WARN, TRACE, INFO, DEBUG;
+    WARN(3), // most specific - little logging
+    INFO(2),
+    DEBUG(1),
+    TRACE(0); // least specific - lots of logging
+
+    private final int specificity;
+
+    SlowLogLevel(int specificity) {
+        this.specificity = specificity;
+    }
+
     public static SlowLogLevel parse(String level) {
         return valueOf(level.toUpperCase(Locale.ROOT));
     }
+
+    boolean isLevelEnabledFor(SlowLogLevel levelToBeUsed) {
+        // example: this.info(2) tries to log with levelToBeUsed.warn(3) - should allow
+        return this.specificity <= levelToBeUsed.specificity;
+    }
 }

server/src/test/java/org/elasticsearch/common/logging/LoggersTests.java

@@ -22,9 +22,6 @@
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.LogEvent;
-import org.apache.logging.log4j.core.appender.AbstractAppender;
-import org.apache.logging.log4j.core.filter.RegexFilter;
 import org.apache.logging.log4j.message.ParameterizedMessage;
 import org.elasticsearch.test.ESTestCase;
 
@@ -38,23 +35,6 @@
 
 public class LoggersTests extends ESTestCase {
 
-    static class MockAppender extends AbstractAppender {
-        private LogEvent lastEvent;
-
-        MockAppender(final String name) throws IllegalAccessException {
-            super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null);
-        }
-
-        @Override
-        public void append(LogEvent event) {
-            lastEvent = event.toImmutable();
-        }
-
-        ParameterizedMessage lastParameterizedMessage() {
-            return (ParameterizedMessage) lastEvent.getMessage();
-        }
-    }
-
     public void testParameterizedMessageLambda() throws Exception {
         final MockAppender appender = new MockAppender("trace_appender");
         appender.start();

server/src/test/java/org/elasticsearch/common/logging/MockAppender.java

@@ -0,0 +1,48 @@
+/*
+ * Licensed to Elasticsearch under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch licenses this file to you under
+ * the Apache License, Version 2.0 (the "License"); you may
+ * not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+package org.elasticsearch.common.logging;
+
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.appender.AbstractAppender;
+import org.apache.logging.log4j.core.filter.RegexFilter;
+import org.apache.logging.log4j.message.ParameterizedMessage;
+
+public class MockAppender extends AbstractAppender {
+    public LogEvent lastEvent;
+
+    public MockAppender(final String name) throws IllegalAccessException {
+        super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null);
+    }
+
+    @Override
+    public void append(LogEvent event) {
+        lastEvent = event.toImmutable();
+    }
+
+    ParameterizedMessage lastParameterizedMessage() {
+        return (ParameterizedMessage) lastEvent.getMessage();
+    }
+
+    public LogEvent getLastEventAndReset() {
+        LogEvent toReturn = lastEvent;
+        lastEvent = null;
+        return toReturn;
+    }
+}