Implement deprecation logging using log4j (#61629)

Backport of #61474.

Part of #46106. Simplify the implementation of deprecation logging by
relying of log4j more completely, and implementing additional behaviour
through custom appenders and filters.
This commit is contained in:
Rory Hunter 2020-08-31 12:42:04 +01:00 committed by GitHub
parent 4c9fe31da8
commit ff6c071275
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
21 changed files with 534 additions and 361 deletions

View File

@ -8,14 +8,19 @@ appender.rolling.layout.type_name = server
rootLogger.level = info
rootLogger.appenderRef.rolling.ref = rolling
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
appender.deprecation_rolling.type = Console
appender.deprecation_rolling.name = deprecation_rolling
appender.deprecation_rolling.layout.type = ESJsonLayout
appender.deprecation_rolling.layout.type_name = deprecation
appender.deprecation_rolling.filter.rate_limit.type = RateLimitingFilter
logger.deprecation.name = org.elasticsearch.deprecation
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false
appender.index_search_slowlog_rolling.type = Console

View File

@ -64,6 +64,7 @@ appender.deprecation_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separ
appender.deprecation_rolling.layout.type = ESJsonLayout
appender.deprecation_rolling.layout.type_name = deprecation
appender.deprecation_rolling.layout.esmessagefields=x-opaque-id
appender.deprecation_rolling.filter.rate_limit.type = RateLimitingFilter
appender.deprecation_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation-%i.json.gz
appender.deprecation_rolling.policies.type = Policies
@ -71,6 +72,9 @@ appender.deprecation_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.deprecation_rolling.policies.size.size = 1GB
appender.deprecation_rolling.strategy.type = DefaultRolloverStrategy
appender.deprecation_rolling.strategy.max = 4
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
#################################################
######## Deprecation - old style pattern #######
appender.deprecation_rolling_old.type = RollingFile
@ -88,9 +92,10 @@ appender.deprecation_rolling_old.strategy.type = DefaultRolloverStrategy
appender.deprecation_rolling_old.strategy.max = 4
#################################################
logger.deprecation.name = org.elasticsearch.deprecation
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
logger.deprecation.appenderRef.deprecation_rolling_old.ref = deprecation_rolling_old
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false
######## Search slowlog JSON ####################

View File

@ -57,6 +57,7 @@ import java.util.regex.Pattern;
import java.util.stream.Collectors;
import java.util.stream.IntStream;
import static org.elasticsearch.common.logging.DeprecationLogger.DEPRECATION;
import static org.hamcrest.Matchers.endsWith;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.hasItem;
@ -119,7 +120,7 @@ public class EvilLoggerTests extends ESTestCase {
final List<Integer> ids = IntStream.range(0, 128).boxed().collect(Collectors.toList());
Randomness.shuffle(ids);
final ThreadContext threadContext = new ThreadContext(Settings.EMPTY);
DeprecationLogger.setThreadContext(threadContext);
HeaderWarning.setThreadContext(threadContext);
try {
barrier.await();
} catch (final BrokenBarrierException | InterruptedException e) {
@ -171,11 +172,12 @@ public class EvilLoggerTests extends ESTestCase {
// we appended an integer to each log message, use that for sorting
deprecationEvents.sort(Comparator.comparingInt(s -> Integer.parseInt(s.split("message")[1])));
assertThat(deprecationEvents.size(), equalTo(128));
for (int i = 0; i < 128; i++) {
assertLogLine(
deprecationEvents.get(i),
Level.WARN,
"org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
DEPRECATION,
"org.elasticsearch.common.logging.DeprecationLogger\\$DeprecationLoggerBuilder.withDeprecation",
"This is a maybe logged deprecation message" + i);
}
@ -185,49 +187,6 @@ public class EvilLoggerTests extends ESTestCase {
}
public void testDeprecationLoggerMaybeLog() throws IOException, UserException {
setupLogging("deprecation");
final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger("deprecation");
final int iterations = randomIntBetween(1, 16);
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecate("key", "This is a maybe logged deprecation message");
assertWarnings("This is a maybe logged deprecation message");
}
for (int k = 0; k < 128; k++) {
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecate("key" + k, "This is a maybe logged deprecation message" + k);
assertWarnings("This is a maybe logged deprecation message" + k);
}
}
for (int i = 0; i < iterations; i++) {
deprecationLogger.deprecate("key", "This is a maybe logged deprecation message");
assertWarnings("This is a maybe logged deprecation message");
}
final String deprecationPath =
System.getProperty("es.logs.base_path") +
System.getProperty("file.separator") +
System.getProperty("es.logs.cluster_name") +
"_deprecation.log";
final List<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
assertThat(deprecationEvents.size(), equalTo(1 + 128 + 1));
assertLogLine(
deprecationEvents.get(0),
Level.WARN,
"org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
"This is a maybe logged deprecation message");
for (int k = 0; k < 128; k++) {
assertLogLine(
deprecationEvents.get(1 + k),
Level.WARN,
"org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
"This is a maybe logged deprecation message" + k);
}
}
public void testDeprecatedSettings() throws IOException, UserException {
setupLogging("settings");
@ -250,8 +209,8 @@ public class EvilLoggerTests extends ESTestCase {
assertThat(deprecationEvents.size(), equalTo(1));
assertLogLine(
deprecationEvents.get(0),
Level.WARN,
"org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
DEPRECATION,
"org.elasticsearch.common.logging.DeprecationLogger\\$DeprecationLoggerBuilder.withDeprecation",
"\\[deprecated.foo\\] setting was deprecated in Elasticsearch and will be removed in a future release! " +
"See the breaking changes documentation for the next major version.");
}

View File

@ -24,8 +24,13 @@ appender.deprecation_file.name = deprecation_file
appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_file.layout.type = PatternLayout
appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
appender.deprecation_file.filter.rate_limit.type = RateLimitingFilter
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = deprecation
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

View File

@ -18,8 +18,13 @@ appender.deprecation_file.name = deprecation_file
appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_file.layout.type = PatternLayout
appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
appender.deprecation_file.filter.rate_limit.type = RateLimitingFilter
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = deprecation
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

View File

@ -18,8 +18,13 @@ appender.deprecation_file.name = deprecation_file
appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_file.layout.type = PatternLayout
appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n
appender.deprecation_file.filter.rate_limit.type = RateLimitingFilter
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = deprecation
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

View File

@ -18,9 +18,14 @@ appender.deprecation_file.name = deprecation_file
appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
appender.deprecation_file.layout.type = PatternLayout
appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
appender.deprecation_file.filter.rate_limit.type = RateLimitingFilter
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = org.elasticsearch.deprecation.common.settings
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.deprecation_console.ref = console
logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

View File

@ -9,7 +9,7 @@ appender.rolling.type = RollingFile
appender.rolling.name = rolling
appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_server.log
appender.rolling.layout.type = PatternLayout
appender.rolling.layout.pattern =%notEmpty{%node_name} %notEmpty{%node_and_cluster_id} %notEmpty{${sys:es.logs.cluster_name}} %m%n
appender.rolling.layout.pattern =%notEmpty{%node_name} %notEmpty{%node_and_cluster_id} %notEmpty{${sys:es.logs.cluster_name}} %m%n
appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.log.gz
appender.rolling.policies.type = Policies

View File

@ -25,6 +25,7 @@ import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configurator;
import org.elasticsearch.cli.UserException;
import org.elasticsearch.common.CheckedConsumer;
import org.elasticsearch.common.io.PathUtils;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.common.util.concurrent.ThreadContext;
@ -77,36 +78,48 @@ public class JsonLoggerTests extends ESTestCase {
Configurator.shutdown(context);
super.tearDown();
}
public void testDeprecatedMessage() throws IOException {
final Logger testLogger = LogManager.getLogger("test");
testLogger.info(new DeprecatedMessage("someId", "deprecated message1"));
final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_deprecated.json");
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());
public void testDeprecatedMessage() throws Exception {
withThreadContext(threadContext -> {
threadContext.putHeader(Task.X_OPAQUE_ID, "someId");
final DeprecationLogger testLogger = DeprecationLogger.getLogger("test");
testLogger.deprecate("someKey", "deprecated message1");
assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message1"),
hasEntry("x-opaque-id", "someId"))
)
final Path path = PathUtils.get(
System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_deprecated.json"
);
}
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream.collect(Collectors.toList());
assertThat(
jsonLogs,
contains(
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "DEPRECATION"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message1"),
hasEntry("x-opaque-id", "someId")
)
)
);
}
assertWarnings("deprecated message1");
});
}
public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
final Logger testLogger = LogManager.getLogger("test");
testLogger.info(new DeprecatedMessage("someId", "deprecated message1"));
testLogger.info(new DeprecatedMessage("", "deprecated message2"));
testLogger.info(new DeprecatedMessage(null, "deprecated message3"));
testLogger.info(new DeprecatedMessage("key", "someId", "deprecated message1"));
testLogger.info(new DeprecatedMessage("key", "", "deprecated message2"));
// This message will be filtered out by the RateLimitingFilter because an empty ID is the same as a null one.
testLogger.info(new DeprecatedMessage("key", null, "deprecated message3"));
testLogger.info("deprecated message4");
final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
@ -133,15 +146,6 @@ public class JsonLoggerTests extends ESTestCase {
hasEntry("message", "deprecated message2"),
not(hasKey("x-opaque-id"))
),
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message3"),
not(hasKey("x-opaque-id"))
),
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
@ -269,14 +273,12 @@ public class JsonLoggerTests extends ESTestCase {
}
public void testDuplicateLogMessages() throws IOException {
public void testDuplicateLogMessages() throws Exception {
final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger("test");
// For the same key and X-Opaque-ID deprecation should be once
ThreadContext threadContext = new ThreadContext(Settings.EMPTY);
try (ThreadContext.StoredContext ignore = threadContext.stashContext()) {
withThreadContext(threadContext -> {
threadContext.putHeader(Task.X_OPAQUE_ID, "ID1");
DeprecationLogger.setThreadContext(threadContext);
deprecationLogger.deprecate("key", "message1");
deprecationLogger.deprecate("key", "message2");
assertWarnings("message1", "message2");
@ -290,7 +292,7 @@ public class JsonLoggerTests extends ESTestCase {
assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "WARN"),
hasEntry("level", "DEPRECATION"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
@ -299,51 +301,48 @@ public class JsonLoggerTests extends ESTestCase {
)
);
}
} finally {
DeprecationLogger.removeThreadContext(threadContext);
}
});
// For the same key and different X-Opaque-ID should be multiple times per key/x-opaque-id
//continuing with message1-ID1 in logs already, adding a new deprecation log line with message2-ID2
try (ThreadContext.StoredContext ignore = threadContext.stashContext()) {
withThreadContext(threadContext -> {
threadContext.putHeader(Task.X_OPAQUE_ID, "ID2");
DeprecationLogger.setThreadContext(threadContext);
deprecationLogger.deprecate("key", "message1");
deprecationLogger.deprecate("key", "message2");
assertWarnings("message1", "message2");
final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_deprecated.json");
final Path path = PathUtils.get(
System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_deprecated.json"
);
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());
List<Map<String, String>> jsonLogs = stream.collect(Collectors.toList());
assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "WARN"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "message1"),
hasEntry("x-opaque-id", "ID1")
),
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "WARN"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "message1"),
hasEntry("x-opaque-id", "ID2")
)
assertThat(
jsonLogs,
contains(
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "DEPRECATION"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "message1"),
hasEntry("x-opaque-id", "ID1")
),
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "DEPRECATION"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "message1"),
hasEntry("x-opaque-id", "ID2")
)
)
);
}
} finally {
DeprecationLogger.removeThreadContext(threadContext);
}
});
}
private List<JsonLogLine> collectLines(Stream<JsonLogLine> stream) {
@ -396,4 +395,14 @@ public class JsonLoggerTests extends ESTestCase {
}
};
}
private void withThreadContext(CheckedConsumer<ThreadContext, Exception> consumer) throws Exception {
final ThreadContext threadContext = new ThreadContext(Settings.EMPTY);
try (ThreadContext.StoredContext ignore = threadContext.stashContext()) {
HeaderWarning.setThreadContext(threadContext);
consumer.accept(threadContext);
} finally {
HeaderWarning.removeThreadContext(threadContext);
}
}
}

