Implement deprecation logging using log4j

Part of elastic#46106. Simplify the implementation of deprecation logging by
relying of log4j more completely, and implementing additional behaviour
through custom appenders and filters.

Author: pugnascotia

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

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 ####################

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

@@ -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

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

@@ -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

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

@@ -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 ####################