From ff6c071275b1b973b817b88b41d9d43b0b2f1e41 Mon Sep 17 00:00:00 2001 From: Rory Hunter Date: Mon, 31 Aug 2020 12:42:04 +0100 Subject: [PATCH] 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. --- .../src/docker/config/oss/log4j2.properties | 7 +- distribution/src/config/log4j2.properties | 7 +- .../common/logging/EvilLoggerTests.java | 55 +----- .../common/logging/config/log4j2.properties | 7 +- .../logging/deprecation/log4j2.properties | 7 +- .../logging/no_node_name/log4j2.properties | 7 +- .../common/logging/settings/log4j2.properties | 7 +- qa/logging-config/custom-log4j2.properties | 2 +- .../common/logging/JsonLoggerTests.java | 145 ++++++++-------- .../logging/json_layout/log4j2.properties | 8 +- .../common/logging/DeprecatedMessage.java | 19 ++- .../common/logging/DeprecationLogger.java | 83 +++++---- .../common/logging/HeaderWarningAppender.java | 63 +++++++ .../common/logging/RateLimitingFilter.java | 97 +++++++++++ .../ThrottlingAndHeaderWarningLogger.java | 49 ------ .../common/logging/ThrottlingLogger.java | 79 --------- .../logging/DeprecationLoggerTests.java | 66 +------ .../logging/RateLimitingFilterTests.java | 161 ++++++++++++++++++ .../org/elasticsearch/test/ESTestCase.java | 17 ++ .../src/main/resources/log4j2-test.properties | 7 + .../query/DeprecatedQueryBuilder.java | 2 +- 21 files changed, 534 insertions(+), 361 deletions(-) create mode 100644 server/src/main/java/org/elasticsearch/common/logging/HeaderWarningAppender.java create mode 100644 server/src/main/java/org/elasticsearch/common/logging/RateLimitingFilter.java delete mode 100644 server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java delete mode 100644 server/src/main/java/org/elasticsearch/common/logging/ThrottlingLogger.java create mode 100644 server/src/test/java/org/elasticsearch/common/logging/RateLimitingFilterTests.java diff --git a/distribution/docker/src/docker/config/oss/log4j2.properties b/distribution/docker/src/docker/config/oss/log4j2.properties index a52e500310b..4a03bc281a9 100644 --- a/distribution/docker/src/docker/config/oss/log4j2.properties +++ b/distribution/docker/src/docker/config/oss/log4j2.properties @@ -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 diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index be4ffc03f20..b9ad7112116 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -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 #################### diff --git a/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java b/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java index dcb82228f48..9628beb25b1 100644 --- a/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java +++ b/qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java @@ -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 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 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."); } diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties index 2c9f48a359a..255c53a8d7d 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties @@ -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 diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties index 388c9f9b2fc..e488da2f95f 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties @@ -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 diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties index fd7af2ce731..1a1f70c7a26 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties @@ -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 diff --git a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/settings/log4j2.properties b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/settings/log4j2.properties index abe4a279dc8..284b7bda1f7 100644 --- a/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/settings/log4j2.properties +++ b/qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/settings/log4j2.properties @@ -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 diff --git a/qa/logging-config/custom-log4j2.properties b/qa/logging-config/custom-log4j2.properties index b225d7cd550..21f834e58f5 100644 --- a/qa/logging-config/custom-log4j2.properties +++ b/qa/logging-config/custom-log4j2.properties @@ -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 diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java index 39e6e68e40b..4994a6888be 100644 --- a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java +++ b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java @@ -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> stream = JsonLogsStream.mapStreamFrom(path)) { - List> 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> stream = JsonLogsStream.mapStreamFrom(path)) { + List> 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> stream = JsonLogsStream.mapStreamFrom(path)) { - List> jsonLogs = stream - .collect(Collectors.toList()); + List> 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 collectLines(Stream stream) { @@ -396,4 +395,14 @@ public class JsonLoggerTests extends ESTestCase { } }; } + + private void withThreadContext(CheckedConsumer 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); + } + } } diff --git a/qa/logging-config/src/test/resources/org/elasticsearch/common/logging/json_layout/log4j2.properties b/qa/logging-config/src/test/resources/org/elasticsearch/common/logging/json_layout/log4j2.properties index 14400177c18..708d3924749 100644 --- a/qa/logging-config/src/test/resources/org/elasticsearch/common/logging/json_layout/log4j2.properties +++ b/qa/logging-config/src/test/resources/org/elasticsearch/common/logging/json_layout/log4j2.properties @@ -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 diff --git a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java index 5d66d043e84..f34e53eaddd 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -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 fieldMap(String xOpaqueId) { - if (Strings.isNullOrEmpty(xOpaqueId)) { - return Collections.emptyMap(); + private static Map fieldMap(String key, String xOpaqueId) { + final MapBuilder builder = MapBuilder.newMapBuilder(); + if (Strings.isNullOrEmpty(key) == false) { + builder.put("key", key); } - - return MapBuilder.newMapBuilder().put("x-opaque-id", xOpaqueId).immutableMap(); + if (Strings.isNullOrEmpty(xOpaqueId) == false) { + builder.put(X_OPAQUE_ID_FIELD_NAME, xOpaqueId); + } + return builder.immutableMap(); } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java index 285fdd39171..fcc3b2b0995 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java @@ -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 new DeprecationLogger("org.elasticsearch.test.SomeClass") will - * result in a deprecation logger with name org.elasticsearch.deprecation.test.SomeClass. This allows to use + * for deprecation logger. For instance DeprecationLogger.getLogger("org.elasticsearch.test.SomeClass") will + * result in a deprecation logger with name org.elasticsearch.deprecation.test.SomeClass. This allows to use a * deprecation 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 - * X-Opaque-Id. This allows to throttle deprecations per client usage. - * deprecationLogger.deprecate("key","message {}", "param"); - * - * @see ThrottlingAndHeaderWarningLogger for throttling and header warnings implementation details + *

