Write deprecation logs to a data stream

distribution/docker/src/docker/config/log4j2.properties

@@ -12,10 +12,15 @@ 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
+
+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
 
 appender.index_search_slowlog_rolling.type = Console

distribution/docker/src/docker/config/oss/log4j2.properties

@@ -12,10 +12,15 @@ 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
+
+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
 
 appender.index_search_slowlog_rolling.type = Console

distribution/src/config/log4j2.properties

@@ -63,18 +63,23 @@ 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
 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 ####################

libs/x-content/src/main/resources/log4j2.properties

@@ -0,0 +1,8 @@
+appender.header_warning.type = HeaderWarningAppender
+appender.header_warning.name = header_warning
+
+logger.deprecation.name = deprecation
+logger.deprecation.level = deprecation
+logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
+logger.deprecation.appenderRef.header_warning.ref = header_warning
+logger.deprecation.additivity = false

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<Integer> ids = IntStream.range(0, 128).boxed().collect(Collectors.toList());
                 Randomness.shuffle(ids);
                 final ThreadContext threadContext = new ThreadContext(Settings.EMPTY);
-                DeprecationLogger.setThreadContext(threadContext);
+                HeaderWarning.setThreadContext(threadContext);
                 try {
                     barrier.await();
                 } catch (final BrokenBarrierException | InterruptedException e) {
@@ -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<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
-        assertThat(deprecationEvents.size(), equalTo(1 + 128 + 1));
-        assertLogLine(
-                deprecationEvents.get(0),
-                Level.WARN,
-                "org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
-                "This is a maybe logged deprecation message");
-        for (int k = 0; k < 128; k++) {
-            assertLogLine(
-                    deprecationEvents.get(1 + k),
-                    Level.WARN,
-                    "org.elasticsearch.common.logging.ThrottlingLogger\\$2\\.run",
-                    "This is a maybe logged deprecation message" + k);
-        }
-    }
-
     public void testDeprecatedSettings() throws IOException, UserException {
         setupLogging("settings");
 
@@ -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.");
         }

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties

@@ -25,7 +25,11 @@ appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separato
 appender.deprecation_file.layout.type = PatternLayout
 appender.deprecation_file.layout.pattern = [%p][%l] [%test_thread_info]%marker %m%n
 
+appender.header_warning.type = HeaderWarningAppender
+appender.header_warning.name = header_warning
+
 logger.deprecation.name = deprecation
 logger.deprecation.level = warn
 logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
+logger.deprecation.appenderRef.header_warning.ref = header_warning
 logger.deprecation.additivity = false

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

qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties

@@ -19,7 +19,11 @@ appender.deprecation_file.fileName = ${sys:es.logs.base_path}${sys:file.separato
 appender.deprecation_file.layout.type = PatternLayout
 appender.deprecation_file.layout.pattern = [%p][%l] %marker%m%n
 
+appender.header_warning.type = HeaderWarningAppender
+appender.header_warning.name = header_warning
+
 logger.deprecation.name = deprecation
 logger.deprecation.level = warn
 logger.deprecation.appenderRef.deprecation_file.ref = deprecation_file
+logger.deprecation.appenderRef.header_warning.ref = header_warning
 logger.deprecation.additivity = false

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

qa/logging-config/custom-log4j2.properties

@@ -87,10 +87,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.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 ####################

qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java

@@ -48,6 +48,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;
@@ -87,18 +88,19 @@ public void tearDown() throws Exception {
 
     public void testDeprecatedMessage() throws IOException {
         final Logger testLogger = LogManager.getLogger("deprecation.test");
-        testLogger.info(DeprecatedMessage.of("someId","deprecated message1"));
+        testLogger.log(DEPRECATION, DeprecatedMessage.of("someKey", "someId","deprecated message1"));
 
         final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
             System.getProperty("es.logs.cluster_name") + "_deprecated.json");
+
         try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
             List<Map<String, String>> jsonLogs = stream
                 .collect(Collectors.toList());
 
             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"),
@@ -107,6 +109,8 @@ public void testDeprecatedMessage() throws IOException {
                 )
             );
         }
+
+        assertWarnings("deprecated message1");
     }
 
     public void testBuildingMessage() throws IOException {
@@ -169,10 +173,11 @@ 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");
+        testLogger.log(DEPRECATION, DeprecatedMessage.of("a key", "someOtherId","deprecated message1"));
+        testLogger.log(DEPRECATION, DeprecatedMessage.of("a key", "", "deprecated message2"));
+        // This next message will be filtered out, because a null opaque ID has the same effect as an empty ID.
+        testLogger.log(DEPRECATION, DeprecatedMessage.of("a key", null,"deprecated message3"));
+        testLogger.log(DEPRECATION,"deprecated message4");
 
         final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
             System.getProperty("es.logs.cluster_name") + "_deprecated.json");
@@ -183,15 +188,15 @@ 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")),
+                    hasEntry("x-opaque-id", "someOtherId")),
                 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"),
@@ -200,16 +205,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
                 ),
                 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 message3"),
-                    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"),
@@ -218,7 +214,11 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
                 )
                 )
             );
+
+            assertThat(jsonLogs, not(contains(hasEntry("message", "deprecated message3"))));
         }
+
+        assertWarnings("deprecated message1", "deprecated message2", "deprecated message3", "deprecated message4");
     }
 
     public void testJsonLayout() throws IOException {
@@ -342,7 +342,7 @@ public void testDuplicateLogMessages() throws IOException {
         ThreadContext threadContext = new ThreadContext(Settings.EMPTY);
         try (ThreadContext.StoredContext ignore = threadContext.stashContext()) {
             threadContext.putHeader(Task.X_OPAQUE_ID, "ID1");
-            DeprecationLogger.setThreadContext(threadContext);
+            HeaderWarning.setThreadContext(threadContext);
             deprecationLogger.deprecate("key", "message1");
             deprecationLogger.deprecate("key", "message2");
             assertWarnings("message1", "message2");
@@ -356,7 +356,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"),
@@ -366,15 +366,15 @@ public void testDuplicateLogMessages() throws IOException {
                 );
             }
         } finally {
-            DeprecationLogger.removeThreadContext(threadContext);
+            HeaderWarning.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()) {
             threadContext.putHeader(Task.X_OPAQUE_ID, "ID2");
-            DeprecationLogger.setThreadContext(threadContext);
+            HeaderWarning.setThreadContext(threadContext);
             deprecationLogger.deprecate("key", "message1");
             deprecationLogger.deprecate("key", "message2");
             assertWarnings("message1", "message2");
@@ -388,7 +388,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"),
@@ -397,7 +397,7 @@ public void testDuplicateLogMessages() throws IOException {
                     ),
                     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"),
@@ -408,7 +408,7 @@ public void testDuplicateLogMessages() throws IOException {
                 );
             }
         } finally {
-            DeprecationLogger.removeThreadContext(threadContext);
+            HeaderWarning.removeThreadContext(threadContext);
         }
     }