From 5d94cf629b5ad5cc5d8526904a1068d798130acf Mon Sep 17 00:00:00 2001 From: Rory Hunter Date: Mon, 24 Aug 2020 14:52:46 +0100 Subject: [PATCH 1/2] Implement deprecation logging using log4j 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 | 54 +----- .../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 | 8 +- .../common/logging/JsonLoggerTests.java | 172 +++++++++--------- .../logging/json_layout/log4j2.properties | 8 +- .../common/logging/DeprecatedMessage.java | 7 +- .../common/logging/DeprecationLogger.java | 71 ++++---- .../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 | 19 +- .../src/main/resources/log4j2-test.properties | 7 + .../query/DeprecatedQueryBuilder.java | 2 +- 21 files changed, 534 insertions(+), 371 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 a4e175edf431d..88b2d1d60254c 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 = ECSJsonLayout 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 2aac6f58dc4e6..c3867747d69e2 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -63,6 +63,7 @@ appender.deprecation_rolling.name = deprecation_rolling appender.deprecation_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.json appender.deprecation_rolling.layout.type = ECSJsonLayout appender.deprecation_rolling.layout.type_name = deprecation +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 @@ -70,11 +71,15 @@ 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 ################################################# 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 ######## 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 fdd64ef1e73d1..d0d5f062cf6ef 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.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 void testConcurrentDeprecationLogger() throws IOException, UserException, 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) { @@ -180,8 +181,8 @@ public void testConcurrentDeprecationLogger() throws IOException, UserException, 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); } @@ -191,49 +192,6 @@ public void testConcurrentDeprecationLogger() throws IOException, UserException, } - 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"); @@ -256,8 +214,8 @@ public void testDeprecatedSettings() throws IOException, UserException { 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 2c9f48a359a46..255c53a8d7dd8 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 388c9f9b2fc64..e488da2f95f58 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 fd7af2ce73136..1a1f70c7a2657 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 abe4a279dc820..284b7bda1f7b0 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 be4ffc03f20ef..0bd4479e1fe19 100644 --- a/qa/logging-config/custom-log4j2.properties +++ b/qa/logging-config/custom-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 @@ -78,6 +79,7 @@ appender.deprecation_rolling_old.name = deprecation_rolling_old appender.deprecation_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log appender.deprecation_rolling_old.layout.type = PatternLayout appender.deprecation_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n +appender.deprecation_rolling_old.filter.rate_limit.type = RateLimitingFilter appender.deprecation_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\ _deprecation-%i.log.gz @@ -87,10 +89,14 @@ appender.deprecation_rolling_old.policies.size.size = 1GB appender.deprecation_rolling_old.strategy.type = DefaultRolloverStrategy appender.deprecation_rolling_old.strategy.max = 4 ################################################# +appender.header_warning.type = HeaderWarningAppender +appender.header_warning.name = header_warning +################################################# 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/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 c2a467212c084..92d71b9a25343 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.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; @@ -48,6 +49,7 @@ import java.util.stream.Collectors; import java.util.stream.Stream; +import static org.elasticsearch.common.logging.DeprecationLogger.DEPRECATION; import static org.hamcrest.Matchers.allOf; import static org.hamcrest.Matchers.contains; import static org.hamcrest.Matchers.hasEntry; @@ -85,28 +87,38 @@ public void tearDown() throws Exception { super.tearDown(); } - public void testDeprecatedMessage() throws IOException { - final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info(DeprecatedMessage.of("someId","deprecated message1")); + 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"); - 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("log.level", "INFO"), - hasEntry("log.logger", "deprecation.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("log.level", "DEPRECATION"), + hasEntry("log.logger", "deprecation.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message1"), + hasEntry("x-opaque-id", "someId") + ) + ) + ); + } + + assertWarnings("deprecated message1"); + }); } public void testBuildingMessage() throws IOException { @@ -139,7 +151,7 @@ public void testBuildingMessage() throws IOException { } public void testCustomMessageWithMultipleFields() throws IOException { - // if a field is defined to be overriden, it has to always be overriden in that appender. + // If a field is defined to be overridden, it has to always be overridden in that appender. final Logger testLogger = LogManager.getLogger("test"); testLogger.info(new ESLogMessage("some message") .with("field1","value1") @@ -168,14 +180,17 @@ public void testCustomMessageWithMultipleFields() throws IOException { public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { - final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info( DeprecatedMessage.of("someId","deprecated message1")); - testLogger.info( DeprecatedMessage.of("","deprecated message2")); - testLogger.info( DeprecatedMessage.of(null,"deprecated message3")); - testLogger.info("deprecated message4"); + final DeprecationLogger testLogger = DeprecationLogger.getLogger("test"); + + testLogger.deprecate("a key", "deprecated message1"); + + // Also test that a message sent directly to the logger comes through + final Logger rawLogger = LogManager.getLogger("deprecation.test"); + rawLogger.log(DEPRECATION, "deprecated message2"); 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()); @@ -183,42 +198,27 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { assertThat(jsonLogs, contains( allOf( hasEntry("type", "deprecation"), - hasEntry("log.level", "INFO"), + hasEntry("log.level", "DEPRECATION"), hasEntry("log.logger", "deprecation.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message1"), - hasEntry("x-opaque-id", "someId")), - allOf( - hasEntry("type", "deprecation"), - hasEntry("log.level", "INFO"), - hasEntry("log.logger", "deprecation.test"), - hasEntry("cluster.name", "elasticsearch"), - hasEntry("node.name", "sample-name"), - hasEntry("message", "deprecated message2"), not(hasKey("x-opaque-id")) ), allOf( hasEntry("type", "deprecation"), - hasEntry("log.level", "INFO"), + hasEntry("log.level", "DEPRECATION"), hasEntry("log.logger", "deprecation.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), - hasEntry("message", "deprecated message3"), - not(hasKey("x-opaque-id")) - ), - allOf( - hasEntry("type", "deprecation"), - hasEntry("log.level", "INFO"), - hasEntry("log.logger", "deprecation.test"), - hasEntry("cluster.name", "elasticsearch"), - hasEntry("node.name", "sample-name"), - hasEntry("message", "deprecated message4"), + hasEntry("message", "deprecated message2"), not(hasKey("x-opaque-id")) ) ) ); } + + assertWarnings("deprecated message1", "deprecated message2"); } public void testJsonLayout() throws IOException { @@ -335,14 +335,12 @@ public void testJsonInStacktraceMessageIsNotSplitted() throws IOException { } - 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"); @@ -356,7 +354,7 @@ public void testDuplicateLogMessages() throws IOException { assertThat(jsonLogs, contains( allOf( hasEntry("type", "deprecation"), - hasEntry("log.level", "WARN"), + hasEntry("log.level", "DEPRECATION"), hasEntry("log.logger", "deprecation.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), @@ -365,51 +363,48 @@ public void testDuplicateLogMessages() throws IOException { ) ); } - } 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()); - - assertThat(jsonLogs, contains( - allOf( - hasEntry("type", "deprecation"), - hasEntry("log.level", "WARN"), - hasEntry("log.logger", "deprecation.test"), - hasEntry("cluster.name", "elasticsearch"), - hasEntry("node.name", "sample-name"), - hasEntry("message", "message1"), - hasEntry("x-opaque-id", "ID1") - ), - allOf( - hasEntry("type", "deprecation"), - hasEntry("log.level", "WARN"), - hasEntry("log.logger", "deprecation.test"), - hasEntry("cluster.name", "elasticsearch"), - hasEntry("node.name", "sample-name"), - hasEntry("message", "message1"), - hasEntry("x-opaque-id", "ID2") - ) + List> jsonLogs = stream.collect(Collectors.toList()); + + assertThat( + jsonLogs, + contains( + allOf( + hasEntry("type", "deprecation"), + hasEntry("log.level", "DEPRECATION"), + hasEntry("log.logger", "deprecation.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "message1"), + hasEntry("x-opaque-id", "ID1") + ), + allOf( + hasEntry("type", "deprecation"), + hasEntry("log.level", "DEPRECATION"), + hasEntry("log.logger", "deprecation.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) { @@ -492,4 +487,13 @@ protected List featureValueOf(JsonLogLine actual) { }; } + 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 46c91d4d89b8e..af9a0428d4f10 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,11 +15,13 @@ appender.deprecated.name = deprecated appender.deprecated.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecated.json appender.deprecated.layout.type = ECSJsonLayout appender.deprecated.layout.type_name = deprecation +appender.deprecated.filter.rate_limit.type = RateLimitingFilter appender.deprecatedconsole.type = Console appender.deprecatedconsole.name = deprecatedconsole appender.deprecatedconsole.layout.type = ECSJsonLayout appender.deprecatedconsole.layout.type_name = deprecation +appender.deprecatedconsole.filter.rate_limit.type = RateLimitingFilter rootLogger.level = info @@ -30,12 +32,16 @@ appender.plaintext.name = plaintext appender.plaintext.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_plaintext.json appender.plaintext.layout.type = PatternLayout appender.plaintext.layout.pattern =%m%n +appender.plaintext.filter.rate_limit.type = RateLimitingFilter +appender.header_warning.type = HeaderWarningAppender +appender.header_warning.name = header_warning logger.deprecation.name = deprecation.test -logger.deprecation.level = trace +logger.deprecation.level = deprecation 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 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 2cc882d61695a..b6d3cf3d7eedf 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -28,12 +28,12 @@ * Carries x-opaque-id field if provided in the headers. Will populate the x-opaque-id field in JSON logs. */ public class DeprecatedMessage { - private static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; + public static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; @SuppressLoggerChecks(reason = "safely delegates to logger") - public static ESLogMessage of(String xOpaqueId, String messagePattern, Object... args){ + public static ESLogMessage of(String key, String xOpaqueId, String messagePattern, Object... args){ if (Strings.isNullOrEmpty(xOpaqueId)) { - return new ESLogMessage(messagePattern, args); + return new ESLogMessage(messagePattern, args).field("key", key); } Object value = new Object() { @@ -44,6 +44,7 @@ public String toString() { } }; return new ESLogMessage(messagePattern, args) + .field("key", key) .field("message", value) .field(X_OPAQUE_ID_FIELD_NAME, xOpaqueId); } 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 3a5abf622b0cf..89e02344a84c3 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java @@ -19,45 +19,56 @@ 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.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; /** - * Creates a new deprecation logger based on the parent logger. Automatically - * prefixes the logger name with "deprecation", if it starts with "org.elasticsearch.", - * it replaces "org.elasticsearch" with "org.elasticsearch.deprecation" to maintain - * the "org.elasticsearch" namespace. + * 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) { - deprecationLogger = new ThrottlingAndHeaderWarningLogger(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 + * prefixes the logger name with "deprecation", if it starts with "org.elasticsearch.", + * it replaces "org.elasticsearch" with "org.elasticsearch.deprecation" to maintain + * the "org.elasticsearch" namespace. + */ 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 { @@ -71,32 +82,22 @@ private static String toLoggerName(final Class cls) { 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. - * method returns a builder as more methods are expected to be chained. + * 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. */ public DeprecationLoggerBuilder deprecate(final String key, final String msg, final Object... params) { - return new DeprecationLoggerBuilder() - .withDeprecation(key, msg, params); + return new DeprecationLoggerBuilder().withDeprecation(key, msg, params); } public class DeprecationLoggerBuilder { public DeprecationLoggerBuilder withDeprecation(String key, String msg, Object[] params) { - String opaqueId = HeaderWarning.getXOpaqueId(); - ESLogMessage deprecationMessage = DeprecatedMessage.of(opaqueId, msg, params); - deprecationLogger.throttleLogAndAddWarning(key, deprecationMessage); + ESLogMessage deprecationMessage = DeprecatedMessage.of(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 0000000000000..d793b31e69562 --- /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 0000000000000..b477741b97693 --- /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.get(X_OPAQUE_ID_FIELD_NAME); + final String key = esLogMessage.get("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 0dec2b45d0244..0000000000000 --- 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 072f7c5c05a0c..0000000000000 --- 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 54e62bae4710f..a76afe9b4affb 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(DeprecatedMessage.of(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 @@ class LoggerTest{ } 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 0000000000000..3f62ea7a715c0 --- /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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("key 129", "", "msg " + 129); + assertThat(filter.filter(message), equalTo(Result.ACCEPT)); + + // Should be allowed because key0 was evicted from the cache + message = DeprecatedMessage.of("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 = DeprecatedMessage.of("", "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 = DeprecatedMessage.of("", "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 = DeprecatedMessage.of("", "id 129", "msg 129"); + assertThat(filter.filter(message), equalTo(Result.ACCEPT)); + + // Should be allowed because key0 was evicted from the cache + message = DeprecatedMessage.of("", "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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("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 = DeprecatedMessage.of("key 0", "opaque-id 0", "msg 0"); + assertThat(filter.filter(message), equalTo(Result.ACCEPT)); + + message = DeprecatedMessage.of("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 = DeprecatedMessage.of("key 1", "opaque-id 0", "msg 0"); + // Accepted because the "key" value is different + assertThat(filter.filter(message), equalTo(Result.ACCEPT)); + + message = DeprecatedMessage.of("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 = DeprecatedMessage.of("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 487ed92d18077..416ecbe31d71b 100644 --- a/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java +++ b/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java @@ -65,6 +65,7 @@ import org.elasticsearch.common.io.stream.StreamInput; import org.elasticsearch.common.io.stream.Writeable; 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; @@ -148,6 +149,7 @@ import static java.util.Collections.emptyMap; import static org.elasticsearch.common.util.CollectionUtils.arrayAsArrayList; +import static org.elasticsearch.tasks.Task.X_OPAQUE_ID; import static org.hamcrest.Matchers.empty; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.hasItem; @@ -180,6 +182,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() { @@ -335,6 +338,21 @@ public static void ensureSupportedLocale() { } } + @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()); @@ -1455,5 +1473,4 @@ protected static InetAddress randomIp(boolean v4) { throw new AssertionError(); } } - } diff --git a/test/framework/src/main/resources/log4j2-test.properties b/test/framework/src/main/resources/log4j2-test.properties index 842c9c79d7963..dae00805cb35f 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 0ce331e793d09..9cbf5f9bc97ad 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 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"; From 357a070fd023d7c0b0da9e72140ef1ae952caa5b Mon Sep 17 00:00:00 2001 From: Rory Hunter Date: Mon, 24 Aug 2020 16:59:15 +0100 Subject: [PATCH 2/2] Checkstyle --- .../src/main/java/org/elasticsearch/test/ESTestCase.java | 1 - 1 file changed, 1 deletion(-) 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 416ecbe31d71b..962a3bd898817 100644 --- a/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java +++ b/test/framework/src/main/java/org/elasticsearch/test/ESTestCase.java @@ -149,7 +149,6 @@ import static java.util.Collections.emptyMap; import static org.elasticsearch.common.util.CollectionUtils.arrayAsArrayList; -import static org.elasticsearch.tasks.Task.X_OPAQUE_ID; import static org.hamcrest.Matchers.empty; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.hasItem;