Skip to content

Commit 2704786

Browse files
pgomulkapgomulka
authored
SlowLoggers using single logger backport(#56708) (#57215)
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
1 parent 190d0dc commit 2704786

File tree

8 files changed

+504
-101
lines changed

8 files changed

+504
-101
lines changed

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

Lines changed: 26 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -43,22 +43,7 @@
4343
import java.util.concurrent.TimeUnit;
4444

4545
public final class IndexingSlowLog implements IndexingOperationListener {
46-
private final Index index;
47-
private boolean reformat;
48-
private long indexWarnThreshold;
49-
private long indexInfoThreshold;
50-
private long indexDebugThreshold;
51-
private long indexTraceThreshold;
52-
/**
53-
* How much of the source to log in the slowlog - 0 means log none and
54-
* anything greater than 0 means log at least that many <em>characters</em>
55-
* of the source.
56-
*/
57-
private int maxSourceCharsToLog;
58-
59-
private final Logger indexLogger;
60-
61-
private static final String INDEX_INDEXING_SLOWLOG_PREFIX = "index.indexing.slowlog";
46+
public static final String INDEX_INDEXING_SLOWLOG_PREFIX = "index.indexing.slowlog";
6247
public static final Setting<TimeValue> INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING =
6348
Setting.timeSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".threshold.index.warn", TimeValue.timeValueNanos(-1),
6449
TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
@@ -76,6 +61,22 @@ public final class IndexingSlowLog implements IndexingOperationListener {
7661
public static final Setting<SlowLogLevel> INDEX_INDEXING_SLOWLOG_LEVEL_SETTING =
7762
new Setting<>(INDEX_INDEXING_SLOWLOG_PREFIX +".level", SlowLogLevel.TRACE.name(), SlowLogLevel::parse, Property.Dynamic,
7863
Property.IndexScope);
64+
65+
private final Logger indexLogger;
66+
private final Index index;
67+
68+
private boolean reformat;
69+
private long indexWarnThreshold;
70+
private long indexInfoThreshold;
71+
private long indexDebugThreshold;
72+
private long indexTraceThreshold;
73+
/*
74+
* 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
75+
* <em>characters</em> of the source.
76+
*/
77+
private int maxSourceCharsToLog;
78+
private SlowLogLevel level;
79+
7980
/**
8081
* Reads how much of the source to log. The user can specify any value they
8182
* like and numbers are interpreted the maximum number of characters to log
@@ -92,7 +93,8 @@ public final class IndexingSlowLog implements IndexingOperationListener {
9293
}, Property.Dynamic, Property.IndexScope);
9394

9495
IndexingSlowLog(IndexSettings indexSettings) {
95-
this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index." + indexSettings.getUUID());
96+
this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index");
97+
Loggers.setLevel(this.indexLogger, SlowLogLevel.TRACE.name());
9698
this.index = indexSettings.getIndex();
9799

98100
indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING, this::setReformat);
@@ -121,7 +123,7 @@ private void setMaxSourceCharsToLog(int maxSourceCharsToLog) {
121123
}
122124

123125
private void setLevel(SlowLogLevel level) {
124-
Loggers.setLevel(this.indexLogger, level.name());
126+
this.level = level;
125127
}
126128

127129
private void setWarnThreshold(TimeValue warnThreshold) {
@@ -149,13 +151,14 @@ public void postIndex(ShardId shardId, Engine.Index indexOperation, Engine.Index
149151
if (result.getResultType() == Engine.Result.Type.SUCCESS) {
150152
final ParsedDocument doc = indexOperation.parsedDoc();
151153
final long tookInNanos = result.getTook();
152-
if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) {
154+
// when logger level is more specific than WARN AND event is within threshold it should be logged
155+
if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
153156
indexLogger.warn( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
154-
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
157+
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
155158
indexLogger.info(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
156-
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
159+
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
157160
indexLogger.debug(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
158-
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
161+
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
159162
indexLogger.trace( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
160163
}
161164
}
@@ -258,7 +261,7 @@ int getMaxSourceCharsToLog() {
258261
}
259262

260263
SlowLogLevel getLevel() {
261-
return SlowLogLevel.parse(indexLogger.getLevel().name());
264+
return level;
262265
}
263266

264267
}

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

Lines changed: 17 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -33,8 +33,8 @@
3333
import org.elasticsearch.search.internal.SearchContext;
3434
import org.elasticsearch.tasks.Task;
3535

36-
import java.util.Arrays;
3736
import java.nio.charset.Charset;
37+
import java.util.Arrays;
3838
import java.util.Collections;
3939
import java.util.HashMap;
4040
import java.util.Map;
@@ -57,7 +57,7 @@ public final class SearchSlowLog implements SearchOperationListener {
5757
private final Logger queryLogger;
5858
private final Logger fetchLogger;
5959

60-
private static final String INDEX_SEARCH_SLOWLOG_PREFIX = "index.search.slowlog";
60+
static final String INDEX_SEARCH_SLOWLOG_PREFIX = "index.search.slowlog";
6161
public static final Setting<TimeValue> INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING =
6262
Setting.timeSetting(INDEX_SEARCH_SLOWLOG_PREFIX + ".threshold.query.warn", TimeValue.timeValueNanos(-1),
6363
TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
@@ -87,11 +87,13 @@ public final class SearchSlowLog implements SearchOperationListener {
8787
Property.IndexScope);
8888

8989
private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));
90+
private SlowLogLevel level;
9091

9192
public SearchSlowLog(IndexSettings indexSettings) {
92-
93-
this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query." + indexSettings.getUUID());
94-
this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch." + indexSettings.getUUID());
93+
this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query");
94+
this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch");
95+
Loggers.setLevel(this.fetchLogger, SlowLogLevel.TRACE.name());
96+
Loggers.setLevel(this.queryLogger, SlowLogLevel.TRACE.name());
9597

9698
indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
9799
this::setQueryWarnThreshold);
@@ -124,32 +126,31 @@ public SearchSlowLog(IndexSettings indexSettings) {
124126
}
125127

126128
private void setLevel(SlowLogLevel level) {
127-
Loggers.setLevel(queryLogger, level.name());
128-
Loggers.setLevel(fetchLogger, level.name());
129+
this.level = level;
129130
}
130131

131132
@Override
132133
public void onQueryPhase(SearchContext context, long tookInNanos) {
133-
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
134+
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
134135
queryLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
135-
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
136+
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
136137
queryLogger.info(new SearchSlowLogMessage(context, tookInNanos));
137-
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
138+
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
138139
queryLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
139-
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
140+
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
140141
queryLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
141142
}
142143
}
143144

144145
@Override
145146
public void onFetchPhase(SearchContext context, long tookInNanos) {
146-
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
147+
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
147148
fetchLogger.warn(new SearchSlowLogMessage(context, tookInNanos));
148-
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
149+
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
149150
fetchLogger.info(new SearchSlowLogMessage(context, tookInNanos));
150-
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
151+
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
151152
fetchLogger.debug(new SearchSlowLogMessage(context, tookInNanos));
152-
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
153+
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
153154
fetchLogger.trace(new SearchSlowLogMessage(context, tookInNanos));
154155
}
155156
}
@@ -303,7 +304,6 @@ long getFetchTraceThreshold() {
303304
}
304305

305306
SlowLogLevel getLevel() {
306-
assert queryLogger.getLevel().equals(fetchLogger.getLevel());
307-
return SlowLogLevel.parse(queryLogger.getLevel().name());
307+
return level;
308308
}
309309
}

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

Lines changed: 16 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,8 +21,23 @@
2121
import java.util.Locale;
2222

2323
public enum SlowLogLevel {
24-
WARN, TRACE, INFO, DEBUG;
24+
WARN(3), // most specific - little logging
25+
INFO(2),
26+
DEBUG(1),
27+
TRACE(0); // least specific - lots of logging
28+
29+
private final int specificity;
30+
31+
SlowLogLevel(int specificity) {
32+
this.specificity = specificity;
33+
}
34+
2535
public static SlowLogLevel parse(String level) {
2636
return valueOf(level.toUpperCase(Locale.ROOT));
2737
}
38+
39+
boolean isLevelEnabledFor(SlowLogLevel levelToBeUsed) {
40+
// example: this.info(2) tries to log with levelToBeUsed.warn(3) - should allow
41+
return this.specificity <= levelToBeUsed.specificity;
42+
}
2843
}

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

Lines changed: 0 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -22,9 +22,6 @@
2222
import org.apache.logging.log4j.Level;
2323
import org.apache.logging.log4j.LogManager;
2424
import org.apache.logging.log4j.Logger;
25-
import org.apache.logging.log4j.core.LogEvent;
26-
import org.apache.logging.log4j.core.appender.AbstractAppender;
27-
import org.apache.logging.log4j.core.filter.RegexFilter;
2825
import org.apache.logging.log4j.message.ParameterizedMessage;
2926
import org.elasticsearch.test.ESTestCase;
3027

@@ -38,23 +35,6 @@
3835

3936
public class LoggersTests extends ESTestCase {
4037

41-
static class MockAppender extends AbstractAppender {
42-
private LogEvent lastEvent;
43-
44-
MockAppender(final String name) throws IllegalAccessException {
45-
super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null);
46-
}
47-
48-
@Override
49-
public void append(LogEvent event) {
50-
lastEvent = event.toImmutable();
51-
}
52-
53-
ParameterizedMessage lastParameterizedMessage() {
54-
return (ParameterizedMessage) lastEvent.getMessage();
55-
}
56-
}
57-
5838
public void testParameterizedMessageLambda() throws Exception {
5939
final MockAppender appender = new MockAppender("trace_appender");
6040
appender.start();

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

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
/*
2+
* Licensed to Elasticsearch under one or more contributor
3+
* license agreements. See the NOTICE file distributed with
4+
* this work for additional information regarding copyright
5+
* ownership. Elasticsearch licenses this file to you under
6+
* the Apache License, Version 2.0 (the "License"); you may
7+
* not use this file except in compliance with the License.
8+
* You may obtain a copy of the License at
9+
*
10+
* http://www.apache.org/licenses/LICENSE-2.0
11+
*
12+
* Unless required by applicable law or agreed to in writing,
13+
* software distributed under the License is distributed on an
14+
* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
15+
* KIND, either express or implied. See the License for the
16+
* specific language governing permissions and limitations
17+
* under the License.
18+
*/
19+
20+
package org.elasticsearch.common.logging;
21+
22+
import org.apache.logging.log4j.core.LogEvent;
23+
import org.apache.logging.log4j.core.appender.AbstractAppender;
24+
import org.apache.logging.log4j.core.filter.RegexFilter;
25+
import org.apache.logging.log4j.message.ParameterizedMessage;
26+
27+
public class MockAppender extends AbstractAppender {
28+
public LogEvent lastEvent;
29+
30+
public MockAppender(final String name) throws IllegalAccessException {
31+
super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null);
32+
}
33+
34+
@Override
35+
public void append(LogEvent event) {
36+
lastEvent = event.toImmutable();
37+
}
38+
39+
ParameterizedMessage lastParameterizedMessage() {
40+
return (ParameterizedMessage) lastEvent.getMessage();
41+
}
42+
43+
public LogEvent getLastEventAndReset() {
44+
LogEvent toReturn = lastEvent;
45+
lastEvent = null;
46+
return toReturn;
47+
}
48+
}

0 commit comments

Comments
 (0)