From fe20e217a46909994c85f141487da688861059da Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Mon, 22 Jul 2019 11:38:11 +0200 Subject: [PATCH] Deprecation messages with the same key but different x-opaque-id are allowed backport(#44587) #44682 Deprecation logger was filtering log entries by key, that means that if two log messages with the same key are logged from different users, then the second log messages will be filtered. This change allows to log deprecation message with the same key by different users. relates #41354 backport #44587 --- .../common/logging/JsonLoggerTests.java | 94 ++++++++++++++++++- .../logging/json_layout/log4j2.properties | 12 ++- .../common/logging/DeprecationLogger.java | 29 +++--- 3 files changed, 116 insertions(+), 19 deletions(-) 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 431542bebcb..a3f4ecde813 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 @@ -27,8 +27,10 @@ import org.apache.logging.log4j.core.config.Configurator; import org.elasticsearch.cli.UserException; import org.elasticsearch.common.io.PathUtils; import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.util.concurrent.ThreadContext; import org.elasticsearch.env.Environment; import org.elasticsearch.index.shard.ShardId; +import org.elasticsearch.tasks.Task; import org.elasticsearch.test.ESTestCase; import org.hamcrest.FeatureMatcher; import org.hamcrest.Matcher; @@ -87,7 +89,7 @@ public class JsonLoggerTests extends ESTestCase { assertThat(jsonLogs, contains( allOf( - hasEntry("type", "deprecated"), + hasEntry("type", "deprecation"), hasEntry("level", "INFO"), hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), @@ -99,6 +101,7 @@ public class JsonLoggerTests extends ESTestCase { } } + public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { final Logger testLogger = LogManager.getLogger("test"); testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); @@ -114,7 +117,7 @@ public class JsonLoggerTests extends ESTestCase { assertThat(jsonLogs, contains( allOf( - hasEntry("type", "deprecated"), + hasEntry("type", "deprecation"), hasEntry("level", "INFO"), hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), @@ -122,7 +125,7 @@ public class JsonLoggerTests extends ESTestCase { hasEntry("message", "deprecated message1"), hasEntry("x-opaque-id", "someId")), allOf( - hasEntry("type", "deprecated"), + hasEntry("type", "deprecation"), hasEntry("level", "INFO"), hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), @@ -131,7 +134,7 @@ public class JsonLoggerTests extends ESTestCase { not(hasKey("x-opaque-id")) ), allOf( - hasEntry("type", "deprecated"), + hasEntry("type", "deprecation"), hasEntry("level", "INFO"), hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), @@ -140,7 +143,7 @@ public class JsonLoggerTests extends ESTestCase { not(hasKey("x-opaque-id")) ), allOf( - hasEntry("type", "deprecated"), + hasEntry("type", "deprecation"), hasEntry("level", "INFO"), hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), @@ -265,6 +268,87 @@ public class JsonLoggerTests extends ESTestCase { } } + + public void testDuplicateLogMessages() throws IOException { + final DeprecationLogger deprecationLogger = new DeprecationLogger(LogManager.getLogger("test")); + + + // For the same key and X-Opaque-ID deprecation should be once + try (ThreadContext threadContext = new ThreadContext(Settings.EMPTY)) { + try{ + threadContext.putHeader(Task.X_OPAQUE_ID, "ID1"); + DeprecationLogger.setThreadContext(threadContext); + deprecationLogger.deprecatedAndMaybeLog("key", "message1"); + deprecationLogger.deprecatedAndMaybeLog("key", "message2"); + assertWarnings("message1", "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()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "deprecation"), + hasEntry("level", "WARN"), + hasEntry("component", "d.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "message1"), + hasEntry("x-opaque-id", "ID1")) + ) + ); + } + }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 threadContext = new ThreadContext(Settings.EMPTY)) { + try{ + threadContext.putHeader(Task.X_OPAQUE_ID, "ID2"); + DeprecationLogger.setThreadContext(threadContext); + deprecationLogger.deprecatedAndMaybeLog("key", "message1"); + deprecationLogger.deprecatedAndMaybeLog("key", "message2"); + assertWarnings("message1", "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()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "deprecation"), + hasEntry("level", "WARN"), + hasEntry("component", "d.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "message1"), + hasEntry("x-opaque-id", "ID1") + ), + allOf( + hasEntry("type", "deprecation"), + hasEntry("level", "WARN"), + hasEntry("component", "d.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "message1"), + hasEntry("x-opaque-id", "ID2") + ) + ) + ); + } + }finally{ + DeprecationLogger.removeThreadContext(threadContext); + } + } + } + private List collectLines(Stream stream) { return stream .skip(1)//skip the first line from super class 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 7ece4420933..14400177c18 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 @@ -13,13 +13,13 @@ appender.deprecated.type = File 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 = ESJsonLayout -appender.deprecated.layout.type_name = deprecated +appender.deprecated.layout.type_name = deprecation appender.deprecated.layout.esmessagefields = x-opaque-id appender.deprecatedconsole.type = Console appender.deprecatedconsole.name = deprecatedconsole appender.deprecatedconsole.layout.type = ESJsonLayout -appender.deprecatedconsole.layout.type_name = deprecated +appender.deprecatedconsole.layout.type_name = deprecation appender.deprecatedconsole.layout.esmessagefields = x-opaque-id appender.index_search_slowlog_rolling.type = File @@ -34,6 +34,14 @@ rootLogger.level = info rootLogger.appenderRef.console.ref = console rootLogger.appenderRef.file.ref = file +logger.deprecation.name = deprecation.test +logger.deprecation.level = warn +logger.deprecation.appenderRef.console.ref = console +logger.deprecation.appenderRef.file.ref = file +logger.deprecation.appenderRef.deprecation_rolling.ref = deprecated +logger.deprecation.appenderRef.deprecatedconsole.ref = deprecatedconsole +logger.deprecation.additivity = false + logger.test.name = test logger.test.level = trace logger.test.appenderRef.console.ref = console 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 57aa823d348..f0deaa5b730 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java @@ -134,7 +134,9 @@ public class DeprecationLogger { * @param params parameters to the message */ public void deprecatedAndMaybeLog(final String key, final String msg, final Object... params) { - deprecated(THREAD_CONTEXT, msg, keys.add(key), params); + String xOpaqueId = getXOpaqueId(THREAD_CONTEXT); + boolean log = keys.add(xOpaqueId + key); + deprecated(THREAD_CONTEXT, msg, log, params); } /* @@ -223,14 +225,12 @@ public class DeprecationLogger { } void deprecated(final Set threadContexts, final String message, final boolean log, final Object... params) { - final String formattedMessage = LoggerMessageFormat.format(message, params); - final String warningHeaderValue = formatWarning(formattedMessage); - assert WARNING_HEADER_PATTERN.matcher(warningHeaderValue).matches(); - assert extractWarningValueFromWarningHeader(warningHeaderValue).equals(escapeAndEncode(formattedMessage)); - final Iterator iterator = threadContexts.iterator(); if (iterator.hasNext()) { - + final String formattedMessage = LoggerMessageFormat.format(message, params); + final String warningHeaderValue = formatWarning(formattedMessage); + assert WARNING_HEADER_PATTERN.matcher(warningHeaderValue).matches(); + assert extractWarningValueFromWarningHeader(warningHeaderValue).equals(escapeAndEncode(formattedMessage)); while (iterator.hasNext()) { try { final ThreadContext next = iterator.next(); @@ -249,11 +249,7 @@ public class DeprecationLogger { /** * There should be only one threadContext (in prod env), @see DeprecationLogger#setThreadContext */ - String opaqueId = threadContexts.stream() - .filter(t -> t.isClosed() == false) - .findFirst() - .map(t -> t.getHeader(Task.X_OPAQUE_ID)) - .orElse(""); + String opaqueId = getXOpaqueId(threadContexts); logger.warn(new DeprecatedMessage(message, opaqueId, params)); return null; @@ -262,6 +258,15 @@ public class DeprecationLogger { } } + public String getXOpaqueId(Set threadContexts) { + return threadContexts.stream() + .filter(t -> t.isClosed() == false) + .filter(t -> t.getHeader(Task.X_OPAQUE_ID) != null) + .findFirst() + .map(t -> t.getHeader(Task.X_OPAQUE_ID)) + .orElse(""); + } + /** * Format a warning string in the proper warning format by prepending a warn code, warn agent, wrapping the warning string in quotes, * and appending the RFC 7231 date.