From 03f4e81fc39b20dd61a9a2f1383519bb331e1e40 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Wed, 10 Jul 2019 18:22:50 +0200 Subject: [PATCH] JSON logging refactoring and X-Opaque-ID support (#41354) This is a refactor to current JSON logging to make it more open for extensions and support for custom ES log messages used inDeprecationLogger IndexingSlowLog , SearchSLowLog We want to include x-opaque-id in deprecation logs. The easiest way to have this as an additional JSON field instead of part of the message is to create a custom DeprecatedMessage (extends ESLogMEssage) These messages are regular log4j messages with a text, but also carry a map of fields which can then populate the log pattern. The logic for this lives in ESJsonLayout and ESMessageFieldConverter. Similar approach can be used to refactor IndexingSlowLog and SearchSlowLog JSON logs to contain fields previously only present as escaped JSON string in a message field. closes #41350 --- .../src/docker/config/log4j2.properties | 3 + distribution/src/config/log4j2.properties | 3 + .../common/logging/ESJsonLayoutTests.java | 97 +++++++++ .../common/logging/JsonLoggerTests.java | 115 +++++++++-- .../common/logging/JsonLogsTestSetup.java | 30 +++ .../logging/json_layout/log4j2.properties | 22 +++ .../rest-api-spec/test/README.asciidoc | 2 +- .../common/logging/DeprecatedMessage.java | 44 +++++ .../common/logging/DeprecationLogger.java | 23 ++- .../common/logging/ESJsonLayout.java | 187 ++++++++++++++---- .../common/logging/ESLogMessage.java | 67 +++++++ .../logging/ESMessageFieldConverter.java | 67 +++++++ .../common/util/concurrent/ThreadContext.java | 16 +- .../elasticsearch/index/IndexingSlowLog.java | 66 +++++-- .../elasticsearch/index/SearchSlowLog.java | 72 +++++-- .../logging/DeprecationLoggerTests.java | 6 +- .../index/IndexingSlowLogTests.java | 70 ++++--- .../index/SearchSlowLogTests.java | 29 ++- .../common/logging/JsonLogLine.java | 2 +- .../common/logging/JsonLogsStream.java | 34 +++- .../loggerusage/ESLoggerUsageChecker.java | 29 ++- .../test/loggerusage/ESLoggerUsageTests.java | 14 ++ .../test/loggerusage/TestMessage.java | 33 ++++ 23 files changed, 892 insertions(+), 139 deletions(-) create mode 100644 qa/logging-config/src/test/java/org/elasticsearch/common/logging/ESJsonLayoutTests.java create mode 100644 qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLogsTestSetup.java create mode 100644 server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java create mode 100644 server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java create mode 100644 server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java create mode 100644 test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java diff --git a/distribution/docker/docker-build-context/src/docker/config/log4j2.properties b/distribution/docker/docker-build-context/src/docker/config/log4j2.properties index 40be55d2e1c3..6727192999c5 100644 --- a/distribution/docker/docker-build-context/src/docker/config/log4j2.properties +++ b/distribution/docker/docker-build-context/src/docker/config/log4j2.properties @@ -16,6 +16,7 @@ appender.deprecation_rolling.type = Console appender.deprecation_rolling.name = deprecation_rolling appender.deprecation_rolling.layout.type = ESJsonLayout appender.deprecation_rolling.layout.type_name = deprecation +appender.deprecation_rolling.layout.esmessagefields=x-opaque-id logger.deprecation.name = org.elasticsearch.deprecation logger.deprecation.level = warn @@ -26,6 +27,7 @@ appender.index_search_slowlog_rolling.type = Console appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling appender.index_search_slowlog_rolling.layout.type = ESJsonLayout appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog +appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,stats,search_type,total_shards,source,id logger.index_search_slowlog_rolling.name = index.search.slowlog logger.index_search_slowlog_rolling.level = trace @@ -36,6 +38,7 @@ appender.index_indexing_slowlog_rolling.type = Console appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog +appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source logger.index_indexing_slowlog.name = index.indexing.slowlog.index logger.index_indexing_slowlog.level = trace diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index 45bf720902c1..d3398fa1b5d8 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -67,6 +67,7 @@ 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 = ESJsonLayout appender.deprecation_rolling.layout.type_name = deprecation +appender.deprecation_rolling.layout.esmessagefields=x-opaque-id 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 @@ -103,6 +104,7 @@ appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:f .cluster_name}_index_search_slowlog.json appender.index_search_slowlog_rolling.layout.type = ESJsonLayout appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog +appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,stats,search_type,total_shards,source,id appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ .cluster_name}_index_search_slowlog-%i.json.gz @@ -141,6 +143,7 @@ appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys _index_indexing_slowlog.json appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog +appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\ _index_indexing_slowlog-%i.json.gz diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/ESJsonLayoutTests.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/ESJsonLayoutTests.java new file mode 100644 index 000000000000..bdcbc41585d0 --- /dev/null +++ b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/ESJsonLayoutTests.java @@ -0,0 +1,97 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.elasticsearch.common.logging; + + +import org.elasticsearch.test.ESTestCase; +import org.hamcrest.Matchers; +import org.junit.BeforeClass; + + +public class ESJsonLayoutTests extends ESTestCase { + @BeforeClass + public static void initNodeName() { + JsonLogsTestSetup.init(); + } + + public void testEmptyType() { + expectThrows(IllegalArgumentException.class, () -> ESJsonLayout.newBuilder().build()); + } + + public void testLayout() { + ESJsonLayout server = ESJsonLayout.newBuilder() + .setType("server") + .build(); + String conversionPattern = server.getPatternLayout().getConversionPattern(); + + assertThat(conversionPattern, Matchers.equalTo( + "{" + + "\"type\": \"server\", " + + "\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}\", " + + "\"level\": \"%p\", " + + "\"component\": \"%c{1.}\", " + + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + + "\"node.name\": \"%node_name\", " + + "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" + + "%notEmpty{, %node_and_cluster_id }" + + "%exceptionAsJson }\n")); + } + + public void testLayoutWithAdditionalFields() { + ESJsonLayout server = ESJsonLayout.newBuilder() + .setType("server") + .setESMessageFields("x-opaque-id,someOtherField") + .build(); + String conversionPattern = server.getPatternLayout().getConversionPattern(); + + assertThat(conversionPattern, Matchers.equalTo( + "{" + + "\"type\": \"server\", " + + "\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}\", " + + "\"level\": \"%p\", " + + "\"component\": \"%c{1.}\", " + + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + + "\"node.name\": \"%node_name\", " + + "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" + + "%notEmpty{, \"x-opaque-id\": \"%ESMessageField{x-opaque-id}\"}" + + "%notEmpty{, \"someOtherField\": \"%ESMessageField{someOtherField}\"}" + + "%notEmpty{, %node_and_cluster_id }" + + "%exceptionAsJson }\n")); + } + + public void testLayoutWithAdditionalFieldOverride() { + ESJsonLayout server = ESJsonLayout.newBuilder() + .setType("server") + .setESMessageFields("message") + .build(); + String conversionPattern = server.getPatternLayout().getConversionPattern(); + + assertThat(conversionPattern, Matchers.equalTo( + "{" + + "\"type\": \"server\", " + + "\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}\", " + + "\"level\": \"%p\", " + + "\"component\": \"%c{1.}\", " + + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + + "\"node.name\": \"%node_name\"" + + "%notEmpty{, \"message\": \"%ESMessageField{message}\"}" + + "%notEmpty{, %node_and_cluster_id }" + + "%exceptionAsJson }\n")); + } +} 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 2416eb02bfd4..431542bebcbc 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 @@ -38,19 +38,28 @@ import org.junit.BeforeClass; import java.io.IOException; import java.nio.file.Path; import java.util.List; +import java.util.Map; +import java.util.Objects; import java.util.stream.Collectors; import java.util.stream.Stream; +import static org.hamcrest.Matchers.allOf; +import static org.hamcrest.Matchers.contains; +import static org.hamcrest.Matchers.hasEntry; +import static org.hamcrest.Matchers.hasKey; +import static org.hamcrest.Matchers.not; + /** * This test confirms JSON log structure is properly formatted and can be parsed. * It has to be in a org.elasticsearch.common.logging package to use PrefixLogger */ public class JsonLoggerTests extends ESTestCase { + private static final String LINE_SEPARATOR = System.lineSeparator(); @BeforeClass public static void initNodeName() { - LogConfigurator.setNodeName("sample-name"); + JsonLogsTestSetup.init(); } @Override @@ -66,6 +75,83 @@ public class JsonLoggerTests extends ESTestCase { Configurator.shutdown(context); super.tearDown(); } + public void testDeprecatedMessage() throws IOException { + final Logger testLogger = LogManager.getLogger("test"); + testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); + + 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", "deprecated"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message1"), + hasEntry("x-opaque-id", "someId")) + ) + ); + } + } + + public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { + final Logger testLogger = LogManager.getLogger("test"); + testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); + testLogger.info(new DeprecatedMessage("deprecated message2", "")); + testLogger.info(new DeprecatedMessage("deprecated message3", null)); + testLogger.info("deprecated message4"); + + 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", "deprecated"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message1"), + hasEntry("x-opaque-id", "someId")), + allOf( + hasEntry("type", "deprecated"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message2"), + not(hasKey("x-opaque-id")) + ), + allOf( + hasEntry("type", "deprecated"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message3"), + not(hasKey("x-opaque-id")) + ), + allOf( + hasEntry("type", "deprecated"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "deprecated message4"), + not(hasKey("x-opaque-id")) + ) + ) + ); + } + } public void testJsonLayout() throws IOException { final Logger testLogger = LogManager.getLogger("test"); @@ -79,7 +165,7 @@ public class JsonLoggerTests extends ESTestCase { try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); - assertThat(jsonLogs, Matchers.contains( + assertThat(jsonLogs, contains( logLine("file", Level.ERROR, "sample-name", "test", "This is an error message"), logLine("file", Level.WARN, "sample-name", "test", "This is a warning message"), logLine("file", Level.INFO, "sample-name", "test", "This is an info message"), @@ -99,8 +185,9 @@ public class JsonLoggerTests extends ESTestCase { final Path path = clusterLogsPath(); try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); - assertThat(jsonLogs, Matchers.contains( - logLine("file", Level.INFO, "sample-name", "shardIdLogger", "[indexName][123] This is an info message with a shardId"), + assertThat(jsonLogs, contains( + logLine("file", Level.INFO, "sample-name", "shardIdLogger", + "[indexName][123] This is an info message with a shardId"), logLine("file", Level.INFO, "sample-name", "prefixLogger", "PREFIX This is an info message with a prefix") )); } @@ -124,7 +211,7 @@ public class JsonLoggerTests extends ESTestCase { final Path path = clusterLogsPath(); try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); - assertThat(jsonLogs, Matchers.contains( + assertThat(jsonLogs, contains( logLine("file", Level.INFO, "sample-name", "test", json) )); } @@ -137,8 +224,8 @@ public class JsonLoggerTests extends ESTestCase { final Path path = clusterLogsPath(); try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); - assertThat(jsonLogs, Matchers.contains( - Matchers.allOf( + assertThat(jsonLogs, contains( + allOf( logLine("file", Level.ERROR, "sample-name", "test", "error message"), stacktraceWith("java.lang.Exception: exception message"), stacktraceWith("Caused by: java.lang.RuntimeException: cause message") @@ -166,8 +253,8 @@ public class JsonLoggerTests extends ESTestCase { try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); - assertThat(jsonLogs, Matchers.contains( - Matchers.allOf( + assertThat(jsonLogs, contains( + allOf( //message field will have a single line with json escaped logLine("file", Level.ERROR, "sample-name", "test", "error message " + json), @@ -209,11 +296,11 @@ public class JsonLoggerTests extends ESTestCase { @Override protected Boolean featureValueOf(JsonLogLine actual) { - return actual.type().equals(type) && - actual.level().equals(level.toString()) && - actual.nodeName().equals(nodeName) && - actual.component().equals(component) && - actual.message().equals(message); + return Objects.equals(actual.type(), type) && + Objects.equals(actual.level(), level.toString()) && + Objects.equals(actual.nodeName(), nodeName) && + Objects.equals(actual.component(), component) && + Objects.equals(actual.message(), message); } }; } diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLogsTestSetup.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLogsTestSetup.java new file mode 100644 index 000000000000..7ddb11a56965 --- /dev/null +++ b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLogsTestSetup.java @@ -0,0 +1,30 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.elasticsearch.common.logging; + +public class JsonLogsTestSetup { + private static boolean initialized = false; + + public static void init() { + if (initialized == false) { + LogConfigurator.setNodeName("sample-name"); + initialized = true; + } + } +} 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 4bbd0b038ab8..7ece44209339 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 @@ -9,6 +9,26 @@ appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.l appender.file.layout.type = ESJsonLayout appender.file.layout.type_name = file +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.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.esmessagefields = x-opaque-id + +appender.index_search_slowlog_rolling.type = File +appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling +appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_index_search_slowlog.json +appender.index_search_slowlog_rolling.layout.type = ESJsonLayout +appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog +appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,types,stats,search_type,total_shards,source,id rootLogger.level = info rootLogger.appenderRef.console.ref = console @@ -18,4 +38,6 @@ logger.test.name = test logger.test.level = trace logger.test.appenderRef.console.ref = console logger.test.appenderRef.file.ref = file +logger.test.appenderRef.deprecated.ref = deprecated +logger.test.appenderRef.deprecatedconsole.ref = deprecatedconsole logger.test.additivity = false diff --git a/rest-api-spec/src/main/resources/rest-api-spec/test/README.asciidoc b/rest-api-spec/src/main/resources/rest-api-spec/test/README.asciidoc index c83edb69b3e6..84afbf0217ab 100644 --- a/rest-api-spec/src/main/resources/rest-api-spec/test/README.asciidoc +++ b/rest-api-spec/src/main/resources/rest-api-spec/test/README.asciidoc @@ -50,7 +50,7 @@ section in order to setup the same environment for each test section. A `teardown` section contains a list of commands to run after each test section in order to setup the same environment for each test section. This -may be needed for modifications made by the testthat are not cleared by the +may be needed for modifications made by the test that are not cleared by the deletion of indices and templates. A test section represents an independent test, containing multiple `do` diff --git a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java new file mode 100644 index 000000000000..cf31ab796c79 --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -0,0 +1,44 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.elasticsearch.common.logging; + +import org.elasticsearch.common.Strings; + +import java.util.Collections; +import java.util.Map; + +/** + * A logger message used by {@link DeprecationLogger}. + * Carries x-opaque-id field if provided in the headers. Will populate the x-opaque-id field in JSON logs. + */ +public class DeprecatedMessage extends ESLogMessage { + + public DeprecatedMessage(String messagePattern, String xOpaqueId, Object... args) { + super(fieldMap(xOpaqueId), messagePattern, args); + } + + private static Map fieldMap(String xOpaqueId) { + if (Strings.isNullOrEmpty(xOpaqueId)) { + return Collections.emptyMap(); + } + + return Map.of("x-opaque-id", xOpaqueId); + } +} 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 d5d682f807ae..57aa823d3480 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java @@ -25,6 +25,7 @@ import org.elasticsearch.Build; import org.elasticsearch.Version; import org.elasticsearch.common.SuppressLoggerChecks; import org.elasticsearch.common.util.concurrent.ThreadContext; +import org.elasticsearch.tasks.Task; import java.nio.charset.Charset; import java.security.AccessController; @@ -222,13 +223,14 @@ public class DeprecationLogger { } void deprecated(final Set threadContexts, final String message, final boolean log, final Object... params) { - final Iterator iterator = threadContexts.iterator(); + 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(); @@ -244,7 +246,16 @@ public class DeprecationLogger { @SuppressLoggerChecks(reason = "safely delegates to logger") @Override public Void run() { - logger.warn(message, params); + /** + * 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(""); + + logger.warn(new DeprecatedMessage(message, opaqueId, params)); return null; } }); diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java index af7cd81f202e..425743f2b8a2 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -24,6 +24,7 @@ import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.config.Node; import org.apache.logging.log4j.core.config.plugins.Plugin; import org.apache.logging.log4j.core.config.plugins.PluginAttribute; +import org.apache.logging.log4j.core.config.plugins.PluginBuilderFactory; import org.apache.logging.log4j.core.config.plugins.PluginFactory; import org.apache.logging.log4j.core.layout.AbstractStringLayout; import org.apache.logging.log4j.core.layout.ByteBufferDestination; @@ -31,66 +32,182 @@ import org.apache.logging.log4j.core.layout.PatternLayout; import org.elasticsearch.common.Strings; import java.nio.charset.Charset; +import java.nio.charset.StandardCharsets; +import java.util.LinkedHashMap; import java.util.Map; +import java.util.Set; /** * Formats log events as strings in a json format. *

* The class is wrapping the {@link PatternLayout} with a pattern to format into json. This gives more flexibility and control over how the * log messages are formatted in {@link org.apache.logging.log4j.core.layout.JsonLayout} + * There are fields which are always present in the log line: + *

    + *
  • type - the type of logs. These represent appenders and help docker distinguish log streams.
    • + *
  • timestamp - ISO8601 with additional timezone ID
    • + *
  • level - INFO, WARN etc
    • + *
  • component - logger name, most of the times class name
    • + *
  • cluster.name - taken from sys:es.logs.cluster_name system property because it is always set
    • + *
  • node.name - taken from NodeNamePatternConverter, as it can be set in runtime as hostname when not set in elasticsearch.yml
    • + *
  • node_and_cluster_id - in json as node.id and cluster.uuid - taken from NodeAndClusterIdConverter and present + * once clusterStateUpdate is first received
    • + *
  • message - a json escaped message. Multiline messages will be converted to single line with new line explicitly + * replaced to \n
    • + *
  • exceptionAsJson - in json as a stacktrace field. Only present when throwable is passed as a parameter when using a logger. + * Taken from JsonThrowablePatternConverter
    • + *
+ *

+ * It is possible to add more or override them with esmessagefield + * appender.logger.layout.esmessagefields=message,took,took_millis,total_hits,types,stats,search_type,total_shards,source,id + * Each of these will be expanded into a json field with a value taken {@link ESLogMessage} field. In the example above + * ... "message": %ESMessageField{message}, "took": %ESMessageField{took} ... + * the message passed to a logger will be overriden with a value from %ESMessageField{message} + *

+ * The value taken from %ESMessageField{message} has to be a simple escaped JSON value and is populated in subclasses of + * ESLogMessage */ @Plugin(name = "ESJsonLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true) public class ESJsonLayout extends AbstractStringLayout { - /** - * Fields used in a pattern to format a json log line: - *

    - *
  • type - the type of logs. These represent appenders and help docker distinguish log streams.
    • - *
  • timestamp - ISO8601 with additional timezone ID
    • - *
  • level - INFO, WARN etc
    • - *
  • component - logger name, most of the times class name
    • - *
  • cluster.name - taken from sys:es.logs.cluster_name system property because it is always set
    • - *
  • node.name - taken from NodeNamePatternConverter, as it can be set in runtime as hostname when not set in elasticsearch.yml
    • - *
  • node_and_cluster_id - in json as node.id and cluster.uuid - taken from NodeAndClusterIdConverter and present - * once clusterStateUpdate is first received
    • - *
  • message - a json escaped message. Multiline messages will be converted to single line with new line explicitly - * replaced to \n
    • - *
  • exceptionAsJson - in json as a stacktrace field. Only present when throwable is passed as a parameter when using a logger. - * Taken from JsonThrowablePatternConverter
    • - *
- */ - private static final String PATTERN = "{" + - "\"type\": \"${TYPE}\", " + - "\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZ}\", " + - "\"level\": \"%p\", " + - "\"component\": \"%c{1.}\", " + - "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + - "\"node.name\": \"%node_name\", " + - "%notEmpty{%node_and_cluster_id, } " + - "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\" " + - "%exceptionAsJson " + - "}%n"; private final PatternLayout patternLayout; - protected ESJsonLayout(String typeName, Charset charset) { + protected ESJsonLayout(String typeName, Charset charset, String[] esmessagefields) { super(charset); this.patternLayout = PatternLayout.newBuilder() - .withPattern(pattern(typeName)) + .withPattern(pattern(typeName, esmessagefields)) .withAlwaysWriteExceptions(false) .build(); } - private String pattern(String type) { + private String pattern(String type, String[] esMessageFields) { if (Strings.isEmpty(type)) { throw new IllegalArgumentException("layout parameter 'type_name' cannot be empty"); } - return PATTERN.replace("${TYPE}", type); + Map map = new LinkedHashMap<>(); + map.put("type", inQuotes(type)); + map.put("timestamp", inQuotes("%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}")); + map.put("level", inQuotes("%p")); + map.put("component", inQuotes("%c{1.}")); + map.put("cluster.name", inQuotes("${sys:es.logs.cluster_name}")); + map.put("node.name", inQuotes("%node_name")); + map.put("message", inQuotes("%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}")); + + for (String key : esMessageFields) { + map.put(key, inQuotes("%ESMessageField{" + key + "}")); + } + + return createPattern(map, Set.of(esMessageFields)); + } + + + private String createPattern(Map map, Set esMessageFields) { + StringBuilder sb = new StringBuilder(); + sb.append("{"); + String separator = ""; + for (Map.Entry entry : map.entrySet()) { + + if (esMessageFields.contains(entry.getKey())) { + sb.append("%notEmpty{"); + sb.append(separator); + appendField(sb, entry); + sb.append("}"); + } else { + sb.append(separator); + appendField(sb, entry); + } + + separator = ", "; + } + sb.append(notEmpty(", %node_and_cluster_id ")); + sb.append("%exceptionAsJson "); + sb.append("}"); + sb.append(System.lineSeparator()); + + return sb.toString(); + } + + private void appendField(StringBuilder sb, Map.Entry entry) { + sb.append(jsonKey(entry.getKey())); + sb.append(entry.getValue().toString()); + } + + private String notEmpty(String value) { + return "%notEmpty{" + value + "}"; + } + + private CharSequence jsonKey(String s) { + return inQuotes(s) + ": "; + } + + private String inQuotes(String s) { + return "\"" + s + "\""; } @PluginFactory - public static ESJsonLayout createLayout(@PluginAttribute("type_name") String type, - @PluginAttribute(value = "charset", defaultString = "UTF-8") Charset charset) { - return new ESJsonLayout(type, charset); + public static ESJsonLayout createLayout(String type, + Charset charset, + String[] esmessagefields) { + return new ESJsonLayout(type, charset, esmessagefields); + } + + PatternLayout getPatternLayout() { + return patternLayout; + } + + public static class Builder> extends AbstractStringLayout.Builder + implements org.apache.logging.log4j.core.util.Builder { + + @PluginAttribute("type_name") + String type; + + @PluginAttribute(value = "charset", defaultString = "UTF-8") + Charset charset; + + @PluginAttribute("esmessagefields") + private String esMessageFields; + + public Builder() { + setCharset(StandardCharsets.UTF_8); + } + + @Override + public ESJsonLayout build() { + String[] split = Strings.isNullOrEmpty(esMessageFields) ? new String[]{} : esMessageFields.split(","); + return ESJsonLayout.createLayout(type, charset, split); + } + + public Charset getCharset() { + return charset; + } + + public B setCharset(final Charset charset) { + this.charset = charset; + return asBuilder(); + } + + public String getType() { + return type; + } + + public B setType(final String type) { + this.type = type; + return asBuilder(); + } + + public String getESMessageFields() { + return esMessageFields; + } + + public B setESMessageFields(String esmessagefields) { + this.esMessageFields = esmessagefields; + return asBuilder(); + } + } + + @PluginBuilderFactory + public static > B newBuilder() { + return new ESJsonLayout.Builder().asBuilder(); } @Override diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java new file mode 100644 index 000000000000..aeb8bdc8197b --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -0,0 +1,67 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.elasticsearch.common.logging; + +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.elasticsearch.common.SuppressLoggerChecks; + +import java.util.Map; +import java.util.stream.Collectors; +import java.util.stream.Stream; + +/** + * A base class for custom log4j logger messages. Carries additional fields which will populate JSON fields in logs. + */ +public abstract class ESLogMessage extends ParameterizedMessage { + private final Map fields; + + /** + * This is an abstract class, so this is safe. The check is done on DeprecationMessage. + * Other subclasses are not allowing varargs + */ + @SuppressLoggerChecks(reason = "Safe as this is abstract class") + public ESLogMessage(Map fields, String messagePattern, Object... args) { + super(messagePattern, args); + this.fields = fields; + } + + public String getValueFor(String key) { + Object value = fields.get(key); + return value!=null ? value.toString() : null; + } + + public static String inQuotes(String s) { + if(s == null) + return inQuotes(""); + return "\"" + s + "\""; + } + + public static String inQuotes(Object s) { + if(s == null) + return inQuotes(""); + return inQuotes(s.toString()); + } + + public static String asJsonArray(Stream stream) { + return "[" + stream + .map(ESLogMessage::inQuotes) + .collect(Collectors.joining(", ")) + "]"; + } +} diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java b/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java new file mode 100644 index 000000000000..40d702bc76bc --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java @@ -0,0 +1,67 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.elasticsearch.common.logging; + +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.config.Configuration; +import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.pattern.ConverterKeys; +import org.apache.logging.log4j.core.pattern.LogEventPatternConverter; +import org.apache.logging.log4j.core.pattern.PatternConverter; +import org.apache.logging.log4j.util.StringBuilders; +import org.elasticsearch.common.Strings; + +/** + * Pattern converter to populate ESMessageField in a pattern. + * It will only populate these if the event have message of type ESLogMessage. + */ +@Plugin(category = PatternConverter.CATEGORY, name = "ESMessageField") +@ConverterKeys({"ESMessageField"}) +public final class ESMessageFieldConverter extends LogEventPatternConverter { + + private String key; + + /** + * Called by log4j2 to initialize this converter. + */ + public static ESMessageFieldConverter newInstance(final Configuration config, final String[] options) { + final String key = options[0]; + + return new ESMessageFieldConverter(key); + } + + public ESMessageFieldConverter(String key) { + super("ESMessageField", "ESMessageField"); + this.key = key; + } + + @Override + public void format(LogEvent event, StringBuilder toAppendTo) { + if (event.getMessage() instanceof ESLogMessage) { + ESLogMessage logMessage = (ESLogMessage) event.getMessage(); + final String value = logMessage.getValueFor(key); + if (Strings.isNullOrEmpty(value) == false) { + StringBuilders.appendValue(toAppendTo, value); + return; + } + } + StringBuilders.appendValue(toAppendTo, ""); + } +} diff --git a/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java b/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java index b52bc2b199c8..a8bb172e203c 100644 --- a/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java +++ b/server/src/main/java/org/elasticsearch/common/util/concurrent/ThreadContext.java @@ -30,6 +30,7 @@ import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Setting.Property; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.http.HttpTransportSettings; +import org.elasticsearch.tasks.Task; import java.io.Closeable; import java.io.IOException; @@ -129,7 +130,18 @@ public final class ThreadContext implements Closeable, Writeable { */ public StoredContext stashContext() { final ThreadContextStruct context = threadLocal.get(); - threadLocal.set(null); + /** + * X-Opaque-ID should be preserved in a threadContext in order to propagate this across threads. + * This is needed so the DeprecationLogger in another thread can see the value of X-Opaque-ID provided by a user. + * Otherwise when context is stash, it should be empty. + */ + if (context.requestHeaders.containsKey(Task.X_OPAQUE_ID)) { + ThreadContextStruct threadContextStruct = + DEFAULT_CONTEXT.putHeaders(Map.of(Task.X_OPAQUE_ID, context.requestHeaders.get(Task.X_OPAQUE_ID))); + threadLocal.set(threadContextStruct); + } else { + threadLocal.set(null); + } return () -> { // If the node and thus the threadLocal get closed while this task // is still executing, we don't want this runnable to fail with an @@ -402,7 +414,7 @@ public final class ThreadContext implements Closeable, Writeable { /** * Returns true if the context is closed, otherwise true */ - boolean isClosed() { + public boolean isClosed() { return threadLocal.closed.get(); } diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index b4b471e220a7..faeb9d3bc26e 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java @@ -19,10 +19,12 @@ package org.elasticsearch.index; -import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.util.StringBuilders; import org.elasticsearch.common.Booleans; import org.elasticsearch.common.Strings; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Setting.Property; @@ -35,7 +37,9 @@ import org.elasticsearch.index.shard.ShardId; import java.io.IOException; import java.io.UncheckedIOException; +import java.util.HashMap; import java.util.Locale; +import java.util.Map; import java.util.concurrent.TimeUnit; public final class IndexingSlowLog implements IndexingOperationListener { @@ -149,34 +153,58 @@ public final class IndexingSlowLog implements IndexingOperationListener { final ParsedDocument doc = indexOperation.parsedDoc(); final long tookInNanos = result.getTook(); if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) { - indexLogger.warn("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.warn( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) { - indexLogger.info("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.info(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) { - indexLogger.debug("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.debug(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) { - indexLogger.trace("{}", new SlowLogParsedDocumentPrinter(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.trace( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } } } - static final class SlowLogParsedDocumentPrinter { - private final ParsedDocument doc; - private final long tookInNanos; - private final boolean reformat; - private final int maxSourceCharsToLog; - private final Index index; + static final class IndexingSlowLogMessage extends ESLogMessage { - SlowLogParsedDocumentPrinter(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { - this.doc = doc; - this.index = index; - this.tookInNanos = tookInNanos; - this.reformat = reformat; - this.maxSourceCharsToLog = maxSourceCharsToLog; + IndexingSlowLogMessage(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { + super(prepareMap(index,doc,tookInNanos,reformat,maxSourceCharsToLog), + message(index,doc,tookInNanos,reformat,maxSourceCharsToLog)); } - @Override - public String toString() { + private static Map prepareMap(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, + int maxSourceCharsToLog) { + Map map = new HashMap<>(); + map.put("message", index); + map.put("took", TimeValue.timeValueNanos(tookInNanos)); + map.put("took_millis", ""+TimeUnit.NANOSECONDS.toMillis(tookInNanos)); + map.put("doc_type", doc.type()); + map.put("id", doc.id()); + map.put("routing", doc.routing()); + + if (maxSourceCharsToLog == 0 || doc.source() == null || doc.source().length() == 0) { + return map; + } + try { + String source = XContentHelper.convertToJson(doc.source(), reformat, doc.getXContentType()); + String trim = Strings.cleanTruncate(source, maxSourceCharsToLog).trim(); + StringBuilder sb = new StringBuilder(trim); + StringBuilders.escapeJson(sb,0); + map.put("source", sb.toString()); + } catch (IOException e) { + StringBuilder sb = new StringBuilder("_failed_to_convert_[" + e.getMessage()+"]"); + StringBuilders.escapeJson(sb,0); + map.put("source", sb.toString()); + /* + * We choose to fail to write to the slow log and instead let this percolate up to the post index listener loop where this + * will be logged at the warn level. + */ + final String message = String.format(Locale.ROOT, "failed to convert source for slow log entry [%s]", map.toString()); + throw new UncheckedIOException(message, e); + } + return map; + } + + private static String message(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { StringBuilder sb = new StringBuilder(); sb.append(index).append(" "); sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], "); diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java index a2193a1bdf73..d3c7638e2a85 100644 --- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java @@ -19,9 +19,11 @@ package org.elasticsearch.index; +import com.fasterxml.jackson.core.io.JsonStringEncoder; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.elasticsearch.common.Strings; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Setting.Property; @@ -31,8 +33,12 @@ import org.elasticsearch.index.shard.SearchOperationListener; import org.elasticsearch.search.internal.SearchContext; import org.elasticsearch.tasks.Task; +import java.nio.charset.Charset; import java.util.Collections; +import java.util.HashMap; +import java.util.Map; import java.util.concurrent.TimeUnit; +import java.util.stream.Stream; public final class SearchSlowLog implements SearchOperationListener { private long queryWarnThreshold; @@ -121,49 +127,75 @@ public final class SearchSlowLog implements SearchOperationListener { Loggers.setLevel(queryLogger, level.name()); Loggers.setLevel(fetchLogger, level.name()); } + @Override public void onQueryPhase(SearchContext context, long tookInNanos) { if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + queryLogger.warn(new SearchSlowLogMessage(context, tookInNanos)); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + queryLogger.info(new SearchSlowLogMessage(context, tookInNanos)); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + queryLogger.debug(new SearchSlowLogMessage(context, tookInNanos)); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + queryLogger.trace(new SearchSlowLogMessage(context, tookInNanos)); } } @Override public void onFetchPhase(SearchContext context, long tookInNanos) { if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) { - fetchLogger.warn("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + fetchLogger.warn(new SearchSlowLogMessage(context, tookInNanos)); } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) { - fetchLogger.info("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + fetchLogger.info(new SearchSlowLogMessage(context, tookInNanos)); } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) { - fetchLogger.debug("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + fetchLogger.debug(new SearchSlowLogMessage(context, tookInNanos)); } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) { - fetchLogger.trace("{}", new SlowLogSearchContextPrinter(context, tookInNanos)); + fetchLogger.trace(new SearchSlowLogMessage(context, tookInNanos)); } } - static final class SlowLogSearchContextPrinter { - private final SearchContext context; - private final long tookInNanos; + static final class SearchSlowLogMessage extends ESLogMessage { - SlowLogSearchContextPrinter(SearchContext context, long tookInNanos) { - this.context = context; - this.tookInNanos = tookInNanos; + SearchSlowLogMessage(SearchContext context, long tookInNanos) { + super(prepareMap(context, tookInNanos), message(context, tookInNanos)); } - @Override - public String toString() { + private static Map prepareMap(SearchContext context, long tookInNanos) { + Map messageFields = new HashMap<>(); + messageFields.put("message", context.indexShard().shardId()); + messageFields.put("took", TimeValue.timeValueNanos(tookInNanos)); + messageFields.put("took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos)); + if (context.queryResult().getTotalHits() != null) { + messageFields.put("total_hits", context.queryResult().getTotalHits()); + } else { + messageFields.put("total_hits", "-1"); + } + messageFields.put("stats", asJsonArray(context.groupStats() != null ? context.groupStats().stream() : Stream.empty())); + messageFields.put("search_type", context.searchType()); + messageFields.put("total_shards", context.numberOfShards()); + + if (context.request().source() != null) { + byte[] sourceEscaped = JsonStringEncoder.getInstance() + .quoteAsUTF8(context.request().source().toString(FORMAT_PARAMS)); + String source = new String(sourceEscaped, Charset.defaultCharset()); + + messageFields.put("source", source); + } else { + messageFields.put("source", "{}"); + } + + messageFields.put("id", context.getTask().getHeader(Task.X_OPAQUE_ID)); + return messageFields; + } + + // Message will be used in plaintext logs + private static String message(SearchContext context, long tookInNanos) { StringBuilder sb = new StringBuilder(); sb.append(context.indexShard().shardId()) - .append(" ") - .append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ") - .append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ") - .append("total_hits["); + .append(" ") + .append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ") + .append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ") + .append("total_hits["); if (context.queryResult().getTotalHits() != null) { sb.append(context.queryResult().getTotalHits()); } else { diff --git a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java index 740430ac0993..ad1412dfa44e 100644 --- a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java +++ b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java @@ -26,6 +26,7 @@ import org.apache.logging.log4j.simple.SimpleLoggerContextFactory; import org.apache.logging.log4j.spi.ExtendedLogger; import org.apache.logging.log4j.spi.LoggerContext; import org.apache.logging.log4j.spi.LoggerContextFactory; +import org.elasticsearch.common.SuppressLoggerChecks; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.util.concurrent.ThreadContext; import org.elasticsearch.test.ESTestCase; @@ -56,6 +57,7 @@ import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.hasSize; import static org.hamcrest.Matchers.not; import static org.hamcrest.core.Is.is; +import static org.mockito.Matchers.any; import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.when; @@ -318,7 +320,7 @@ public class DeprecationLoggerTests extends ESTestCase { assertTrue(warningHeadersSize <= 1024); } } - + @SuppressLoggerChecks(reason = "Safe as this is using mockito") public void testLogPermissions() { AtomicBoolean supplierCalled = new AtomicBoolean(false); @@ -330,7 +332,7 @@ public class DeprecationLoggerTests extends ESTestCase { supplierCalled.set(true); createTempDir(); // trigger file permission, like rolling logs would return null; - }).when(mockLogger).warn("foo", new Object[] {"bar"}); + }).when(mockLogger).warn(new DeprecatedMessage("foo", any())); final LoggerContext context = new SimpleLoggerContext() { @Override public ExtendedLogger getLogger(String name) { diff --git a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java index 72a1cb4a87d7..49747993ec1f 100644 --- a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java @@ -29,7 +29,7 @@ import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.common.xcontent.XContentType; import org.elasticsearch.common.xcontent.json.JsonXContent; -import org.elasticsearch.index.IndexingSlowLog.SlowLogParsedDocumentPrinter; +import org.elasticsearch.index.IndexingSlowLog.IndexingSlowLogMessage; import org.elasticsearch.index.mapper.ParsedDocument; import org.elasticsearch.index.mapper.SeqNoFieldMapper; import org.elasticsearch.test.ESTestCase; @@ -38,13 +38,39 @@ import java.io.IOException; import java.io.UncheckedIOException; import static org.hamcrest.Matchers.containsString; +import static org.hamcrest.Matchers.emptyOrNullString; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.hasToString; import static org.hamcrest.Matchers.instanceOf; +import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.startsWith; public class IndexingSlowLogTests extends ESTestCase { + + public void testSlowLogMessageHasJsonFields() throws IOException { + BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder() + .startObject().field("foo", "bar").endObject()); + ParsedDocument pd = new ParsedDocument(new NumericDocValuesField("version", 1), + SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id", + "test", "routingValue", null, source, XContentType.JSON, null); + Index index = new Index("foo", "123"); + // Turning off document logging doesn't log source[] + IndexingSlowLogMessage p = new IndexingSlowLogMessage(index, pd, 10, true, 0); + + assertThat(p.getValueFor("message"),equalTo("[foo/123]")); + assertThat(p.getValueFor("took"),equalTo("10nanos")); + assertThat(p.getValueFor("took_millis"),equalTo("0")); + assertThat(p.getValueFor("doc_type"),equalTo("test")); + assertThat(p.getValueFor("id"),equalTo("id")); + assertThat(p.getValueFor("routing"),equalTo("routingValue")); + assertThat(p.getValueFor("source"), is(emptyOrNullString())); + + // Turning on document logging logs the whole thing + p = new IndexingSlowLogMessage(index, pd, 10, true, Integer.MAX_VALUE); + assertThat(p.getValueFor("source"), containsString("{\\\"foo\\\":\\\"bar\\\"}")); + } + public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { BytesReference source = BytesReference.bytes(JsonXContent.contentBuilder() .startObject().field("foo", "bar").endObject()); @@ -53,32 +79,32 @@ public class IndexingSlowLogTests extends ESTestCase { "test", null, null, source, XContentType.JSON, null); Index index = new Index("foo", "123"); // Turning off document logging doesn't log source[] - SlowLogParsedDocumentPrinter p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 0); - assertThat(p.toString(), not(containsString("source["))); + IndexingSlowLogMessage p = new IndexingSlowLogMessage(index, pd, 10, true, 0); + assertThat(p.getFormattedMessage(), not(containsString("source["))); // Turning on document logging logs the whole thing - p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, Integer.MAX_VALUE); - assertThat(p.toString(), containsString("source[{\"foo\":\"bar\"}]")); + p = new IndexingSlowLogMessage(index, pd, 10, true, Integer.MAX_VALUE); + assertThat(p.getFormattedMessage(), containsString("source[{\"foo\":\"bar\"}]")); // And you can truncate the source - p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3); - assertThat(p.toString(), containsString("source[{\"f]")); + p = new IndexingSlowLogMessage(index, pd, 10, true, 3); + assertThat(p.getFormattedMessage(), containsString("source[{\"f]")); // And you can truncate the source - p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3); - assertThat(p.toString(), containsString("source[{\"f]")); - assertThat(p.toString(), startsWith("[foo/123] took")); + p = new IndexingSlowLogMessage(index, pd, 10, true, 3); + assertThat(p.getFormattedMessage(), containsString("source[{\"f]")); + assertThat(p.getFormattedMessage(), startsWith("[foo/123] took")); // Throwing a error if source cannot be converted source = new BytesArray("invalid"); - pd = new ParsedDocument(new NumericDocValuesField("version", 1), + ParsedDocument doc = new ParsedDocument(new NumericDocValuesField("version", 1), SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id", "test", null, null, source, XContentType.JSON, null); - p = new SlowLogParsedDocumentPrinter(index, pd, 10, true, 3); - final UncheckedIOException e = expectThrows(UncheckedIOException.class, p::toString); + final UncheckedIOException e = expectThrows(UncheckedIOException.class, + ()->new IndexingSlowLogMessage(index, doc, 10, true, 3)); assertThat(e, hasToString(containsString("_failed_to_convert_[Unrecognized token 'invalid':" - + " was expecting ('true', 'false' or 'null')\n" + + " was expecting ('true', 'false' or 'null')\\n" + " at [Source: org.elasticsearch.common.bytes.BytesReference$MarkSupportingStreamInputWrapper"))); assertNotNull(e.getCause()); assertThat(e.getCause(), instanceOf(JsonParseException.class)); @@ -128,22 +154,6 @@ public class IndexingSlowLogTests extends ESTestCase { assertTrue(log.isReformat()); } - public void testReformatIsFalseAndSourceIsTrim() { - String json = "\n\n{ \"fieldName\": 123 } \n "; - BytesReference source = new BytesArray(json); - ParsedDocument pd = new ParsedDocument(new NumericDocValuesField("version", 1), - SeqNoFieldMapper.SequenceIDFields.emptySeqID(), "id", - "test", null, null, source, XContentType.JSON, null); - Index index = new Index("foo", "123"); - // Turning off reformatting so the document is in logs as provided - SlowLogParsedDocumentPrinter p = new SlowLogParsedDocumentPrinter(index, pd, 10, false, 1000); - String logLine = p.toString(); - - //expect the new lines and white characters to be trimmed - assertThat(logLine, containsString("source[{")); - assertThat(logLine.split("\n").length, equalTo(1)); - } - public void testLevelSetting() { SlowLogLevel level = randomFrom(SlowLogLevel.values()); IndexMetaData metaData = newIndexMeta("index", Settings.builder() diff --git a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java index 2f682f437a2c..3c23b477122a 100644 --- a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java @@ -39,12 +39,14 @@ import org.elasticsearch.tasks.Task; import org.elasticsearch.test.ESSingleNodeTestCase; import org.elasticsearch.test.TestSearchContext; import org.elasticsearch.threadpool.ThreadPool; +import org.hamcrest.Matchers; import java.io.IOException; import java.util.Collections; import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.endsWith; +import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.hasToString; import static org.hamcrest.Matchers.instanceOf; import static org.hamcrest.Matchers.not; @@ -150,6 +152,25 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase { }; } + public void testSlowLogHasJsonFields() throws IOException { + IndexService index = createIndex("foo"); + SearchContext searchContext = createSearchContext(index); + SearchSourceBuilder source = SearchSourceBuilder.searchSource().query(QueryBuilders.matchAllQuery()); + searchContext.request().source(source); + searchContext.setTask(new SearchTask(0, "n/a", "n/a", "test", null, + Collections.singletonMap(Task.X_OPAQUE_ID, "my_id"))); + SearchSlowLog.SearchSlowLogMessage p = new SearchSlowLog.SearchSlowLogMessage(searchContext, 10); + + assertThat(p.getValueFor("message"), equalTo("[foo][0]")); + assertThat(p.getValueFor("took"), equalTo("10nanos")); + assertThat(p.getValueFor("took_millis"), equalTo("0")); + assertThat(p.getValueFor("total_hits"), equalTo("-1")); + assertThat(p.getValueFor("stats"), equalTo("[]")); + assertThat(p.getValueFor("search_type"), Matchers.nullValue()); + assertThat(p.getValueFor("total_shards"), equalTo("1")); + assertThat(p.getValueFor("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); + } + public void testSlowLogSearchContextPrinterToLog() throws IOException { IndexService index = createIndex("foo"); SearchContext searchContext = createSearchContext(index); @@ -157,11 +178,11 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase { searchContext.request().source(source); searchContext.setTask(new SearchTask(0, "n/a", "n/a", "test", null, Collections.singletonMap(Task.X_OPAQUE_ID, "my_id"))); - SearchSlowLog.SlowLogSearchContextPrinter p = new SearchSlowLog.SlowLogSearchContextPrinter(searchContext, 10); - assertThat(p.toString(), startsWith("[foo][0]")); + SearchSlowLog.SearchSlowLogMessage p = new SearchSlowLog.SearchSlowLogMessage(searchContext, 10); + assertThat(p.getFormattedMessage(), startsWith("[foo][0]")); // Makes sure that output doesn't contain any new lines - assertThat(p.toString(), not(containsString("\n"))); - assertThat(p.toString(), endsWith("id[my_id], ")); + assertThat(p.getFormattedMessage(), not(containsString("\n"))); + assertThat(p.getFormattedMessage(), endsWith("id[my_id], ")); } public void testLevelSetting() { diff --git a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java index fa8f3d7d2701..15f4b17ba6f8 100644 --- a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java +++ b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogLine.java @@ -30,7 +30,7 @@ import java.util.List; * Parsing log lines with this class confirms the json format of logs */ public class JsonLogLine { - public static final ObjectParser PARSER = createParser(false); + public static final ObjectParser PARSER = createParser(true); private String type; private String timestamp; diff --git a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java index 28ad649f55a7..ad6fedca2d92 100644 --- a/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java +++ b/test/framework/src/main/java/org/elasticsearch/common/logging/JsonLogsStream.java @@ -30,6 +30,8 @@ import java.io.UncheckedIOException; import java.nio.file.Files; import java.nio.file.Path; import java.util.Iterator; +import java.util.LinkedHashMap; +import java.util.Map; import java.util.Spliterator; import java.util.Spliterators; import java.util.stream.Stream; @@ -57,10 +59,20 @@ public class JsonLogsStream { return from(Files.newBufferedReader(path)); } + public static Stream> mapStreamFrom(Path path) throws IOException { + return new JsonLogsStream(Files.newBufferedReader(path)).streamMap(); + } + private Stream stream() { Spliterator spliterator = Spliterators.spliteratorUnknownSize(new JsonIterator(), Spliterator.ORDERED); return StreamSupport.stream(spliterator, false) - .onClose(this::close); + .onClose(this::close); + } + + private Stream> streamMap() { + Spliterator> spliterator = Spliterators.spliteratorUnknownSize(new MapIterator(), Spliterator.ORDERED); + return StreamSupport.stream(spliterator, false) + .onClose(this::close); } private void close() { @@ -72,6 +84,26 @@ public class JsonLogsStream { } } + private class MapIterator implements Iterator> { + + @Override + public boolean hasNext() { + return parser.isClosed() == false; + } + + @Override + public Map next() { + Map map; + try { + map = parser.map(LinkedHashMap::new, XContentParser::text); + parser.nextToken(); + } catch (IOException e) { + throw new UncheckedIOException(e); + } + return map; + } + } + private class JsonIterator implements Iterator { @Override diff --git a/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java b/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java index b8404ea76b6a..35d2b5803cfe 100644 --- a/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java +++ b/test/logger-usage/src/main/java/org/elasticsearch/test/loggerusage/ESLoggerUsageChecker.java @@ -52,6 +52,7 @@ import java.nio.file.SimpleFileVisitor; import java.nio.file.attribute.BasicFileAttributes; import java.util.Arrays; import java.util.List; +import java.util.Set; import java.util.function.Consumer; import java.util.function.Predicate; @@ -60,13 +61,21 @@ public class ESLoggerUsageChecker { public static final Type THROWABLE_CLASS = Type.getType(Throwable.class); public static final Type STRING_CLASS = Type.getType(String.class); public static final Type STRING_ARRAY_CLASS = Type.getType(String[].class); - public static final Type PARAMETERIZED_MESSAGE_CLASS = Type.getType(ParameterizedMessage.class); + public static final Type OBJECT_CLASS = Type.getType(Object.class); public static final Type OBJECT_ARRAY_CLASS = Type.getType(Object[].class); public static final Type SUPPLIER_ARRAY_CLASS = Type.getType(Supplier[].class); public static final Type MARKER_CLASS = Type.getType(Marker.class); public static final List LOGGER_METHODS = Arrays.asList("trace", "debug", "info", "warn", "error", "fatal"); public static final String IGNORE_CHECKS_ANNOTATION = "org.elasticsearch.common.SuppressLoggerChecks"; + // types which are subject to checking when used in logger. TestMessage is also declared here to + // make sure this functionality works + public static final Set DEPRECATED_TYPES = Set.of( + Type.getObjectType("org/elasticsearch/common/logging/DeprecatedMessage"), + Type.getObjectType("org/elasticsearch/test/loggerusage/TestMessage") + ); + + public static final Type PARAMETERIZED_MESSAGE_CLASS = Type.getType(ParameterizedMessage.class); @SuppressForbidden(reason = "command line tool") public static void main(String... args) throws Exception { @@ -290,7 +299,17 @@ public class ESLoggerUsageChecker { } } else if (insn.getOpcode() == Opcodes.INVOKESPECIAL) { // constructor invocation MethodInsnNode methodInsn = (MethodInsnNode) insn; - if (Type.getObjectType(methodInsn.owner).equals(PARAMETERIZED_MESSAGE_CLASS)) { + Type objectType = Type.getObjectType(methodInsn.owner); + + if (DEPRECATED_TYPES.contains(objectType)) { + Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); + if (argumentTypes.length == 3 && + argumentTypes[0].equals(STRING_CLASS) && + argumentTypes[1].equals(STRING_CLASS) && + argumentTypes[2].equals(OBJECT_ARRAY_CLASS)) { + checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 2); + } + }else if (objectType.equals(PARAMETERIZED_MESSAGE_CLASS)) { Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); if (argumentTypes.length == 2 && argumentTypes[0].equals(STRING_CLASS) && @@ -316,8 +335,10 @@ public class ESLoggerUsageChecker { argumentTypes[2].equals(THROWABLE_CLASS)) { checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 1); } else { - throw new IllegalStateException("Constructor invoked on " + PARAMETERIZED_MESSAGE_CLASS.getClassName() + - " that is not supported by logger usage checker"); + throw new IllegalStateException("Constructor invoked on " + objectType + + " that is not supported by logger usage checker"+ + new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber, + "Constructor: "+ Arrays.toString(argumentTypes))); } } } diff --git a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java index ea60b0cf5b7c..9221a16840de 100644 --- a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java +++ b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/ESLoggerUsageTests.java @@ -116,6 +116,20 @@ public class ESLoggerUsageTests extends ESTestCase { assertEquals(5, ParameterizedMessage.class.getConstructors().length); } + public void checkForSubclasses() { + logger.debug(new TestMessage("message", "x-opaque-id")); + } + + public void checkArraySizeForSubclasses() { + logger.debug(new TestMessage("message {}", "x-opaque-id", 1)); + } + public void checkFailArraySizeForSubclasses(Object... arr) { + logger.debug(new TestMessage("message {}", "x-opaque-id", arr)); + } + + public void checkFailArraySize(String... arr) { + logger.debug(new ParameterizedMessage("text {}", (Object[])arr)); + } public void checkNumberOfArguments1() { logger.info("Hello {}", "world"); diff --git a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java new file mode 100644 index 000000000000..fa25d506ba4d --- /dev/null +++ b/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java @@ -0,0 +1,33 @@ +/* + * Licensed to Elasticsearch under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.elasticsearch.test.loggerusage; + +import org.apache.logging.log4j.message.ParameterizedMessage; + +/** + * This class is for testing that ESLoggerUsageChecker can find incorrect usages of LogMessages + * which are subclasses of ParametrizedMessage + * @see ESLoggerUsageTests + */ +class TestMessage extends ParameterizedMessage { + TestMessage(String messagePattern, String xOpaqueId, Object... args) { + super(messagePattern, args); + } +}