+ * 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}. + *

+ * Deprecation messages include a key, 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 X-Opaque-Id 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; + } + } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/HeaderWarningAppender.java b/server/src/main/java/org/elasticsearch/common/logging/HeaderWarningAppender.java new file mode 100644 index 00000000000..d793b31e695 --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/HeaderWarningAppender.java @@ -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); + } +} diff --git a/server/src/main/java/org/elasticsearch/common/logging/RateLimitingFilter.java b/server/src/main/java/org/elasticsearch/common/logging/RateLimitingFilter.java new file mode 100644 index 00000000000..d471e1ae5d8 --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/RateLimitingFilter.java @@ -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 lruKeyCache = Collections.newSetFromMap(Collections.synchronizedMap(new LinkedHashMap() { + @Override + protected boolean removeEldestEntry(final Map.Entry 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); + } +} diff --git a/server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java b/server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java deleted file mode 100644 index 0dec2b45d02..00000000000 --- a/server/src/main/java/org/elasticsearch/common/logging/ThrottlingAndHeaderWarningLogger.java +++ /dev/null @@ -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 HeaderWarningLogger and ThrottlingLogger - * 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); - } - -} diff --git a/server/src/main/java/org/elasticsearch/common/logging/ThrottlingLogger.java b/server/src/main/java/org/elasticsearch/common/logging/ThrottlingLogger.java deleted file mode 100644 index 072f7c5c05a..00000000000 --- a/server/src/main/java/org/elasticsearch/common/logging/ThrottlingLogger.java +++ /dev/null @@ -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. - *

- * 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. - *

- * The throttling algorithm is relying on LRU set of keys which evicts entries when its size is > 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 keys = Collections.newSetFromMap(Collections.synchronizedMap(new LinkedHashMap() { - @Override - protected boolean removeEldestEntry(final Map.Entry 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() { - @SuppressLoggerChecks(reason = "safely delegates to logger") - @Override - public Void run() { - logger.warn(message); - return null; - } - }); - } -} diff --git a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java index dd4c152bff2..a76afe9b4af 100644 --- a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java +++ b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java @@ -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) () -> { - 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)); diff --git a/server/src/test/java/org/elasticsearch/common/logging/RateLimitingFilterTests.java b/server/src/test/java/org/elasticsearch/common/logging/RateLimitingFilterTests.java new file mode 100644 index 00000000000..95f081f5f7b --- /dev/null +++ b/server/src/test/java/org/elasticsearch/common/logging/RateLimitingFilterTests.java @@ -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)); + } +} diff --git a/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java b/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java index a408672b25b..a14489c9ad2 100644 --- a/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java +++ b/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java @@ -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 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()); diff --git a/test/framework/src/main/resources/log4j2-test.properties b/test/framework/src/main/resources/log4j2-test.properties index 842c9c79d79..dae00805cb3 100644 --- a/test/framework/src/main/resources/log4j2-test.properties +++ b/test/framework/src/main/resources/log4j2-test.properties @@ -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 diff --git a/x-pack/plugin/async-search/qa/rest/src/main/java/org/elasticsearch/query/DeprecatedQueryBuilder.java b/x-pack/plugin/async-search/qa/rest/src/main/java/org/elasticsearch/query/DeprecatedQueryBuilder.java index 0ce331e793d..9cbf5f9bc97 100644 --- a/x-pack/plugin/async-search/qa/rest/src/main/java/org/elasticsearch/query/DeprecatedQueryBuilder.java +++ b/x-pack/plugin/async-search/qa/rest/src/main/java/org/elasticsearch/query/DeprecatedQueryBuilder.java @@ -21,7 +21,7 @@ import org.elasticsearch.index.query.QueryShardContext; import java.io.IOException; public class DeprecatedQueryBuilder extends AbstractQueryBuilder { - private static final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger("Deprecated"); + private static final DeprecationLogger deprecationLogger = DeprecationLogger.getLogger(DeprecatedQueryBuilder.class); public static final String NAME = "deprecated";