View File

@ -15,12 +15,14 @@ appender.deprecated.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sy
appender.deprecated.layout.type = ESJsonLayout
appender.deprecated.layout.type_name = deprecation
appender.deprecated.layout.esmessagefields = x-opaque-id
appender.deprecated.filter.rate_limit.type = RateLimitingFilter
appender.deprecatedconsole.type = Console
appender.deprecatedconsole.name = deprecatedconsole
appender.deprecatedconsole.layout.type = ESJsonLayout
appender.deprecatedconsole.layout.type_name = deprecation
appender.deprecatedconsole.layout.esmessagefields = x-opaque-id
appender.deprecatedconsole.filter.rate_limit.type = RateLimitingFilter
appender.index_search_slowlog_rolling.type = File
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
@ -34,12 +36,16 @@ rootLogger.level = info
rootLogger.appenderRef.console.ref = console
rootLogger.appenderRef.file.ref = file
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = deprecation.test
logger.deprecation.level = warn
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.console.ref = console
logger.deprecation.appenderRef.file.ref = file
logger.deprecation.appenderRef.deprecation_rolling.ref = deprecated
logger.deprecation.appenderRef.deprecatedconsole.ref = deprecatedconsole
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false
logger.test.name = test

View File

@ -22,7 +22,6 @@ package org.elasticsearch.common.logging;
import org.elasticsearch.common.Strings;
import org.elasticsearch.common.collect.MapBuilder;
import java.util.Collections;
import java.util.Map;
/**
@ -30,16 +29,20 @@ import java.util.Map;
* Carries x-opaque-id field if provided in the headers. Will populate the x-opaque-id field in JSON logs.
*/
public class DeprecatedMessage extends ESLogMessage {
public static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id";
public DeprecatedMessage(String xOpaqueId, String messagePattern, Object... args) {
super(fieldMap(xOpaqueId), messagePattern, args);
public DeprecatedMessage(String key, String xOpaqueId, String messagePattern, Object... args) {
super(fieldMap(key, xOpaqueId), messagePattern, args);
}
private static Map<String, Object> fieldMap(String xOpaqueId) {
if (Strings.isNullOrEmpty(xOpaqueId)) {
return Collections.emptyMap();
private static Map<String, Object> fieldMap(String key, String xOpaqueId) {
final MapBuilder<String, Object> builder = MapBuilder.newMapBuilder();
if (Strings.isNullOrEmpty(key) == false) {
builder.put("key", key);
}
return MapBuilder.<String,Object>newMapBuilder().put("x-opaque-id", xOpaqueId).immutableMap();
if (Strings.isNullOrEmpty(xOpaqueId) == false) {
builder.put(X_OPAQUE_ID_FIELD_NAME, xOpaqueId);
}
return builder.immutableMap();
}
}

View File

@ -19,26 +19,44 @@
package org.elasticsearch.common.logging;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.elasticsearch.common.SuppressLoggerChecks;
import org.elasticsearch.common.util.concurrent.ThreadContext;
/**
* A logger that logs deprecation notices. Logger should be initialized with a parent logger which name will be used
* for deprecation logger. For instance <code>new DeprecationLogger("org.elasticsearch.test.SomeClass")</code> will
* result in a deprecation logger with name <code>org.elasticsearch.deprecation.test.SomeClass</code>. This allows to use
* for deprecation logger. For instance <code>DeprecationLogger.getLogger("org.elasticsearch.test.SomeClass")</code> will
* result in a deprecation logger with name <code>org.elasticsearch.deprecation.test.SomeClass</code>. This allows to use a
* <code>deprecation</code> logger defined in log4j2.properties.
*
* Deprecation logs are written to deprecation log file - defined in log4j2.properties, as well as warnings added to a response header.
* All deprecation usages are throttled basing on a key. Key is a string provided in an argument and can be prefixed with
* <code>X-Opaque-Id</code>. This allows to throttle deprecations per client usage.
* <code>deprecationLogger.deprecate("key","message {}", "param");</code>
*
* @see ThrottlingAndHeaderWarningLogger for throttling and header warnings implementation details
* <p>
* Logs are emitted at the custom {@link #DEPRECATION} level, and routed wherever they need to go using log4j. For example,
* to disk using a rolling file appender, or added as a response header using {@link HeaderWarningAppender}.
* <p>
* Deprecation messages include a <code>key</code>, which is used for rate-limiting purposes. The log4j configuration
* uses {@link RateLimitingFilter} to prevent the same message being logged repeatedly in a short span of time. This
* key is combined with the <code>X-Opaque-Id</code> request header value, if supplied, which allows for per-client
* message limiting.
*/
public class DeprecationLogger {
private final ThrottlingAndHeaderWarningLogger deprecationLogger;
/**
* Deprecation messages are logged at this level.
*/
public static Level DEPRECATION = Level.forName("DEPRECATION", Level.WARN.intLevel() + 1);
private final Logger logger;
private DeprecationLogger(Logger parentLogger) {
this.logger = parentLogger;
}
/**
* Creates a new deprecation logger for the supplied class. Internally, it delegates to
* {@link #getLogger(String)}, passing the full class name.
*/
public static DeprecationLogger getLogger(Class<?> aClass) {
return getLogger(toLoggerName(aClass));
}
/**
* Creates a new deprecation logger based on the parent logger. Automatically
@ -46,19 +64,11 @@ public class DeprecationLogger {
* it replaces "org.elasticsearch" with "org.elasticsearch.deprecation" to maintain
* the "org.elasticsearch" namespace.
*/
private DeprecationLogger(Logger parentLogger) {
deprecationLogger = new ThrottlingAndHeaderWarningLogger(parentLogger);
}
public static DeprecationLogger getLogger(Class<?> aClass) {
return getLogger(toLoggerName(aClass));
}
public static DeprecationLogger getLogger(String name) {
return new DeprecationLogger(deprecatedLoggerName(name));
return new DeprecationLogger(getDeprecatedLoggerForName(name));
}
private static Logger deprecatedLoggerName(String name) {
private static Logger getDeprecatedLoggerForName(String name) {
if (name.startsWith("org.elasticsearch")) {
name = name.replace("org.elasticsearch.", "org.elasticsearch.deprecation.");
} else {
@ -72,23 +82,22 @@ public class DeprecationLogger {
return canonicalName != null ? canonicalName : cls.getName();
}
public static void setThreadContext(ThreadContext threadContext) {
HeaderWarning.setThreadContext(threadContext);
}
public static void removeThreadContext(ThreadContext threadContext) {
HeaderWarning.removeThreadContext(threadContext);
}
/**
* Logs a deprecation message, adding a formatted warning message as a response header on the thread context.
* The deprecation message will be throttled to deprecation log.
* Logs a message at the {@link #DEPRECATION} level. The message is also sent to the header warning logger,
* so that it can be returned to the client.
*/
@SuppressLoggerChecks(reason = "Safely delegates to a deprecated message")
public void deprecate(final String key, final String msg, final Object... params) {
String opaqueId = HeaderWarning.getXOpaqueId();
ESLogMessage deprecationMessage = new DeprecatedMessage(opaqueId, msg, params);
deprecationLogger.throttleLogAndAddWarning(key, deprecationMessage);
public DeprecationLoggerBuilder deprecate(final String key, final String msg, final Object... params) {
return new DeprecationLoggerBuilder().withDeprecation(key, msg, params);
}
public class DeprecationLoggerBuilder {
public DeprecationLoggerBuilder withDeprecation(String key, String msg, Object[] params) {
ESLogMessage deprecationMessage = new DeprecatedMessage(key, HeaderWarning.getXOpaqueId(), msg, params);
logger.log(DEPRECATION, deprecationMessage);
return this;
}
}
}

View File

@ -0,0 +1,63 @@
/*
* 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.Appender;
import org.apache.logging.log4j.core.Core;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.message.Message;
@Plugin(name = "HeaderWarningAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class HeaderWarningAppender extends AbstractAppender {
public HeaderWarningAppender(String name, Filter filter) {
super(name, filter, null);
}
@Override
public void append(LogEvent event) {
final Message message = event.getMessage();
if (message instanceof ESLogMessage) {
final ESLogMessage esLogMessage = (ESLogMessage) message;
String messagePattern = esLogMessage.getMessagePattern();
Object[] arguments = esLogMessage.getArguments();
HeaderWarning.addWarning(messagePattern, arguments);
} else {
final String formattedMessage = event.getMessage().getFormattedMessage();
HeaderWarning.addWarning(formattedMessage);
}
}
@PluginFactory
public static HeaderWarningAppender createAppender(
@PluginAttribute("name") String name,
@PluginElement("filter") Filter filter
) {
return new HeaderWarningAppender(name, filter);
}
}

View File

@ -0,0 +1,97 @@
/*
* 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.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.config.Node;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.filter.AbstractFilter;
import org.apache.logging.log4j.message.Message;
import java.util.Collections;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.Set;
import static org.elasticsearch.common.logging.DeprecatedMessage.X_OPAQUE_ID_FIELD_NAME;
@Plugin(name = "RateLimitingFilter", category = Node.CATEGORY, elementType = Filter.ELEMENT_TYPE)
public class RateLimitingFilter extends AbstractFilter {
private final Set<String> lruKeyCache = Collections.newSetFromMap(Collections.synchronizedMap(new LinkedHashMap<String, Boolean>() {
@Override
protected boolean removeEldestEntry(final Map.Entry<String, Boolean> eldest) {
return size() > 128;
}
}));
public RateLimitingFilter() {
this(Result.ACCEPT, Result.DENY);
}
public RateLimitingFilter(Result onMatch, Result onMismatch) {
super(onMatch, onMismatch);
}
/**
* Clears the cache of previously-seen keys.
*/
public void reset() {
this.lruKeyCache.clear();
}
public Result filter(Message message) {
if (message instanceof ESLogMessage) {
final ESLogMessage esLogMessage = (ESLogMessage) message;
String xOpaqueId = esLogMessage.getValueFor(X_OPAQUE_ID_FIELD_NAME);
final String key = esLogMessage.getValueFor("key");
return lruKeyCache.add(xOpaqueId + key) ? Result.ACCEPT : Result.DENY;
} else {
return Result.NEUTRAL;
}
}
@Override
public Result filter(LogEvent event) {
return filter(event.getMessage());
}
@Override
public Result filter(Logger logger, Level level, Marker marker, Message msg, Throwable t) {
return filter(msg);
}
@PluginFactory
public static RateLimitingFilter createFilter(
@PluginAttribute("onMatch") final Result match,
@PluginAttribute("onMismatch") final Result mismatch
) {
return new RateLimitingFilter(match, mismatch);
}
}

View File

@ -1,49 +0,0 @@
/*
* 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.Logger;
/**
* This class wraps both <code>HeaderWarningLogger</code> and <code>ThrottlingLogger</code>
* which is a common use case across Elasticsearch
*/
class ThrottlingAndHeaderWarningLogger {
private final ThrottlingLogger throttlingLogger;
ThrottlingAndHeaderWarningLogger(Logger logger) {
this.throttlingLogger = new ThrottlingLogger(logger);
}
/**
* Adds a formatted warning message as a response header on the thread context, and logs a message if the associated key has
* not recently been seen.
*
* @param key the key used to determine if this message should be logged
* @param message the message to log
*/
void throttleLogAndAddWarning(final String key, ESLogMessage message) {
String messagePattern = message.getMessagePattern();
Object[] arguments = message.getArguments();
HeaderWarning.addWarning(messagePattern, arguments);
throttlingLogger.throttleLog(key, message);
}
}

View File

@ -1,79 +0,0 @@
/*
* 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.Logger;
import org.apache.logging.log4j.message.Message;
import org.elasticsearch.common.SuppressLoggerChecks;
import java.security.AccessController;
import java.security.PrivilegedAction;
import java.util.Collections;
import java.util.LinkedHashMap;
import java.util.Map;
import java.util.Set;
/**
* TODO wrapping logging this way limits the usage of %location. It will think this is used from that class.
* <p>
* This is a wrapper around a logger that allows to throttle log messages.
* In order to throttle a key has to be used and throttling happens per each key combined with X-Opaque-Id.
* X-Opaque-Id allows throttling per user. This value is set in ThreadContext from X-Opaque-Id HTTP header.
* <p>
* The throttling algorithm is relying on LRU set of keys which evicts entries when its size is &gt; 128.
* When a log with a key is emitted, it won't be logged again until the set reaches size 128 and the key is removed from the set.
*
* @see HeaderWarning
*/
class ThrottlingLogger {
// LRU set of keys used to determine if a message should be emitted to the logs
private final Set<String> keys = Collections.newSetFromMap(Collections.synchronizedMap(new LinkedHashMap<String, Boolean>() {
@Override
protected boolean removeEldestEntry(final Map.Entry<String, Boolean> eldest) {
return size() > 128;
}
}));
private final Logger logger;
ThrottlingLogger(Logger logger) {
this.logger = logger;
}
void throttleLog(String key, Message message) {
String xOpaqueId = HeaderWarning.getXOpaqueId();
boolean shouldLog = keys.add(xOpaqueId + key);
if (shouldLog) {
log(message);
}
}
private void log(Message message) {
AccessController.doPrivileged(new PrivilegedAction<Void>() {
@SuppressLoggerChecks(reason = "safely delegates to logger")
@Override
public Void run() {
logger.warn(message);
return null;
}
});
}
}

View File

@ -20,75 +20,15 @@
package org.elasticsearch.common.logging;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.simple.SimpleLoggerContext;
import org.apache.logging.log4j.simple.SimpleLoggerContextFactory;
import org.apache.logging.log4j.spi.ExtendedLogger;
import org.apache.logging.log4j.spi.LoggerContext;
import org.apache.logging.log4j.spi.LoggerContextFactory;
import org.elasticsearch.common.SuppressLoggerChecks;
import org.apache.logging.log4j.core.LoggerContext;
import org.elasticsearch.test.ESTestCase;
import java.net.URI;
import java.security.AccessControlContext;
import java.security.AccessController;
import java.security.Permissions;
import java.security.PrivilegedAction;
import java.security.ProtectionDomain;
import java.util.concurrent.atomic.AtomicBoolean;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.core.Is.is;
import static org.mockito.Matchers.any;
import static org.mockito.Mockito.doAnswer;
import static org.mockito.Mockito.mock;
public class DeprecationLoggerTests extends ESTestCase {
@SuppressLoggerChecks(reason = "Safe as this is using mockito")
public void testLogPermissions() {
AtomicBoolean supplierCalled = new AtomicBoolean(false);
// mocking the logger used inside DeprecationLogger requires heavy hacking...
ExtendedLogger mockLogger = mock(ExtendedLogger.class);
doAnswer(invocationOnMock -> {
supplierCalled.set(true);
createTempDir(); // trigger file permission, like rolling logs would
return null;
}).when(mockLogger).warn(new DeprecatedMessage(any(), "foo"));
final LoggerContext context = new SimpleLoggerContext() {
@Override
public ExtendedLogger getLogger(String name) {
return mockLogger;
}
};
final LoggerContextFactory originalFactory = LogManager.getFactory();
try {
LogManager.setFactory(new SimpleLoggerContextFactory() {
@Override
public LoggerContext getContext(String fqcn, ClassLoader loader, Object externalContext, boolean currentContext,
URI configLocation, String name) {
return context;
}
});
DeprecationLogger deprecationLogger = DeprecationLogger.getLogger("logger");
AccessControlContext noPermissionsAcc = new AccessControlContext(
new ProtectionDomain[]{new ProtectionDomain(null, new Permissions())}
);
AccessController.doPrivileged((PrivilegedAction<Void>) () -> {
deprecationLogger.deprecate("testLogPermissions_key", "foo {}", "bar");
return null;
}, noPermissionsAcc);
assertThat("supplier called", supplierCalled.get(), is(true));
assertWarnings("foo bar");
} finally {
LogManager.setFactory(originalFactory);
}
}
public void testMultipleSlowLoggersUseSingleLog4jLogger() {
org.apache.logging.log4j.core.LoggerContext context = (org.apache.logging.log4j.core.LoggerContext) LogManager.getContext(false);
LoggerContext context = (LoggerContext) LogManager.getContext(false);
DeprecationLogger deprecationLogger = DeprecationLogger.getLogger(DeprecationLoggerTests.class);
int numberOfLoggersBefore = context.getLoggers().size();
@ -97,7 +37,7 @@ public class DeprecationLoggerTests extends ESTestCase {
}
DeprecationLogger deprecationLogger2 = DeprecationLogger.getLogger(LoggerTest.class);
context = (org.apache.logging.log4j.core.LoggerContext) LogManager.getContext(false);
context = (LoggerContext) LogManager.getContext(false);
int numberOfLoggersAfter = context.getLoggers().size();
assertThat(numberOfLoggersAfter, equalTo(numberOfLoggersBefore+1));

View File

@ -0,0 +1,161 @@
/*
* 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.message.Message;
import org.apache.logging.log4j.message.SimpleMessage;
import org.elasticsearch.test.ESTestCase;
import org.junit.After;
import org.junit.Before;
import static org.apache.logging.log4j.core.Filter.Result;
import static org.hamcrest.Matchers.equalTo;
public class RateLimitingFilterTests extends ESTestCase {
private RateLimitingFilter filter;
@Before
public void setup() {
this.filter = new RateLimitingFilter();
filter.start();
}
@After
public void cleanup() {
this.filter.stop();
}
/**
* Check that messages are rate-limited by their key.
*/
public void testMessagesAreRateLimitedByKey() {
// Fill up the cache
for (int i = 0; i < 128; i++) {
Message message = new DeprecatedMessage("key " + i, "", "msg " + i);
assertThat("Expected key" + i + " to be accepted", filter.filter(message), equalTo(Result.ACCEPT));
}
// Should be rate-limited because it's still in the cache
Message message = new DeprecatedMessage("key 0", "", "msg " + 0);
assertThat(filter.filter(message), equalTo(Result.DENY));
// Filter a message with a previously unseen key, in order to evict key0 as it's the oldest
message = new DeprecatedMessage("key 129", "", "msg " + 129);
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
// Should be allowed because key0 was evicted from the cache
message = new DeprecatedMessage("key 0", "", "msg " + 0);
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
}
/**
* Check that messages are rate-limited by their x-opaque-id value
*/
public void testMessagesAreRateLimitedByXOpaqueId() {
// Fill up the cache
for (int i = 0; i < 128; i++) {
Message message = new DeprecatedMessage("", "id " + i, "msg " + i);
assertThat("Expected key" + i + " to be accepted", filter.filter(message), equalTo(Result.ACCEPT));
}
// Should be rate-limited because it's still in the cache
Message message = new DeprecatedMessage("", "id 0", "msg 0");
assertThat(filter.filter(message), equalTo(Result.DENY));
// Filter a message with a previously unseen key, in order to evict key0 as it's the oldest
message = new DeprecatedMessage("", "id 129", "msg 129");
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
// Should be allowed because key0 was evicted from the cache
message = new DeprecatedMessage("", "id 0", "msg 0");
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
}
/**
* Check that messages are rate-limited by their key and x-opaque-id value
*/
public void testMessagesAreRateLimitedByKeyAndXOpaqueId() {
// Fill up the cache
for (int i = 0; i < 128; i++) {
Message message = new DeprecatedMessage("key " + i, "opaque-id " + i, "msg " + i);
assertThat("Expected key" + i + " to be accepted", filter.filter(message), equalTo(Result.ACCEPT));
}
// Should be rate-limited because it's still in the cache
Message message = new DeprecatedMessage("key 0", "opaque-id 0", "msg 0");
assertThat(filter.filter(message), equalTo(Result.DENY));
// Filter a message with a previously unseen key, in order to evict key0 as it's the oldest
message = new DeprecatedMessage("key 129", "opaque-id 129", "msg 129");
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
// Should be allowed because key 0 was evicted from the cache
message = new DeprecatedMessage("key 0", "opaque-id 0", "msg 0");
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
}
/**
* Check that it is the combination of key and x-opaque-id that rate-limits messages, by varying each
* independently and checking that a message is not filtered.
*/
public void testVariationsInKeyAndXOpaqueId() {
Message message = new DeprecatedMessage("key 0", "opaque-id 0", "msg 0");
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
message = new DeprecatedMessage("key 0", "opaque-id 0", "msg 0");
// Rejected because the "x-opaque-id" and "key" values are the same as above
assertThat(filter.filter(message), equalTo(Result.DENY));
message = new DeprecatedMessage("key 1", "opaque-id 0", "msg 0");
// Accepted because the "key" value is different
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
message = new DeprecatedMessage("key 0", "opaque-id 1", "msg 0");
// Accepted because the "x-opaque-id" value is different
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
}
/**
* Check that rate-limiting is not applied to messages if they are not an EsLogMessage.
*/
public void testOnlyEsMessagesAreFiltered() {
Message message = new SimpleMessage("a message");
assertThat(filter.filter(message), equalTo(Result.NEUTRAL));
}
/**
* Check that the filter can be reset, so that previously-seen keys are treated as new keys.
*/
public void testFilterCanBeReset() {
final Message message = new DeprecatedMessage("key", "", "msg");
// First time, the message is a allowed
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
// Second time, it is filtered out
assertThat(filter.filter(message), equalTo(Result.DENY));
filter.reset();
// Third time, it is allowed again
assertThat(filter.filter(message), equalTo(Result.ACCEPT));
}
}

View File

@ -67,6 +67,7 @@ import org.elasticsearch.common.io.stream.StreamInput;
import org.elasticsearch.common.io.stream.Writeable;
import org.elasticsearch.common.joda.JodaDeprecationPatterns;
import org.elasticsearch.common.logging.HeaderWarning;
import org.elasticsearch.common.logging.HeaderWarningAppender;
import org.elasticsearch.common.logging.LogConfigurator;
import org.elasticsearch.common.logging.Loggers;
import org.elasticsearch.common.settings.Setting;
@ -183,6 +184,7 @@ public abstract class ESTestCase extends LuceneTestCase {
private static final AtomicInteger portGenerator = new AtomicInteger();
private static final Collection<String> nettyLoggedLeaks = new ArrayList<>();
private HeaderWarningAppender headerWarningAppender;
@AfterClass
public static void resetPortCounter() {
@ -338,6 +340,21 @@ public abstract class ESTestCase extends LuceneTestCase {
}
}
@Before
public void setHeaderWarningAppender() {
this.headerWarningAppender = HeaderWarningAppender.createAppender("header_warning", null);
this.headerWarningAppender.start();
Loggers.addAppender(LogManager.getLogger("org.elasticsearch.deprecation"), this.headerWarningAppender);
}
@After
public void removeHeaderWarningAppender() {
if (this.headerWarningAppender != null) {
Loggers.removeAppender(LogManager.getLogger("org.elasticsearch.deprecation"), this.headerWarningAppender);
this.headerWarningAppender = null;
}
}
@Before
public final void before() {
logger.info("{}before test", getTestParamsForLogging());

View File

@ -5,3 +5,10 @@ appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%test_thread_i
rootLogger.level = ${sys:tests.es.logger.level:-info}
rootLogger.appenderRef.console.ref = console
appender.header_warning.type = HeaderWarningAppender
appender.header_warning.name = header_warning
logger.deprecation.name = org.elasticsearch.deprecation
logger.deprecation.level = deprecation
logger.deprecation.appenderRef.header_warning.ref = header_warning

View File

@ -21,7 +21,7 @@ import org.elasticsearch.index.query.QueryShardContext;
import java.io.IOException;
public class DeprecatedQueryBuilder extends AbstractQueryBuilder<DeprecatedQueryBuilder> {
private static final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger("Deprecated");
private static final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger(DeprecatedQueryBuilder.class);
public static final String NAME = "deprecated";