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 6727192999c52..129ad8bf67cd3 100644 --- a/distribution/docker/docker-build-context/src/docker/config/log4j2.properties +++ b/distribution/docker/docker-build-context/src/docker/config/log4j2.properties @@ -16,7 +16,6 @@ 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 @@ -27,7 +26,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 +appender.index_search_slowlog_rolling.layout.overrideFields=message logger.index_search_slowlog_rolling.name = index.search.slowlog logger.index_search_slowlog_rolling.level = trace @@ -38,7 +37,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 +appender.index_indexing_slowlog_rolling.layout.overrideFields=message 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 d3398fa1b5d87..f770b5910fdc0 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -67,7 +67,6 @@ 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 @@ -104,7 +103,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.layout.overrideFields=message 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 @@ -143,7 +142,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.layout.overrideFields=message 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 index 655424ce5b040..da75e843524da 100644 --- 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 @@ -50,38 +50,18 @@ public void testLayout() { "\"node.name\": \"%node_name\", " + "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" + "%notEmpty{, %node_and_cluster_id }" + - "%exceptionAsJson }" + System.lineSeparator())); - } - - 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 }" + + "%notEmpty{, %CustomMapFields{} }" + "%exceptionAsJson }" + System.lineSeparator())); } public void testLayoutWithAdditionalFieldOverride() { ESJsonLayout server = ESJsonLayout.newBuilder() .setType("server") - .setESMessageFields("message") + .setOverrideFields("message") .build(); String conversionPattern = server.getPatternLayout().getConversionPattern(); + //message field is removed as is expected to be provided by a field from a message assertThat(conversionPattern, Matchers.equalTo( "{" + "\"type\": \"server\", " + @@ -90,8 +70,8 @@ public void testLayoutWithAdditionalFieldOverride() { "\"component\": \"%c{1.}\", " + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + "\"node.name\": \"%node_name\"" + - "%notEmpty{, \"message\": \"%ESMessageField{message}\"}" + "%notEmpty{, %node_and_cluster_id }" + + "%notEmpty{, %CustomMapFields{message} }" + "%exceptionAsJson }" + System.lineSeparator())); } } 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 a3f4ecde8135a..7bb22854769c5 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,6 +38,7 @@ import org.junit.BeforeClass; import java.io.IOException; +import java.nio.file.Files; import java.nio.file.Path; import java.util.List; import java.util.Map; @@ -78,8 +79,8 @@ public void tearDown() throws Exception { super.tearDown(); } public void testDeprecatedMessage() throws IOException { - final Logger testLogger = LogManager.getLogger("test"); - testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); + final Logger testLogger = LogManager.getLogger("deprecation.test"); + testLogger.info(DeprecatedMessage.of("someId","deprecated message1")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_deprecated.json"); @@ -91,7 +92,7 @@ public void testDeprecatedMessage() throws IOException { allOf( hasEntry("type", "deprecation"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "d.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message1"), @@ -101,12 +102,126 @@ public void testDeprecatedMessage() throws IOException { } } + public void testMessageOverrideWithNoValue() throws IOException { + //message field is meant to be overriden (see custom.test config), but is not provided. + //Expected is that it will be emptied + final Logger testLogger = LogManager.getLogger("custom.test"); + + testLogger.info(new ESLogMessage("some message")); + + final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), + System.getProperty("es.logs.cluster_name") + "_custom.json"); + try (Stream> stream = JsonLogsStream.mapStreamFrom(path)) { + List> jsonLogs = stream + .collect(Collectors.toList()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "custom"), + hasEntry("level", "INFO"), + hasEntry("component", "c.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name")) + ) + ); + } + } + public void testBuildingMessage() throws IOException { - 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(new ESLogMessage("some message {} {}", "value0") + .argAndField("key1","value1") + .field("key2","value2")); + + final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), + System.getProperty("es.logs.cluster_name") + ".json"); + try (Stream> stream = JsonLogsStream.mapStreamFrom(path)) { + List> jsonLogs = stream + .collect(Collectors.toList()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "file"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "some message value0 value1"), + hasEntry("key1", "value1"), + hasEntry("key2", "value2")) + ) + ); + } + } + + public void testMessageOverride() throws IOException { + + final Logger testLogger = LogManager.getLogger("custom.test"); + testLogger.info(new ESLogMessage("some message") + .with("message","overriden")); + + + final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), + System.getProperty("es.logs.cluster_name") + "_custom.json"); + try (Stream> stream = JsonLogsStream.mapStreamFrom(path)) { + List> jsonLogs = stream + .collect(Collectors.toList()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "custom"), + hasEntry("level", "INFO"), + hasEntry("component", "c.test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("message", "overriden")) + ) + ); + } + + final Path plaintextPath = PathUtils.get(System.getProperty("es.logs.base_path"), + System.getProperty("es.logs.cluster_name") + "_plaintext.json"); + List lines = Files.readAllLines(plaintextPath); + assertThat(lines, contains("some message")); + + + } + + public void testCustomMessageWithMultipleFields() throws IOException { + // if a field is defined to be overriden, it has to always be overriden in that appender. + final Logger testLogger = LogManager.getLogger("test"); + testLogger.info(new ESLogMessage("some message") + .with("field1","value1") + .with("field2","value2")); + + final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), + System.getProperty("es.logs.cluster_name") + ".json"); + try (Stream> stream = JsonLogsStream.mapStreamFrom(path)) { + List> jsonLogs = stream + .collect(Collectors.toList()); + + assertThat(jsonLogs, contains( + allOf( + hasEntry("type", "file"), + hasEntry("level", "INFO"), + hasEntry("component", "test"), + hasEntry("cluster.name", "elasticsearch"), + hasEntry("node.name", "sample-name"), + hasEntry("field1", "value1"), + hasEntry("field2", "value2"), + hasEntry("message", "some message")) + ) + ); + } + } + + + public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { + final Logger testLogger = LogManager.getLogger("deprecation.test"); + testLogger.info( DeprecatedMessage.of("someId","deprecated message1")); + testLogger.info( DeprecatedMessage.of("","deprecated message2")); + testLogger.info( DeprecatedMessage.of(null,"deprecated message3")); testLogger.info("deprecated message4"); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), @@ -119,7 +234,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { allOf( hasEntry("type", "deprecation"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "d.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message1"), @@ -127,7 +242,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { allOf( hasEntry("type", "deprecation"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "d.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message2"), @@ -136,7 +251,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { allOf( hasEntry("type", "deprecation"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "d.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message3"), @@ -145,7 +260,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { allOf( hasEntry("type", "deprecation"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "d.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "deprecated message4"), @@ -179,19 +294,19 @@ public void testJsonLayout() throws IOException { } public void testPrefixLoggerInJson() throws IOException { - Logger shardIdLogger = Loggers.getLogger("shardIdLogger", ShardId.fromString("[indexName][123]")); + Logger shardIdLogger = Loggers.getLogger("prefix.shardIdLogger", ShardId.fromString("[indexName][123]")); shardIdLogger.info("This is an info message with a shardId"); - Logger prefixLogger = new PrefixLogger(LogManager.getLogger("prefixLogger"), "PREFIX"); + Logger prefixLogger = new PrefixLogger(LogManager.getLogger("prefix.prefixLogger"), "PREFIX"); prefixLogger.info("This is an info message with a prefix"); final Path path = clusterLogsPath(); try (Stream stream = JsonLogsStream.from(path)) { List jsonLogs = collectLines(stream); assertThat(jsonLogs, contains( - logLine("file", Level.INFO, "sample-name", "shardIdLogger", + logLine("file", Level.INFO, "sample-name", "p.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") + logLine("file", Level.INFO, "sample-name", "p.prefixLogger", "PREFIX This is an info message with a prefix") )); } } @@ -351,12 +466,11 @@ public void testDuplicateLogMessages() throws IOException { private List collectLines(Stream stream) { return stream - .skip(1)//skip the first line from super class .collect(Collectors.toList()); } private Path clusterLogsPath() { - return PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".log"); + return PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".json"); } private void setupLogging(final String config) throws IOException, UserException { 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 14400177c18a2..5c2a158403457 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 @@ -5,7 +5,7 @@ appender.console.layout.type_name = console appender.file.type = File appender.file.name = file -appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.log +appender.file.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}.json appender.file.layout.type = ESJsonLayout appender.file.layout.type_name = file @@ -14,38 +14,60 @@ 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 = 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 = deprecation -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 + +appender.customconsole.type = Console +appender.customconsole.name = customconsole +appender.customconsole.layout.type = ESJsonLayout +appender.customconsole.layout.type_name = custom +appender.customconsole.layout.overrideFields = message + +appender.custom.type = File +appender.custom.name = custom +appender.custom.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_custom.json +appender.custom.layout.type = ESJsonLayout +appender.custom.layout.type_name = custom +appender.custom.layout.overrideFields = message rootLogger.level = info rootLogger.appenderRef.console.ref = console -rootLogger.appenderRef.file.ref = file + +appender.plaintext.type = File +appender.plaintext.name = plaintext +appender.plaintext.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_plaintext.json +appender.plaintext.layout.type = PatternLayout +appender.plaintext.layout.pattern =%m%n + logger.deprecation.name = deprecation.test -logger.deprecation.level = warn -logger.deprecation.appenderRef.console.ref = console -logger.deprecation.appenderRef.file.ref = file +logger.deprecation.level = trace logger.deprecation.appenderRef.deprecation_rolling.ref = deprecated logger.deprecation.appenderRef.deprecatedconsole.ref = deprecatedconsole logger.deprecation.additivity = false + +logger.custom.name = custom.test +logger.custom.level = trace +logger.custom.appenderRef.console.ref = custom +logger.custom.appenderRef.file.ref = customconsole +logger.custom.appenderRef.plaintext.ref = plaintext +logger.custom.additivity = false + 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 + + +logger.prefix.name = prefix +logger.prefix.level = trace +logger.prefix.appenderRef.console.ref = console +logger.prefix.appenderRef.file.ref = file +logger.prefix.additivity = false diff --git a/server/src/main/java/org/elasticsearch/cluster/routing/allocation/AllocationService.java b/server/src/main/java/org/elasticsearch/cluster/routing/allocation/AllocationService.java index b238946e0f666..f158103ed226c 100644 --- a/server/src/main/java/org/elasticsearch/cluster/routing/allocation/AllocationService.java +++ b/server/src/main/java/org/elasticsearch/cluster/routing/allocation/AllocationService.java @@ -40,6 +40,7 @@ import org.elasticsearch.cluster.routing.allocation.command.AllocationCommands; import org.elasticsearch.cluster.routing.allocation.decider.AllocationDeciders; import org.elasticsearch.common.collect.ImmutableOpenMap; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.gateway.GatewayAllocator; import java.util.ArrayList; @@ -378,7 +379,11 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info("Cluster health status changed from [{}] to [{}] (reason: [{}]).", previousHealth, currentHealth, reason); + logger.info(new ESLogMessage("Cluster health status changed from [{}] to [{}] (reason: [{}]).") + .argAndField("previous.health", previousHealth) + .argAndField("current.health", currentHealth) + .argAndField("reason", reason)); + } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java similarity index 60% rename from server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java rename to server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java index 40d702bc76bc5..0ac5bf029c389 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -25,43 +25,44 @@ 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; + +import java.util.Set; /** - * Pattern converter to populate ESMessageField in a pattern. + * Pattern converter to populate CustomMapFields in a pattern. + * This is to be used with custom ElasticSearch log messages * 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 { +@Plugin(category = PatternConverter.CATEGORY, name = "CustomMapFields") +@ConverterKeys({"CustomMapFields"}) +public final class CustomMapFieldsConverter extends LogEventPatternConverter { + - private String key; + private Set overridenFields; + + public CustomMapFieldsConverter(Set overridenFields) { + super("CustomMapFields", "CustomMapFields"); + this.overridenFields = overridenFields; + } /** * 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 static CustomMapFieldsConverter newInstance(final Configuration config, final String[] options) { + Set overridenFields = csvToSet(options[0]); + return new CustomMapFieldsConverter(overridenFields); } - public ESMessageFieldConverter(String key) { - super("ESMessageField", "ESMessageField"); - this.key = key; + private static Set csvToSet(String csv) { + String[] split = csv.split(","); + return Set.of(split); } @Override public void format(LogEvent event, StringBuilder toAppendTo) { - if (event.getMessage() instanceof ESLogMessage) { + 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; - } + logMessage.asJson(toAppendTo); } - StringBuilders.appendValue(toAppendTo, ""); } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java index cf31ab796c79f..7a03cd934266c 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -20,25 +20,22 @@ package org.elasticsearch.common.logging; import org.elasticsearch.common.Strings; - -import java.util.Collections; -import java.util.Map; +import org.elasticsearch.common.SuppressLoggerChecks; /** * 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); - } +public class DeprecatedMessage { + private static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; - private static Map fieldMap(String xOpaqueId) { + @SuppressLoggerChecks(reason = "safely delegates to logger") + public static ESLogMessage of(String xOpaqueId, String messagePattern, Object... args){ if (Strings.isNullOrEmpty(xOpaqueId)) { - return Collections.emptyMap(); + return new ESLogMessage(messagePattern, args); } - return Map.of("x-opaque-id", xOpaqueId); + return new ESLogMessage(messagePattern, args) + .with(X_OPAQUE_ID_FIELD_NAME, 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 31d454e70e3d6..79ef7ec0aad8e 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java @@ -253,7 +253,7 @@ public Void run() { */ String opaqueId = getXOpaqueId(threadContexts); - logger.warn(new DeprecatedMessage(message, opaqueId, params)); + logger.warn(DeprecatedMessage.of(opaqueId, message, 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 425743f2b8a2a..0bccc15e1d9da 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -58,29 +58,31 @@ * 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} + * It is possible to add more field by using {@link ESLogMessage#with} method which allow adding key value pairs + * or override field with overrideFields + * appender.logger.layout.overrideFields=message. + * In the example above the pattern will be ... "message": %OverrideField{message} ... + * the message passed to a logger will be overridden with a value from %OverrideField{message} + * Once an appender is defined to be overriding a field, all the log events should contain this field. *

- * The value taken from %ESMessageField{message} has to be a simple escaped JSON value and is populated in subclasses of - * ESLogMessage + * The value taken from ESLogMessage has to be a simple escaped JSON value. */ @Plugin(name = "ESJsonLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true) public class ESJsonLayout extends AbstractStringLayout { private final PatternLayout patternLayout; + private String overridenFields; - protected ESJsonLayout(String typeName, Charset charset, String[] esmessagefields) { + protected ESJsonLayout(String typeName, Charset charset, String[] overrideFields) { super(charset); + this.overridenFields = String.join(",",overrideFields); this.patternLayout = PatternLayout.newBuilder() - .withPattern(pattern(typeName, esmessagefields)) + .withPattern(pattern(typeName, overrideFields)) .withAlwaysWriteExceptions(false) .build(); } - private String pattern(String type, String[] esMessageFields) { + private String pattern(String type, String[] overrideFields) { if (Strings.isEmpty(type)) { throw new IllegalArgumentException("layout parameter 'type_name' cannot be empty"); } @@ -93,21 +95,23 @@ private String pattern(String type, String[] esMessageFields) { 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 + "}")); + + // overridden fields are expected to be present in a log message + for (String key : overrideFields) { + map.remove(key); } - return createPattern(map, Set.of(esMessageFields)); + return createPattern(map, Set.of(overrideFields)); } - private String createPattern(Map map, Set esMessageFields) { + private String createPattern(Map map, Set overrideFields) { StringBuilder sb = new StringBuilder(); sb.append("{"); String separator = ""; for (Map.Entry entry : map.entrySet()) { - if (esMessageFields.contains(entry.getKey())) { + if (overrideFields.contains(entry.getKey())) { sb.append("%notEmpty{"); sb.append(separator); appendField(sb, entry); @@ -120,6 +124,7 @@ private String createPattern(Map map, Set esMessageField separator = ", "; } sb.append(notEmpty(", %node_and_cluster_id ")); + sb.append(notEmpty(", %CustomMapFields{"+overridenFields+"} ")); sb.append("%exceptionAsJson "); sb.append("}"); sb.append(System.lineSeparator()); @@ -147,8 +152,8 @@ private String inQuotes(String s) { @PluginFactory public static ESJsonLayout createLayout(String type, Charset charset, - String[] esmessagefields) { - return new ESJsonLayout(type, charset, esmessagefields); + String[] overrideFields) { + return new ESJsonLayout(type, charset, overrideFields); } PatternLayout getPatternLayout() { @@ -164,8 +169,8 @@ public static class Builder> extends AbstractS @PluginAttribute(value = "charset", defaultString = "UTF-8") Charset charset; - @PluginAttribute("esmessagefields") - private String esMessageFields; + @PluginAttribute("overrideFields") + private String overrideFields; public Builder() { setCharset(StandardCharsets.UTF_8); @@ -173,7 +178,7 @@ public Builder() { @Override public ESJsonLayout build() { - String[] split = Strings.isNullOrEmpty(esMessageFields) ? new String[]{} : esMessageFields.split(","); + String[] split = Strings.isNullOrEmpty(overrideFields) ? new String[]{} : overrideFields.split(","); return ESJsonLayout.createLayout(type, charset, split); } @@ -195,12 +200,12 @@ public B setType(final String type) { return asBuilder(); } - public String getESMessageFields() { - return esMessageFields; + public String getOverrideFields() { + return overrideFields; } - public B setESMessageFields(String esmessagefields) { - this.esMessageFields = esmessagefields; + public B setOverrideFields(String overrideFields) { + this.overrideFields = overrideFields; return asBuilder(); } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java index cf19697e1c5a5..532a9a5ddee93 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -16,14 +16,19 @@ * specific language governing permissions and limitations * under the License. */ - package org.elasticsearch.common.logging; import com.fasterxml.jackson.core.io.JsonStringEncoder; +import org.apache.logging.log4j.message.MapMessage; import org.apache.logging.log4j.message.ParameterizedMessage; -import org.elasticsearch.common.SuppressLoggerChecks; +import org.apache.logging.log4j.util.Chars; +import org.apache.logging.log4j.util.StringBuilders; import java.nio.charset.Charset; +import java.util.ArrayList; +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.List; import java.util.Map; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -31,28 +36,57 @@ /** * A base class for custom log4j logger messages. Carries additional fields which will populate JSON fields in logs. */ -public abstract class ESLogMessage extends ParameterizedMessage { +public class ESLogMessage extends MapMessage { private static final JsonStringEncoder JSON_STRING_ENCODER = JsonStringEncoder.getInstance(); - 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; + private final String messagePattern; + private final List arguments = new ArrayList<>(); + + public ESLogMessage(String messagePattern, Object... arguments) { + super(new LinkedHashMap<>()); + this.messagePattern = messagePattern; + Collections.addAll(this.arguments, arguments); } - public static String escapeJson(String text) { - byte[] sourceEscaped = JSON_STRING_ENCODER.quoteAsUTF8(text); - return new String(sourceEscaped, Charset.defaultCharset()); + public ESLogMessage argAndField(String key, Object value) { + this.arguments.add(value); + super.with(key,value); + return this; + } + + public ESLogMessage field(String key, Object value) { + super.with(key,value); + return this; + } + + public ESLogMessage withFields(Map prepareMap) { + prepareMap.forEach(this::field); + return this; + } + + @Override + protected void appendMap(final StringBuilder sb) { + String message = ParameterizedMessage.format(messagePattern, arguments.toArray()); + sb.append(message); } - public String getValueFor(String key) { - Object value = fields.get(key); - return value!=null ? value.toString() : null; + //taken from super.asJson without the wrapping '{' '}' + @Override + protected void asJson(StringBuilder sb) { + for (int i = 0; i < getIndexedReadOnlyStringMap().size(); i++) { + if (i > 0) { + sb.append(", "); + } + sb.append(Chars.DQUOTE); + int start = sb.length(); + sb.append(getIndexedReadOnlyStringMap().getKeyAt(i)); + StringBuilders.escapeJson(sb, start); + sb.append(Chars.DQUOTE).append(':').append(Chars.DQUOTE); + start = sb.length(); + sb.append(getIndexedReadOnlyStringMap().getValueAt(i).toString()); + StringBuilders.escapeJson(sb, start); + sb.append(Chars.DQUOTE); + } } public static String inQuotes(String s) { @@ -72,4 +106,9 @@ public static String asJsonArray(Stream stream) { .map(ESLogMessage::inQuotes) .collect(Collectors.joining(", ")) + "]"; } + + public static String escapeJson(String text) { + byte[] sourceEscaped = JSON_STRING_ENCODER.quoteAsUTF8(text); + return new String(sourceEscaped, Charset.defaultCharset()); + } } diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index faeb9d3bc26e8..dc69718927bde 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java @@ -24,8 +24,8 @@ 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.logging.ESLogMessage; import org.elasticsearch.common.settings.Setting; import org.elasticsearch.common.settings.Setting.Property; import org.elasticsearch.common.unit.TimeValue; @@ -153,22 +153,27 @@ public void postIndex(ShardId shardId, Engine.Index indexOperation, Engine.Index final ParsedDocument doc = indexOperation.parsedDoc(); final long tookInNanos = result.getTook(); if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) { - indexLogger.warn( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.warn(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) { - indexLogger.info(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.info(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) { - indexLogger.debug(new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.debug(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) { - indexLogger.trace( new IndexingSlowLogMessage(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); + indexLogger.trace(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog)); } } } - static final class IndexingSlowLogMessage extends ESLogMessage { + static final class IndexingSlowLogMessage { + + public static ESLogMessage of( + Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { + + Map jsonFields = prepareMap(index, doc, tookInNanos, reformat, maxSourceCharsToLog); + //message for json logs is provided by jsonFields + String plaintextMessage = message(index, doc, tookInNanos, reformat, 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)); + return new ESLogMessage(plaintextMessage).withFields(jsonFields); } private static Map prepareMap(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java index f3db24a89f82a..1e16fb7749306 100644 --- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java @@ -129,33 +129,37 @@ private void setLevel(SlowLogLevel level) { @Override public void onQueryPhase(SearchContext context, long tookInNanos) { if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn(new SearchSlowLogMessage(context, tookInNanos)); + queryLogger.warn(SearchSlowLogMessage.of(context, tookInNanos)); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info(new SearchSlowLogMessage(context, tookInNanos)); + queryLogger.info(SearchSlowLogMessage.of(context, tookInNanos)); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug(new SearchSlowLogMessage(context, tookInNanos)); + queryLogger.debug(SearchSlowLogMessage.of(context, tookInNanos)); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace(new SearchSlowLogMessage(context, tookInNanos)); + queryLogger.trace(SearchSlowLogMessage.of(context, tookInNanos)); } } @Override public void onFetchPhase(SearchContext context, long tookInNanos) { if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) { - fetchLogger.warn(new SearchSlowLogMessage(context, tookInNanos)); + fetchLogger.warn(SearchSlowLogMessage.of(context, tookInNanos)); } else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) { - fetchLogger.info(new SearchSlowLogMessage(context, tookInNanos)); + fetchLogger.info(SearchSlowLogMessage.of(context, tookInNanos)); } else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) { - fetchLogger.debug(new SearchSlowLogMessage(context, tookInNanos)); + fetchLogger.debug(SearchSlowLogMessage.of(context, tookInNanos)); } else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) { - fetchLogger.trace(new SearchSlowLogMessage(context, tookInNanos)); + fetchLogger.trace(SearchSlowLogMessage.of(context, tookInNanos)); } } - static final class SearchSlowLogMessage extends ESLogMessage { + static final class SearchSlowLogMessage { - SearchSlowLogMessage(SearchContext context, long tookInNanos) { - super(prepareMap(context, tookInNanos), message(context, tookInNanos)); + public static ESLogMessage of(SearchContext context, long tookInNanos) { + Map jsonFields = prepareMap(context, tookInNanos); + // message for json logs is overridden from json Fields + String plaintextMessage = message(context, tookInNanos); + return new ESLogMessage(plaintextMessage) + .withFields(jsonFields); } private static Map prepareMap(SearchContext context, long tookInNanos) { @@ -168,13 +172,13 @@ private static Map prepareMap(SearchContext context, long tookIn } else { messageFields.put("total_hits", "-1"); } - messageFields.put("stats", escapeJson(asJsonArray( + messageFields.put("stats", ESLogMessage.escapeJson(ESLogMessage.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) { - String source = escapeJson(context.request().source().toString(FORMAT_PARAMS)); + String source = ESLogMessage.escapeJson(context.request().source().toString(FORMAT_PARAMS)); messageFields.put("source", source); } 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 ad1412dfa44e0..71f3e9b03056a 100644 --- a/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java +++ b/server/src/test/java/org/elasticsearch/common/logging/DeprecationLoggerTests.java @@ -332,7 +332,7 @@ public void testLogPermissions() { supplierCalled.set(true); createTempDir(); // trigger file permission, like rolling logs would return null; - }).when(mockLogger).warn(new DeprecatedMessage("foo", any())); + }).when(mockLogger).warn(DeprecatedMessage.of(any(), "foo")); 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 49747993ec1fa..63f54f6d023bf 100644 --- a/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/IndexingSlowLogTests.java @@ -25,6 +25,7 @@ import org.elasticsearch.cluster.metadata.IndexMetaData; import org.elasticsearch.common.bytes.BytesArray; import org.elasticsearch.common.bytes.BytesReference; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.common.xcontent.XContentType; @@ -56,19 +57,19 @@ public void testSlowLogMessageHasJsonFields() throws IOException { "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); + ESLogMessage p = IndexingSlowLogMessage.of(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())); + assertThat(p.get("message"),equalTo("[foo/123]")); + assertThat(p.get("took"),equalTo("10nanos")); + assertThat(p.get("took_millis"),equalTo("0")); + assertThat(p.get("doc_type"),equalTo("test")); + assertThat(p.get("id"),equalTo("id")); + assertThat(p.get("routing"),equalTo("routingValue")); + assertThat(p.get("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\\\"}")); + p = IndexingSlowLogMessage.of(index, pd, 10, true, Integer.MAX_VALUE); + assertThat(p.get("source"), containsString("{\\\"foo\\\":\\\"bar\\\"}")); } public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { @@ -79,19 +80,19 @@ public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { "test", null, 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); + ESLogMessage p = IndexingSlowLogMessage.of(index, pd, 10, true, 0); assertThat(p.getFormattedMessage(), not(containsString("source["))); // Turning on document logging logs the whole thing - p = new IndexingSlowLogMessage(index, pd, 10, true, Integer.MAX_VALUE); + p = IndexingSlowLogMessage.of(index, pd, 10, true, Integer.MAX_VALUE); assertThat(p.getFormattedMessage(), containsString("source[{\"foo\":\"bar\"}]")); // And you can truncate the source - p = new IndexingSlowLogMessage(index, pd, 10, true, 3); + p = IndexingSlowLogMessage.of(index, pd, 10, true, 3); assertThat(p.getFormattedMessage(), containsString("source[{\"f]")); // And you can truncate the source - p = new IndexingSlowLogMessage(index, pd, 10, true, 3); + p = IndexingSlowLogMessage.of(index, pd, 10, true, 3); assertThat(p.getFormattedMessage(), containsString("source[{\"f]")); assertThat(p.getFormattedMessage(), startsWith("[foo/123] took")); @@ -102,7 +103,7 @@ public void testSlowLogParsedDocumentPrinterSourceToLog() throws IOException { "test", null, null, source, XContentType.JSON, null); final UncheckedIOException e = expectThrows(UncheckedIOException.class, - ()->new IndexingSlowLogMessage(index, doc, 10, true, 3)); + () -> IndexingSlowLogMessage.of(index, doc, 10, true, 3)); assertThat(e, hasToString(containsString("_failed_to_convert_[Unrecognized token 'invalid':" + " was expecting ('true', 'false' or 'null')\\n" + " at [Source: org.elasticsearch.common.bytes.BytesReference$MarkSupportingStreamInputWrapper"))); diff --git a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java index 2ae8acf86a0b9..4932cf83ce14c 100644 --- a/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java +++ b/server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java @@ -22,6 +22,7 @@ import org.elasticsearch.Version; import org.elasticsearch.action.search.SearchTask; import org.elasticsearch.cluster.metadata.IndexMetaData; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.common.util.BigArrays; @@ -78,16 +79,16 @@ public void testSlowLogHasJsonFields() throws IOException { 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}}}")); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + + assertThat(p.get("message"), equalTo("[foo][0]")); + assertThat(p.get("took"), equalTo("10nanos")); + assertThat(p.get("took_millis"), equalTo("0")); + assertThat(p.get("total_hits"), equalTo("-1")); + assertThat(p.get("stats"), equalTo("[]")); + assertThat(p.get("search_type"), Matchers.nullValue()); + assertThat(p.get("total_shards"), equalTo("1")); + assertThat(p.get("source"), equalTo("{\\\"query\\\":{\\\"match_all\\\":{\\\"boost\\\":1.0}}}")); } public void testSlowLogsWithStats() throws IOException { @@ -98,16 +99,16 @@ public void testSlowLogsWithStats() throws IOException { 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("stats"), equalTo("[\\\"group1\\\"]")); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + assertThat(p.get("stats"), equalTo("[\\\"group1\\\"]")); searchContext = createSearchContext(index, "group1", "group2"); 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"))); - p = new SearchSlowLog.SearchSlowLogMessage(searchContext, 10); - assertThat(p.getValueFor("stats"), equalTo("[\\\"group1\\\", \\\"group2\\\"]")); + p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); + assertThat(p.get("stats"), equalTo("[\\\"group1\\\", \\\"group2\\\"]")); } public void testSlowLogSearchContextPrinterToLog() throws IOException { @@ -117,7 +118,7 @@ public void testSlowLogSearchContextPrinterToLog() throws IOException { 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); + ESLogMessage p = SearchSlowLog.SearchSlowLogMessage.of(searchContext, 10); assertThat(p.getFormattedMessage(), startsWith("[foo][0]")); // Makes sure that output doesn't contain any new lines assertThat(p.getFormattedMessage(), not(containsString("\n"))); 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 35d2b5803cfe8..5241514c909f5 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 @@ -70,10 +70,8 @@ public class ESLoggerUsageChecker { 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 Set CUSTOM_MESSAGE_TYPE = Set.of( + Type.getObjectType("org/elasticsearch/common/logging/ESLogMessage")); public static final Type PARAMETERIZED_MESSAGE_CLASS = Type.getType(ParameterizedMessage.class); @@ -301,13 +299,12 @@ public void findBadLoggerUsages(MethodNode methodNode) { MethodInsnNode methodInsn = (MethodInsnNode) insn; Type objectType = Type.getObjectType(methodInsn.owner); - if (DEPRECATED_TYPES.contains(objectType)) { + if (CUSTOM_MESSAGE_TYPE.contains(objectType)) { Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); - if (argumentTypes.length == 3 && + if (argumentTypes.length == 2 && 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); + argumentTypes[1].equals(OBJECT_ARRAY_CLASS)) { + checkArrayArgs(methodNode, logMessageFrames[i], arraySizeFrames[i], lineNumber, methodInsn, 0, 1); } }else if (objectType.equals(PARAMETERIZED_MESSAGE_CLASS)) { Type[] argumentTypes = Type.getArgumentTypes(methodInsn.desc); @@ -379,13 +376,31 @@ private void checkArrayArgs(MethodNode methodNode, Frame logMessageF return; } assert logMessageLength.minValue == logMessageLength.maxValue && arraySize.minValue == arraySize.maxValue; - if (logMessageLength.minValue != arraySize.minValue) { + int chainedParams = getChainedParams(methodInsn); + int args = arraySize.minValue + chainedParams; + if (logMessageLength.minValue != args) { wrongUsageCallback.accept(new WrongLoggerUsage(className, methodNode.name, methodInsn.name, lineNumber, "Expected " + logMessageLength.minValue + " arguments but got " + arraySize.minValue)); return; } } + //counts how many times argAndField was called on the method chain + private int getChainedParams(AbstractInsnNode startNode) { + int c = 0; + AbstractInsnNode current = startNode; + while(current.getNext() != null){ + current = current.getNext(); + if(current instanceof MethodInsnNode){ + MethodInsnNode method = (MethodInsnNode)current; + if(method.name.equals("argAndField")){ + c++; + } + } + } + return c; + } + private PlaceHolderStringBasicValue checkLogMessageConsistency(MethodNode methodNode, Frame logMessageFrame, int lineNumber, MethodInsnNode methodInsn, int messageIndex, int argsSize) { 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 9221a16840de0..ee94f33694fdc 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 @@ -26,6 +26,7 @@ import org.apache.logging.log4j.util.MessageSupplier; import org.apache.logging.log4j.util.Supplier; import org.elasticsearch.common.SuppressLoggerChecks; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.test.ESTestCase; import org.elasticsearch.test.loggerusage.ESLoggerUsageChecker.WrongLoggerUsage; import org.hamcrest.Matchers; @@ -116,15 +117,30 @@ public void testLoggerUsageCheckerCompatibilityWithLog4j2Logger() throws NoSuchM assertEquals(5, ParameterizedMessage.class.getConstructors().length); } - public void checkForSubclasses() { - logger.debug(new TestMessage("message", "x-opaque-id")); + + public void checkArgumentsProvidedInConstructor() { + logger.debug(new ESLogMessage("message {}", "some-arg") + .field("x-opaque-id", "some-value")); } - public void checkArraySizeForSubclasses() { - logger.debug(new TestMessage("message {}", "x-opaque-id", 1)); + public void checkWithUsage() { + logger.debug(new ESLogMessage("message {}") + .argAndField("x-opaque-id", "some-value") + .field("field", "value") + .with("field2", "value2")); } + public void checkFailArraySizeForSubclasses(Object... arr) { - logger.debug(new TestMessage("message {}", "x-opaque-id", arr)); + logger.debug(new ESLogMessage("message {}", arr)); + } + + public void checkFailForTooManyArgumentsInConstr() { + logger.debug(new ESLogMessage("message {}", "arg1", "arg2")); + } + + public void checkFailForTooManyArgumentsWithChain() { + logger.debug(new ESLogMessage("message {}").argAndField("x-opaque-id", "some-value") + .argAndField("too-many-arg", "xxx")); } public void checkFailArraySize(String... arr) { 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 deleted file mode 100644 index fa25d506ba4dc..0000000000000 --- a/test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java +++ /dev/null @@ -1,33 +0,0 @@ -/* - * 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); - } -}