Skip to content

Commit

Permalink
Implement deprecation logging using log4j (#61474)
Browse files Browse the repository at this point in the history 
Part of #46106. Simplify the implementation of deprecation logging by
relying of log4j more completely, and implementing additional behaviour
through custom appenders and filters.
  • Loading branch information
@pugnascotia
pugnascotia authored Aug 25, 2020
1 parent d070c99 commit f0aa24e
Show file tree
Hide file tree
Showing 21 changed files with 533 additions and 371 deletions.
7 changes: 6 additions & 1 deletion distribution/docker/src/docker/config/oss/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
7 changes: 6 additions & 1 deletion distribution/src/config/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 ####################
Expand Down
54 changes: 6 additions & 48 deletions qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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);
}

Expand All @@ -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");

Expand All @@ -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.");
}
Expand Down
7 changes: 6 additions & 1 deletion qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/config/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
7 changes: 6 additions & 1 deletion ...l-tests/src/test/resources/org/elasticsearch/common/logging/deprecation/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
7 changes: 6 additions & 1 deletion ...-tests/src/test/resources/org/elasticsearch/common/logging/no_node_name/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
7 changes: 6 additions & 1 deletion qa/evil-tests/src/test/resources/org/elasticsearch/common/logging/settings/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
8 changes: 7 additions & 1 deletion qa/logging-config/custom-log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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 ####################
Expand Down
Loading

0 comments on commit f0aa24e

Please sign in to comment.