honeymoose
/
OpenSearch
mirror of https://github.com/honeymoose/OpenSearch.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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
This commit is contained in:
Przemyslaw Gomulka 2019-07-22 11:38:11 +02:00 committed by GitHub
parent a6adcecd20
commit fe20e217a4
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 116 additions and 19 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -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<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> 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<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> 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<JsonLogLine> collectLines(Stream<JsonLogLine> stream) {
return stream
.skip(1)//skip the first line from super class

12
qa/logging-config/src/test/resources/org/elasticsearch/common/logging/json_layout/log4j2.properties
View File

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

29
server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java
View File

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