Skip to content

Commit

Permalink
SlowLoggers using single logger backport(#56708) (#57228)
Browse files Browse the repository at this point in the history 
Slow loggers should use single shared logger as otherwise when index is
deleted the log4j logger will remain reachable (log4j is caching) and
will create a memory leak.

closes #56171
  • Loading branch information
@pgomulka
pgomulka committed May 27, 2020
1 parent f371e66 commit da3dbed
Show file tree
Hide file tree
Showing 8 changed files with 477 additions and 61 deletions.
49 changes: 26 additions & 23 deletions server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,22 +39,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);
Expand All @@ -72,6 +57,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
Expand All @@ -88,7 +89,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);
Expand Down Expand Up @@ -117,7 +119,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) {
Expand Down Expand Up @@ -145,13 +147,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 SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
indexLogger.info("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
indexLogger.debug("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
indexLogger.trace("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
}
}
Expand Down Expand Up @@ -230,7 +233,7 @@ int getMaxSourceCharsToLog() {
}

SlowLogLevel getLevel() {
return SlowLogLevel.parse(indexLogger.getLevel().name());
return level;
}

}
33 changes: 17 additions & 16 deletions server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,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);
Expand Down Expand Up @@ -78,11 +78,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);
Expand Down Expand Up @@ -115,31 +117,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 SlowLogSearchContextPrinter(context, tookInNanos));
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
queryLogger.trace("{}", new SlowLogSearchContextPrinter(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 SlowLogSearchContextPrinter(context, tookInNanos));
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos));
}
}
Expand Down Expand Up @@ -256,7 +258,6 @@ long getFetchTraceThreshold() {
}

SlowLogLevel getLevel() {
assert queryLogger.getLevel().equals(fetchLogger.getLevel());
return SlowLogLevel.parse(queryLogger.getLevel().name());
return level;
}
}
17 changes: 16 additions & 1 deletion server/src/main/java/org/elasticsearch/index/SlowLogLevel.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}
20 changes: 0 additions & 20 deletions server/src/test/java/org/elasticsearch/common/logging/LoggersTests.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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();
Expand Down
48 changes: 48 additions & 0 deletions server/src/test/java/org/elasticsearch/common/logging/MockAppender.java
View file
Original file line number Diff line number Diff line change
@@ -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;
}
}

0 comments on commit da3dbed

Please sign in to comment.