From cb24964f2436eab6c174a0375a4cf1ebdd10ff4c Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 13 Sep 2019 13:56:55 +0200 Subject: [PATCH 01/12] refactor ESLogMessage and overriding fields --- .../src/docker/config/log4j2.properties | 4 +- distribution/src/config/log4j2.properties | 5 +- .../common/logging/ESJsonLayoutTests.java | 3 + .../common/logging/JsonLoggerTests.java | 42 ++++++++-- .../logging/json_layout/log4j2.properties | 36 ++++---- .../logging/CustomMapFieldsConverter.java | 82 +++++++++++++++++++ .../common/logging/ESJsonLayout.java | 3 + .../common/logging/ESLogMessage.java | 4 + 8 files changed, 153 insertions(+), 26 deletions(-) create mode 100644 server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.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 6727192999c52..74d0c849b1791 100644 --- a/distribution/docker/docker-build-context/src/docker/config/log4j2.properties +++ b/distribution/docker/docker-build-context/src/docker/config/log4j2.properties @@ -27,7 +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 +appender.index_search_slowlog_rolling.layout.esmessagefields=message logger.index_search_slowlog_rolling.name = index.search.slowlog logger.index_search_slowlog_rolling.level = trace @@ -38,7 +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 +appender.index_indexing_slowlog_rolling.layout.esmessagefields=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..ca08f528cff38 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.esmessagefields=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.esmessagefields=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..b1c8c2d160e82 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,6 +50,7 @@ public void testLayout() { "\"node.name\": \"%node_name\", " + "\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" + "%notEmpty{, %node_and_cluster_id }" + + "%notEmpty{, %CustomMapFields{} }" + "%exceptionAsJson }" + System.lineSeparator())); } @@ -72,6 +73,7 @@ public void testLayoutWithAdditionalFields() { "%notEmpty{, \"x-opaque-id\": \"%ESMessageField{x-opaque-id}\"}" + "%notEmpty{, \"someOtherField\": \"%ESMessageField{someOtherField}\"}" + "%notEmpty{, %node_and_cluster_id }" + + "%notEmpty{, %CustomMapFields{x-opaque-id,someOtherField} }" + "%exceptionAsJson }" + System.lineSeparator())); } @@ -92,6 +94,7 @@ public void testLayoutWithAdditionalFieldOverride() { "\"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..61c766697b8d8 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 @@ -78,7 +78,7 @@ public void tearDown() throws Exception { super.tearDown(); } public void testDeprecatedMessage() throws IOException { - final Logger testLogger = LogManager.getLogger("test"); + final Logger testLogger = LogManager.getLogger("deprecation.test"); testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), @@ -91,7 +91,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"), @@ -100,10 +100,38 @@ public void testDeprecatedMessage() throws IOException { ); } } + class CustomMessage extends ESLogMessage{ + CustomMessage() { + super(Map.of("message","overriden"), "some message"); + } + } + + public void testMessageOverride() throws IOException { + final Logger testLogger = LogManager.getLogger("custom.test"); + testLogger.info(new CustomMessage()); + + 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")) + ) + ); + } + } public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { - final Logger testLogger = LogManager.getLogger("test"); + final Logger testLogger = LogManager.getLogger("deprecation.test"); testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); testLogger.info(new DeprecatedMessage("deprecated message2", "")); testLogger.info(new DeprecatedMessage("deprecated message3", null)); @@ -119,7 +147,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 +155,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 +164,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 +173,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"), 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..087ee77dbfb6c 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 @@ -14,38 +14,46 @@ 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.esmessagefields = 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.esmessagefields = message rootLogger.level = info rootLogger.appenderRef.console.ref = console rootLogger.appenderRef.file.ref = file logger.deprecation.name = deprecation.test -logger.deprecation.level = warn -logger.deprecation.appenderRef.console.ref = console -logger.deprecation.appenderRef.file.ref = file +logger.deprecation.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.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 diff --git a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java new file mode 100644 index 0000000000000..50c908aad5acb --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -0,0 +1,82 @@ +/* + * 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; + +import java.util.Map; +import java.util.Set; + +/** + * 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 = "CustomMapFields") +@ConverterKeys({"CustomMapFields"}) +public final class CustomMapFieldsConverter extends LogEventPatternConverter { + + + private Set overridenFields; + + public CustomMapFieldsConverter(Set overridenFields) { + super("CustomMapFields", "CustomMapFields"); + this.overridenFields = overridenFields; + } + + /** + * Called by log4j2 to initialize this converter. + */ + public static CustomMapFieldsConverter newInstance(final Configuration config, final String[] options) { + Set overridenFields = csvToSet(options[0]); + return new CustomMapFieldsConverter(overridenFields); + } + + 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) { + ESLogMessage logMessage = (ESLogMessage) event.getMessage(); + + Map fields = logMessage.getFields(); + for (String key : fields.keySet()) { + if (overridenFields.contains(key) == false) { + String value = logMessage.getValueFor(key); + if (Strings.isNullOrEmpty(value) == false) { + String message = ESLogMessage.inQuotes(key) + ":" + ESLogMessage.inQuotes(value); + StringBuilders.appendValue(toAppendTo, message); + return; + } + } + } + } + StringBuilders.appendValue(toAppendTo, ""); + } +} 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..469a3f8e16620 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -71,9 +71,11 @@ public class ESJsonLayout extends AbstractStringLayout { private final PatternLayout patternLayout; + private String overridenFields; protected ESJsonLayout(String typeName, Charset charset, String[] esmessagefields) { super(charset); + this.overridenFields = String.join(",",esmessagefields); this.patternLayout = PatternLayout.newBuilder() .withPattern(pattern(typeName, esmessagefields)) .withAlwaysWriteExceptions(false) @@ -120,6 +122,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()); 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..844440e16a3fd 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -50,6 +50,10 @@ public static String escapeJson(String text) { return new String(sourceEscaped, Charset.defaultCharset()); } + public Map getFields(){ + return fields; + } + public String getValueFor(String key) { Object value = fields.get(key); return value!=null ? value.toString() : null; From 6b450a9e8cc7ce1e35b4675c549290ccf976fa3e Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 13 Sep 2019 15:16:05 +0200 Subject: [PATCH 02/12] rename esmessagefields to overrideFields --- .../src/docker/config/log4j2.properties | 5 +-- distribution/src/config/log4j2.properties | 4 +- .../common/logging/ESJsonLayoutTests.java | 25 +---------- .../common/logging/JsonLoggerTests.java | 45 ++++++++++++++++--- .../logging/json_layout/log4j2.properties | 6 +-- .../logging/CustomMapFieldsConverter.java | 13 +++--- .../common/logging/ESJsonLayout.java | 45 ++++++++++--------- 7 files changed, 78 insertions(+), 65 deletions(-) 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 74d0c849b1791..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 +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 +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 ca08f528cff38..f770b5910fdc0 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -103,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 +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 @@ -142,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 +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 b1c8c2d160e82..eef5a55d55001 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 @@ -54,33 +54,10 @@ public void testLayout() { "%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{x-opaque-id,someOtherField} }" + - "%exceptionAsJson }" + System.lineSeparator())); - } - public void testLayoutWithAdditionalFieldOverride() { ESJsonLayout server = ESJsonLayout.newBuilder() .setType("server") - .setESMessageFields("message") + .setOverrideFields("message") .build(); String conversionPattern = server.getPatternLayout().getConversionPattern(); 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 61c766697b8d8..3c2996bdb0c91 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 @@ -100,13 +100,14 @@ public void testDeprecatedMessage() throws IOException { ); } } - class CustomMessage extends ESLogMessage{ - CustomMessage() { - super(Map.of("message","overriden"), "some message"); - } - } public void testMessageOverride() throws IOException { + class CustomMessage extends ESLogMessage{ + CustomMessage() { + super(Map.of("message","overriden"), "some message"); + } + } + final Logger testLogger = LogManager.getLogger("custom.test"); testLogger.info(new CustomMessage()); @@ -129,6 +130,38 @@ public void testMessageOverride() throws IOException { } } + public void testCustomMessageWithMultipleFields() throws IOException { + // if a field is defined to be overriden, it has to always be overriden in that appender. + class CustomMessage extends ESLogMessage{ + CustomMessage() { + super(Map.of("field1","value1","field2","value2", "message", "some message"), "some message"); + } + } + + final Logger testLogger = LogManager.getLogger("custom.test"); + testLogger.info(new CustomMessage()); + + 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("field1", "value1"), + hasEntry("field2", "value2"), + hasEntry("message", "some message")) + ) + ); + } + } + public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { final Logger testLogger = LogManager.getLogger("deprecation.test"); @@ -384,7 +417,7 @@ private List collectLines(Stream stream) { } 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 087ee77dbfb6c..96c5b943625f2 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 @@ -25,7 +25,7 @@ appender.customconsole.type = Console appender.customconsole.name = customconsole appender.customconsole.layout.type = ESJsonLayout appender.customconsole.layout.type_name = custom -appender.customconsole.layout.esmessagefields = message +appender.customconsole.layout.overrideFields = message appender.custom.type = File appender.custom.name = custom @@ -33,7 +33,7 @@ appender.custom.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es .cluster_name}_custom.json appender.custom.layout.type = ESJsonLayout appender.custom.layout.type_name = custom -appender.custom.layout.esmessagefields = message +appender.custom.layout.overrideFields = message rootLogger.level = info rootLogger.appenderRef.console.ref = console diff --git a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java index 50c908aad5acb..266f0803f8d56 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -32,7 +32,8 @@ 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 = "CustomMapFields") @@ -65,18 +66,20 @@ public void format(LogEvent event, StringBuilder toAppendTo) { if (event.getMessage() instanceof ESLogMessage) { ESLogMessage logMessage = (ESLogMessage) event.getMessage(); + String separator = ""; Map fields = logMessage.getFields(); for (String key : fields.keySet()) { if (overridenFields.contains(key) == false) { String value = logMessage.getValueFor(key); if (Strings.isNullOrEmpty(value) == false) { - String message = ESLogMessage.inQuotes(key) + ":" + ESLogMessage.inQuotes(value); - StringBuilders.appendValue(toAppendTo, message); - return; + StringBuilders.appendValue(toAppendTo, separator); + StringBuilders.appendValue(toAppendTo, ESLogMessage.inQuotes(key)); + StringBuilders.appendValue(toAppendTo, ":"); + StringBuilders.appendValue(toAppendTo, ESLogMessage.inQuotes(value)); + separator = ", "; } } } } - StringBuilders.appendValue(toAppendTo, ""); } } 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 469a3f8e16620..ba0ea86240f02 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -58,14 +58,15 @@ * 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 + * It is possible to add more field by extending ESLogMessage which expects a map of fields + * or override them with esmessagefield + * appender.logger.layout.overrideFields=message * 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} ... + * ... "message": %ESMessageField{message} ... * the message passed to a logger will be overriden with a value from %ESMessageField{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 { @@ -73,16 +74,16 @@ 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(",",esmessagefields); + 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"); } @@ -95,21 +96,21 @@ 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) { + for (String key : overrideFields) { map.put(key, inQuotes("%ESMessageField{" + 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); @@ -150,8 +151,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() { @@ -167,8 +168,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); @@ -176,7 +177,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); } @@ -198,12 +199,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(); } } From b23ffb1e9e18e9a89866b7a01814cda1ba5a43d4 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 13 Sep 2019 15:16:23 +0200 Subject: [PATCH 03/12] javadoc --- .../java/org/elasticsearch/common/logging/ESJsonLayout.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 ba0ea86240f02..cf9619271fe0d 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -59,7 +59,7 @@ * *

* It is possible to add more field by extending ESLogMessage which expects a map of fields - * or override them with esmessagefield + * or override them with overrideFields * appender.logger.layout.overrideFields=message * Each of these will be expanded into a json field with a value taken {@link ESLogMessage} field. In the example above * ... "message": %ESMessageField{message} ... From 5605955b659cbc2877369a16a2af2e37e5c13641 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 27 Sep 2019 13:29:40 +0200 Subject: [PATCH 04/12] simplify custom message class creation --- .../common/logging/JsonLoggerTests.java | 36 +++++++++++++++---- .../routing/allocation/AllocationService.java | 6 +++- .../common/logging/ESLogMessage.java | 10 ++++++ 3 files changed, 45 insertions(+), 7 deletions(-) diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java index 3c2996bdb0c91..5202e33466722 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 @@ -101,15 +101,38 @@ public void testDeprecatedMessage() throws IOException { } } - public void testMessageOverride() throws IOException { - class CustomMessage extends ESLogMessage{ - CustomMessage() { - super(Map.of("message","overriden"), "some message"); - } + 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(ESLogMessage.message("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 testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(new CustomMessage()); + + testLogger.info(ESLogMessage.message("some message") + .with("message","overriden")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_custom.json"); @@ -141,6 +164,7 @@ class CustomMessage extends ESLogMessage{ final Logger testLogger = LogManager.getLogger("custom.test"); testLogger.info(new CustomMessage()); + 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)) { 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 eb139589724ae..5d57f696693a3 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,10 @@ 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(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).", previousHealth, currentHealth, reason) + .with("previous.health", previousHealth) + .with("current.health", currentHealth) + .with("reason", reason)); } } 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 844440e16a3fd..2f9a4e348c469 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -24,6 +24,7 @@ import org.elasticsearch.common.SuppressLoggerChecks; import java.nio.charset.Charset; +import java.util.LinkedHashMap; import java.util.Map; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -45,6 +46,10 @@ public ESLogMessage(Map fields, String messagePattern, Object... this.fields = fields; } + public ESLogMessage with(String key, Object value) { + fields.put(key, value); + return this; + } public static String escapeJson(String text) { byte[] sourceEscaped = JSON_STRING_ENCODER.quoteAsUTF8(text); return new String(sourceEscaped, Charset.defaultCharset()); @@ -76,4 +81,9 @@ public static String asJsonArray(Stream stream) { .map(ESLogMessage::inQuotes) .collect(Collectors.joining(", ")) + "]"; } + + public static ESLogMessage message(String messagePattern, Object... args){ + return new ESLogMessage(new LinkedHashMap<>(), messagePattern, args) { + }; + } } From 74cb5637f212422ff86c5c96488de934fcdc8a6f Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 27 Sep 2019 13:50:24 +0200 Subject: [PATCH 05/12] line length --- .../cluster/routing/allocation/AllocationService.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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 5d57f696693a3..01e160c131905 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 @@ -379,7 +379,8 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).", previousHealth, currentHealth, reason) + logger.info(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).", + previousHealth, currentHealth, reason) .with("previous.health", previousHealth) .with("current.health", currentHealth) .with("reason", reason)); From ba1bf6fe507ca4ebb6c856e0210fa6271413fd6b Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Mon, 30 Sep 2019 13:39:13 +0200 Subject: [PATCH 06/12] small cleanup and rename of ESJsonField --- .../common/logging/ESJsonLayoutTests.java | 2 +- .../common/logging/ESJsonLayout.java | 13 ++++++------- ...onverter.java => OverrideFieldConverter.java} | 16 ++++++++-------- 3 files changed, 15 insertions(+), 16 deletions(-) rename server/src/main/java/org/elasticsearch/common/logging/{ESMessageFieldConverter.java => OverrideFieldConverter.java} (80%) 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 eef5a55d55001..80c110eff42df 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 @@ -69,7 +69,7 @@ public void testLayoutWithAdditionalFieldOverride() { "\"component\": \"%c{1.}\", " + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + "\"node.name\": \"%node_name\"" + - "%notEmpty{, \"message\": \"%ESMessageField{message}\"}" + + "%notEmpty{, \"message\": \"%OverrideField{message}\"}" + "%notEmpty{, %node_and_cluster_id }" + "%notEmpty{, %CustomMapFields{message} }" + "%exceptionAsJson }" + System.lineSeparator())); 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 cf9619271fe0d..be5a8f406c284 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -58,12 +58,11 @@ * Taken from JsonThrowablePatternConverter * *

- * It is possible to add more field by extending ESLogMessage which expects a map of fields - * or override them with overrideFields - * appender.logger.layout.overrideFields=message - * Each of these will be expanded into a json field with a value taken {@link ESLogMessage} field. In the example above - * ... "message": %ESMessageField{message} ... - * 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 ESLogMessage has to be a simple escaped JSON value. @@ -97,7 +96,7 @@ private String pattern(String type, String[] overrideFields) { map.put("message", inQuotes("%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}")); for (String key : overrideFields) { - map.put(key, inQuotes("%ESMessageField{" + key + "}")); + map.put(key, inQuotes("%OverrideField{" + key + "}")); } return createPattern(map, Set.of(overrideFields)); diff --git a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java b/server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java similarity index 80% rename from server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java rename to server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java index 40d702bc76bc5..c66d1efb04ffd 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESMessageFieldConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java @@ -29,26 +29,26 @@ import org.elasticsearch.common.Strings; /** - * Pattern converter to populate ESMessageField in a pattern. + * Pattern converter to populate OverrideField 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 { +@Plugin(category = PatternConverter.CATEGORY, name = "OverrideField") +@ConverterKeys({"OverrideField"}) +public final class OverrideFieldConverter extends LogEventPatternConverter { private String key; /** * Called by log4j2 to initialize this converter. */ - public static ESMessageFieldConverter newInstance(final Configuration config, final String[] options) { + public static OverrideFieldConverter newInstance(final Configuration config, final String[] options) { final String key = options[0]; - return new ESMessageFieldConverter(key); + return new OverrideFieldConverter(key); } - public ESMessageFieldConverter(String key) { - super("ESMessageField", "ESMessageField"); + public OverrideFieldConverter(String key) { + super("OverrideField", "OverrideField"); this.key = key; } From bf0d6708f32c13050b0e1aeb69681a0cbe0f5249 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Wed, 2 Oct 2019 15:04:25 +0200 Subject: [PATCH 07/12] working with builder --- .../common/logging/JsonLoggerTests.java | 31 +++++++++++- .../routing/allocation/AllocationService.java | 11 +++-- .../common/logging/ESLogMessage.java | 41 ++++++++++++++-- .../ParameterizedStructuredMessage.java | 48 +++++++++++++++++++ 4 files changed, 121 insertions(+), 10 deletions(-) create mode 100644 server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java 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 5202e33466722..4b8c65a04fc38 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 @@ -125,14 +125,43 @@ public void testMessageOverrideWithNoValue() throws IOException { ); } } + public void testMessageOverride2() throws IOException { + final Logger testLogger = LogManager.getLogger("test"); + + testLogger.info(ESLogMessage.message("some message {} {}") + .param("value") + .paramField("key1","value1") + .field("key2","value2") + .build()); + + final Path path = clusterLogsPath(); + 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 value value1"), + hasEntry("key1", "value1"), + hasEntry("key2", "value2")) + ) + ); + } + } public void testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); testLogger.info(ESLogMessage.message("some message") - .with("message","overriden")); + .field("message","overriden") + .build()); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_custom.json"); 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 01e160c131905..d8ab3f7df73c5 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 @@ -379,11 +379,12 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).", - previousHealth, currentHealth, reason) - .with("previous.health", previousHealth) - .with("current.health", currentHealth) - .with("reason", reason)); + logger.info(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).") + .paramField("previous.health", previousHealth) + .paramField("current.health", currentHealth) + .paramField("reason", reason) + .build()); + } } 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 2f9a4e348c469..b9060fa8207dc 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -24,7 +24,9 @@ import org.elasticsearch.common.SuppressLoggerChecks; import java.nio.charset.Charset; +import java.util.ArrayList; import java.util.LinkedHashMap; +import java.util.List; import java.util.Map; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -32,7 +34,7 @@ /** * 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 ParameterizedMessage { private static final JsonStringEncoder JSON_STRING_ENCODER = JsonStringEncoder.getInstance(); private final Map fields; @@ -82,8 +84,39 @@ public static String asJsonArray(Stream stream) { .collect(Collectors.joining(", ")) + "]"; } - public static ESLogMessage message(String messagePattern, Object... args){ - return new ESLogMessage(new LinkedHashMap<>(), messagePattern, args) { - }; + public static ESLogMessageBuilder message(String messagePattern){ + return new ESLogMessageBuilder().message(messagePattern); + } + + public static class ESLogMessageBuilder { + private String parametrizedMessage; + private List parameters = new ArrayList<>(); + private Map fields = new LinkedHashMap<>(); + + public ESLogMessageBuilder message(String parametrizedMessage){ + this.parametrizedMessage = parametrizedMessage; + return this; + } + + public ESLogMessageBuilder param(Object object){ + parameters.add(object); + return this; + } + + public ESLogMessageBuilder paramField(String key, Object value){ + parameters.add(value); + fields.put(key,value); + return this; + } + + public ESLogMessageBuilder field(String key, Object value){ + fields.put(key,value); + return this; + } + + public ESLogMessage build(){ + return new ESLogMessage(fields, parametrizedMessage, parameters.toArray()) ; + } + } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java new file mode 100644 index 0000000000000..ac014bb8f78f2 --- /dev/null +++ b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java @@ -0,0 +1,48 @@ +package org.elasticsearch.common.logging; + +import org.apache.logging.log4j.message.MapMessage; +import org.apache.logging.log4j.message.ParameterizedMessage; +import org.apache.logging.log4j.util.TriConsumer; + +public class ParameterizedStructuredMessage extends MapMessage { + + private static final String MESSAGE = "message"; + private static final TriConsumer ADD_KEY_VALUE_PAIR = new TriConsumer<>() { + @Override + public void accept(String key, Object value, StringBuilder builder) { + if (!MESSAGE.equals(key)) { + builder.append(' ').append(key).append('[').append(value).append(']'); + } + } + }; + + private final String message; + + private ParameterizedStructuredMessage(String message) { + this.message = message; + with(MESSAGE, message); + } + + private ParameterizedStructuredMessage(String messagePattern, Object... arguments) { + this.message = ParameterizedMessage.format(messagePattern, arguments); + with(MESSAGE, message); + } + + public static ParameterizedStructuredMessage of(String message) { + return new ParameterizedStructuredMessage(message); + } + + public static ParameterizedStructuredMessage of(String messagePattern, Object... arguments) { + return new ParameterizedStructuredMessage(messagePattern, arguments); + } + + @Override + protected void asJson(StringBuilder sb) { + super.asJson(sb); + } + + protected void appendMap(final StringBuilder sb) { + sb.append(message); + forEach(ADD_KEY_VALUE_PAIR, sb); + } +} From ae1bc993b8714c0a1bf949b41b1774388e8ae98c Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Wed, 2 Oct 2019 16:21:32 +0200 Subject: [PATCH 08/12] parametrized map - basing on ecs --- .../common/logging/JsonLoggerTests.java | 35 +++++--- .../logging/json_layout/log4j2.properties | 8 ++ .../logging/CustomMapFieldsConverter.java | 6 +- .../ParameterizedStructuredMessage.java | 84 ++++++++++++++----- 4 files changed, 96 insertions(+), 37 deletions(-) diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java index 4b8c65a04fc38..9b5a680185913 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 @@ -37,7 +37,9 @@ import org.hamcrest.Matchers; import org.junit.BeforeClass; +import java.io.BufferedReader; import java.io.IOException; +import java.nio.file.Files; import java.nio.file.Path; import java.util.List; import java.util.Map; @@ -125,29 +127,29 @@ public void testMessageOverrideWithNoValue() throws IOException { ); } } - public void testMessageOverride2() throws IOException { + public void testBuildingMessage() throws IOException { - final Logger testLogger = LogManager.getLogger("test"); + final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ESLogMessage.message("some message {} {}") - .param("value") - .paramField("key1","value1") - .field("key2","value2") + testLogger.info(ParameterizedStructuredMessage.of("some message {} {}", "value0") + .with("key1","value1") + .with("key2","value2") .build()); - final Path path = clusterLogsPath(); + 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", "file"), + hasEntry("type", "custom"), hasEntry("level", "INFO"), - hasEntry("component", "test"), + hasEntry("component", "c.test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), - hasEntry("message", "some message value value1"), + hasEntry("message", "some message value0 value1"), hasEntry("key1", "value1"), hasEntry("key2", "value2")) ) @@ -158,10 +160,10 @@ public void testMessageOverride2() throws IOException { public void testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); + testLogger.info(ParameterizedStructuredMessage.of("some message") + .with("message","overriden") + .build()); - testLogger.info(ESLogMessage.message("some message") - .field("message","overriden") - .build()); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_custom.json"); @@ -180,6 +182,13 @@ public void testMessageOverride() throws IOException { ) ); } + + 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 { 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 96c5b943625f2..c85154f1f2df1 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 @@ -39,6 +39,13 @@ 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 = trace logger.deprecation.appenderRef.deprecation_rolling.ref = deprecated @@ -50,6 +57,7 @@ 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 diff --git a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java index 266f0803f8d56..d1e70b5564360 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -63,7 +63,7 @@ private static Set csvToSet(String csv) { @Override public void format(LogEvent event, StringBuilder toAppendTo) { - if (event.getMessage() instanceof ESLogMessage) { + if (event.getMessage() instanceof ESLogMessage ) { ESLogMessage logMessage = (ESLogMessage) event.getMessage(); String separator = ""; @@ -81,5 +81,9 @@ public void format(LogEvent event, StringBuilder toAppendTo) { } } } + if(event.getMessage() instanceof ParameterizedStructuredMessage) { + ParameterizedStructuredMessage logMessage = (ParameterizedStructuredMessage) event.getMessage(); + logMessage.asJson(toAppendTo); + } } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java index ac014bb8f78f2..846885ffbb798 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java @@ -2,47 +2,85 @@ import org.apache.logging.log4j.message.MapMessage; import org.apache.logging.log4j.message.ParameterizedMessage; +import org.apache.logging.log4j.util.Chars; +import org.apache.logging.log4j.util.StringBuilders; import org.apache.logging.log4j.util.TriConsumer; +import org.elasticsearch.index.query.SimpleQueryStringBuilder; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.List; +import java.util.Map; public class ParameterizedStructuredMessage extends MapMessage { private static final String MESSAGE = "message"; - private static final TriConsumer ADD_KEY_VALUE_PAIR = new TriConsumer<>() { - @Override - public void accept(String key, Object value, StringBuilder builder) { - if (!MESSAGE.equals(key)) { - builder.append(' ').append(key).append('[').append(value).append(']'); - } - } - }; private final String message; - private ParameterizedStructuredMessage(String message) { + public ParameterizedStructuredMessage(String message, Map map) { + super(map); this.message = message; - with(MESSAGE, message); } - private ParameterizedStructuredMessage(String messagePattern, Object... arguments) { - this.message = ParameterizedMessage.format(messagePattern, arguments); - with(MESSAGE, message); + public static ParameterizedStructuredMessageBuilder of(String messagePattern, Object... arguments) { + return new ParameterizedStructuredMessageBuilder(messagePattern, arguments); } - public static ParameterizedStructuredMessage of(String message) { - return new ParameterizedStructuredMessage(message); - } - - public static ParameterizedStructuredMessage of(String messagePattern, Object... arguments) { - return new ParameterizedStructuredMessage(messagePattern, arguments); + @Override + protected void appendMap(final StringBuilder sb) { + sb.append(message); } + //taken from super.asJson without the wrapping '{' '}' @Override protected void asJson(StringBuilder sb) { - super.asJson(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()); +// ParameterFormatter.recursiveDeepToString(getIndexedReadOnlyStringMap().getValueAt(i), sb, null); + StringBuilders.escapeJson(sb, start); + sb.append(Chars.DQUOTE); + } } - protected void appendMap(final StringBuilder sb) { - sb.append(message); - forEach(ADD_KEY_VALUE_PAIR, sb); + public static class ParameterizedStructuredMessageBuilder { + + private String messagePattern; + private List arguments = new ArrayList<>(); + private Map fields = new LinkedHashMap<>(); + + public ParameterizedStructuredMessageBuilder(String messagePattern, Object[] arguments) { + this.messagePattern = messagePattern; + Collections.addAll(this.arguments, arguments); + } + + public ParameterizedStructuredMessageBuilder with(String key, Object value) { + this.arguments.add(value); + fields.put(key, value); + return this; + } + + public ParameterizedStructuredMessageBuilder field(String key, Object value) { + fields.put(key, value); + return this; + } + + public ParameterizedStructuredMessage build() { + messagePattern = ParameterizedMessage.format(messagePattern, arguments.toArray()); + if(fields.containsKey(MESSAGE) == false){ + with(MESSAGE, messagePattern); + } + return new ParameterizedStructuredMessage(messagePattern, fields); + } } } From 9c38db3122571af690a993bffb3b6d2545aca410 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 4 Oct 2019 14:42:28 +0200 Subject: [PATCH 09/12] builder --- .../common/logging/ESJsonLayoutTests.java | 2 +- .../common/logging/JsonLoggerTests.java | 58 ++++++++-------- .../logging/json_layout/log4j2.properties | 8 ++- .../routing/allocation/AllocationService.java | 12 ++-- .../logging/CustomMapFieldsConverter.java | 18 ----- .../common/logging/DeprecatedMessage.java | 17 ++--- .../common/logging/DeprecationLogger.java | 2 +- .../common/logging/ESJsonLayout.java | 4 +- .../logging/OverrideFieldConverter.java | 67 ------------------- .../ParameterizedStructuredMessage.java | 49 ++++++++++++-- 10 files changed, 96 insertions(+), 141 deletions(-) delete mode 100644 server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java 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 80c110eff42df..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 @@ -61,6 +61,7 @@ public void testLayoutWithAdditionalFieldOverride() { .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\", " + @@ -69,7 +70,6 @@ public void testLayoutWithAdditionalFieldOverride() { "\"component\": \"%c{1.}\", " + "\"cluster.name\": \"${sys:es.logs.cluster_name}\", " + "\"node.name\": \"%node_name\"" + - "%notEmpty{, \"message\": \"%OverrideField{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 9b5a680185913..242989451b73f 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 @@ -37,7 +37,6 @@ import org.hamcrest.Matchers; import org.junit.BeforeClass; -import java.io.BufferedReader; import java.io.IOException; import java.nio.file.Files; import java.nio.file.Path; @@ -81,7 +80,10 @@ public void tearDown() throws Exception { } public void testDeprecatedMessage() throws IOException { final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); + testLogger.info(ParameterizedStructuredMessage.of2("deprecated message1") + .with("x-opaque-id","someId")); + +// new DeprecatedMessage("deprecated message1", "someId")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_deprecated.json"); @@ -108,7 +110,7 @@ public void testMessageOverrideWithNoValue() throws IOException { //Expected is that it will be emptied final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ESLogMessage.message("some message")); + testLogger.info(ParameterizedStructuredMessage.of2("some message")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_custom.json"); @@ -129,24 +131,23 @@ public void testMessageOverrideWithNoValue() throws IOException { } public void testBuildingMessage() throws IOException { - final Logger testLogger = LogManager.getLogger("custom.test"); + final Logger testLogger = LogManager.getLogger("test"); - testLogger.info(ParameterizedStructuredMessage.of("some message {} {}", "value0") + testLogger.info(ParameterizedStructuredMessage.of2("some message {} {}", "value0") .with("key1","value1") - .with("key2","value2") - .build()); + .with("key2","value2")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), - System.getProperty("es.logs.cluster_name") + "_custom.json"); + 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", "custom"), + hasEntry("type", "file"), hasEntry("level", "INFO"), - hasEntry("component", "c.test"), + hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("message", "some message value0 value1"), @@ -161,8 +162,7 @@ public void testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); testLogger.info(ParameterizedStructuredMessage.of("some message") - .with("message","overriden") - .build()); + .with("message","overriden")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), @@ -186,34 +186,31 @@ public void testMessageOverride() throws IOException { 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")); + 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. - class CustomMessage extends ESLogMessage{ - CustomMessage() { - super(Map.of("field1","value1","field2","value2", "message", "some message"), "some message"); - } - } + final Logger testLogger = LogManager.getLogger("test"); + testLogger.info(ParameterizedStructuredMessage.of2("some message") + .with("field1","value1") + .with("field2","value2")); - final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(new CustomMessage()); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), - System.getProperty("es.logs.cluster_name") + "_custom.json"); + 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", "custom"), + hasEntry("type", "file"), hasEntry("level", "INFO"), - hasEntry("component", "c.test"), + hasEntry("component", "test"), hasEntry("cluster.name", "elasticsearch"), hasEntry("node.name", "sample-name"), hasEntry("field1", "value1"), @@ -227,9 +224,9 @@ class CustomMessage extends ESLogMessage{ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException { final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info(new DeprecatedMessage("deprecated message1", "someId")); - testLogger.info(new DeprecatedMessage("deprecated message2", "")); - testLogger.info(new DeprecatedMessage("deprecated message3", null)); + 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"), @@ -302,19 +299,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") )); } } @@ -474,7 +471,6 @@ public void testDuplicateLogMessages() throws IOException { private List collectLines(Stream stream) { return stream - .skip(1)//skip the first line from super class .collect(Collectors.toList()); } 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 c85154f1f2df1..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 @@ -37,7 +37,6 @@ 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 @@ -65,3 +64,10 @@ logger.test.level = trace logger.test.appenderRef.console.ref = console logger.test.appenderRef.file.ref = file 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 d8ab3f7df73c5..dfbdfe2e03f25 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,7 +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.common.logging.ParameterizedStructuredMessage; import org.elasticsearch.gateway.GatewayAllocator; import java.util.ArrayList; @@ -379,11 +379,11 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info(ESLogMessage.message("Cluster health status changed from [{}] to [{}] (reason: [{}]).") - .paramField("previous.health", previousHealth) - .paramField("current.health", currentHealth) - .paramField("reason", reason) - .build()); + logger.info(ParameterizedStructuredMessage.of("Cluster health status changed from [{}] to [{}] (reason: [{}]).") + .with("previous.health", previousHealth) + .with("current.health", currentHealth) + .with("reason", reason) + .build()); } } diff --git a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java index d1e70b5564360..01183dcbc26f6 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -63,24 +63,6 @@ private static Set csvToSet(String csv) { @Override public void format(LogEvent event, StringBuilder toAppendTo) { - if (event.getMessage() instanceof ESLogMessage ) { - ESLogMessage logMessage = (ESLogMessage) event.getMessage(); - - String separator = ""; - Map fields = logMessage.getFields(); - for (String key : fields.keySet()) { - if (overridenFields.contains(key) == false) { - String value = logMessage.getValueFor(key); - if (Strings.isNullOrEmpty(value) == false) { - StringBuilders.appendValue(toAppendTo, separator); - StringBuilders.appendValue(toAppendTo, ESLogMessage.inQuotes(key)); - StringBuilders.appendValue(toAppendTo, ":"); - StringBuilders.appendValue(toAppendTo, ESLogMessage.inQuotes(value)); - separator = ", "; - } - } - } - } if(event.getMessage() instanceof ParameterizedStructuredMessage) { ParameterizedStructuredMessage logMessage = (ParameterizedStructuredMessage) event.getMessage(); logMessage.asJson(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..177d0f1303c02 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -28,17 +28,18 @@ * 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 class DeprecatedMessage { + private static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; - public DeprecatedMessage(String messagePattern, String xOpaqueId, Object... args) { - super(fieldMap(xOpaqueId), messagePattern, args); - } - private static Map fieldMap(String xOpaqueId) { + public static ParameterizedStructuredMessage of(String xOpaqueId, String messagePattern, Object... args){ if (Strings.isNullOrEmpty(xOpaqueId)) { - return Collections.emptyMap(); + return ParameterizedStructuredMessage.of(messagePattern,args) + .build(); } - - return Map.of("x-opaque-id", xOpaqueId); + return ParameterizedStructuredMessage.of(messagePattern,args) + .field(X_OPAQUE_ID_FIELD_NAME, xOpaqueId) + .build(); } + } 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 be5a8f406c284..0bccc15e1d9da 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java @@ -95,8 +95,10 @@ private String pattern(String type, String[] overrideFields) { map.put("node.name", inQuotes("%node_name")); map.put("message", inQuotes("%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}")); + + // overridden fields are expected to be present in a log message for (String key : overrideFields) { - map.put(key, inQuotes("%OverrideField{" + key + "}")); + map.remove(key); } return createPattern(map, Set.of(overrideFields)); diff --git a/server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java b/server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java deleted file mode 100644 index c66d1efb04ffd..0000000000000 --- a/server/src/main/java/org/elasticsearch/common/logging/OverrideFieldConverter.java +++ /dev/null @@ -1,67 +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.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 OverrideField in a pattern. - * It will only populate these if the event have message of type ESLogMessage. - */ -@Plugin(category = PatternConverter.CATEGORY, name = "OverrideField") -@ConverterKeys({"OverrideField"}) -public final class OverrideFieldConverter extends LogEventPatternConverter { - - private String key; - - /** - * Called by log4j2 to initialize this converter. - */ - public static OverrideFieldConverter newInstance(final Configuration config, final String[] options) { - final String key = options[0]; - - return new OverrideFieldConverter(key); - } - - public OverrideFieldConverter(String key) { - super("OverrideField", "OverrideField"); - 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/logging/ParameterizedStructuredMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java index 846885ffbb798..4eb4adba1787a 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java @@ -4,7 +4,9 @@ import org.apache.logging.log4j.message.ParameterizedMessage; import org.apache.logging.log4j.util.Chars; import org.apache.logging.log4j.util.StringBuilders; +import org.apache.logging.log4j.util.Supplier; import org.apache.logging.log4j.util.TriConsumer; +import org.elasticsearch.action.admin.cluster.reroute.ClusterRerouteRequestBuilder; import org.elasticsearch.index.query.SimpleQueryStringBuilder; import java.util.ArrayList; @@ -16,20 +18,45 @@ public class ParameterizedStructuredMessage extends MapMessage { private static final String MESSAGE = "message"; + private Supplier message; - private final String message; + private String messagePattern; + private List arguments = new ArrayList<>(); - public ParameterizedStructuredMessage(String message, Map map) { + public ParameterizedStructuredMessage(Supplier message, Map map) { super(map); this.message = message; } + public ParameterizedStructuredMessage(String messagePattern, Object... arguments) { + super(new LinkedHashMap<>()); + this.messagePattern = messagePattern; + Collections.addAll(this.arguments, arguments); + } + + public static ParameterizedStructuredMessage of2(String messagePattern, Object... arguments){ + return new ParameterizedStructuredMessage(messagePattern, arguments); + } + + public ParameterizedStructuredMessage with(String key, Object value) { + this.arguments.add(value); + super.with(key,value); + return this; + } + + public ParameterizedStructuredMessage field(String key, Object value) { + super.with(key,value); + return this; + } + + public static ParameterizedStructuredMessageBuilder of(String messagePattern, Object... arguments) { return new ParameterizedStructuredMessageBuilder(messagePattern, arguments); } @Override protected void appendMap(final StringBuilder sb) { + String message = ParameterizedMessage.format(messagePattern, arguments.toArray()); sb.append(message); } @@ -76,11 +103,19 @@ public ParameterizedStructuredMessageBuilder field(String key, Object value) { } public ParameterizedStructuredMessage build() { - messagePattern = ParameterizedMessage.format(messagePattern, arguments.toArray()); - if(fields.containsKey(MESSAGE) == false){ - with(MESSAGE, messagePattern); - } - return new ParameterizedStructuredMessage(messagePattern, fields); + Supplier messageSupplier = () -> ParameterizedMessage.format(messagePattern, arguments.toArray()); + +// if(fields.containsKey(MESSAGE) == false){ +// with(MESSAGE, new Object(){ +// @Override +// public String toString() { +// return messageSupplier.get(); +// } +// }); +// +// +// } + return new ParameterizedStructuredMessage(messageSupplier, fields); } } } From 9f307c896f66d038e3e3d6b59a951b97a3be6210 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 4 Oct 2019 18:10:18 +0200 Subject: [PATCH 10/12] refactoring and cleanup --- .../common/logging/JsonLoggerTests.java | 23 ++-- .../routing/allocation/AllocationService.java | 11 +- .../logging/CustomMapFieldsConverter.java | 7 +- .../common/logging/DeprecatedMessage.java | 16 +-- .../common/logging/ESLogMessage.java | 109 ++++++++-------- .../ParameterizedStructuredMessage.java | 121 ------------------ .../elasticsearch/index/IndexingSlowLog.java | 29 +++-- .../elasticsearch/index/SearchSlowLog.java | 32 +++-- .../logging/DeprecationLoggerTests.java | 2 +- .../index/IndexingSlowLogTests.java | 31 ++--- .../index/SearchSlowLogTests.java | 31 ++--- 11 files changed, 148 insertions(+), 264 deletions(-) delete mode 100644 server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java 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 242989451b73f..5f11f6d565543 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 @@ -80,8 +80,8 @@ public void tearDown() throws Exception { } public void testDeprecatedMessage() throws IOException { final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info(ParameterizedStructuredMessage.of2("deprecated message1") - .with("x-opaque-id","someId")); + testLogger.info(ESLogMessage.of("deprecated message1") + .with("x-opaque-id","someId")); // new DeprecatedMessage("deprecated message1", "someId")); @@ -110,7 +110,7 @@ public void testMessageOverrideWithNoValue() throws IOException { //Expected is that it will be emptied final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ParameterizedStructuredMessage.of2("some message")); + testLogger.info(ESLogMessage.of("some message")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + "_custom.json"); @@ -133,9 +133,9 @@ public void testBuildingMessage() throws IOException { final Logger testLogger = LogManager.getLogger("test"); - testLogger.info(ParameterizedStructuredMessage.of2("some message {} {}", "value0") - .with("key1","value1") - .with("key2","value2")); + testLogger.info(ESLogMessage.of("some message {} {}", "value0") + .argAndField("key1","value1") + .argAndField("key2","value2")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".json"); @@ -161,8 +161,8 @@ public void testBuildingMessage() throws IOException { public void testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ParameterizedStructuredMessage.of("some message") - .with("message","overriden")); + testLogger.info(ESLogMessage.of("some message") + .with("message","overriden")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), @@ -194,10 +194,9 @@ public void testMessageOverride() throws IOException { 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(ParameterizedStructuredMessage.of2("some message") - .with("field1","value1") - .with("field2","value2")); - + testLogger.info(ESLogMessage.of("some message") + .with("field1","value1") + .with("field2","value2")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), 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 dfbdfe2e03f25..6a804556d2377 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,7 +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.ParameterizedStructuredMessage; +import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.gateway.GatewayAllocator; import java.util.ArrayList; @@ -379,11 +379,10 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info(ParameterizedStructuredMessage.of("Cluster health status changed from [{}] to [{}] (reason: [{}]).") - .with("previous.health", previousHealth) - .with("current.health", currentHealth) - .with("reason", reason) - .build()); + logger.info(ESLogMessage.of("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/CustomMapFieldsConverter.java b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java index 01183dcbc26f6..0ac5bf029c389 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java +++ b/server/src/main/java/org/elasticsearch/common/logging/CustomMapFieldsConverter.java @@ -25,10 +25,7 @@ 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.Map; import java.util.Set; /** @@ -63,8 +60,8 @@ private static Set csvToSet(String csv) { @Override public void format(LogEvent event, StringBuilder toAppendTo) { - if(event.getMessage() instanceof ParameterizedStructuredMessage) { - ParameterizedStructuredMessage logMessage = (ParameterizedStructuredMessage) event.getMessage(); + if(event.getMessage() instanceof ESLogMessage) { + ESLogMessage logMessage = (ESLogMessage) event.getMessage(); logMessage.asJson(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 177d0f1303c02..a4082e26043bb 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java @@ -21,9 +21,6 @@ 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. @@ -31,15 +28,12 @@ public class DeprecatedMessage { private static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; - - public static ParameterizedStructuredMessage of(String xOpaqueId, String messagePattern, Object... args){ + public static ESLogMessage of(String xOpaqueId, String messagePattern, Object... args){ if (Strings.isNullOrEmpty(xOpaqueId)) { - return ParameterizedStructuredMessage.of(messagePattern,args) - .build(); + return ESLogMessage.of(messagePattern,args); } - return ParameterizedStructuredMessage.of(messagePattern,args) - .field(X_OPAQUE_ID_FIELD_NAME, xOpaqueId) - .build(); - } + return ESLogMessage.of(messagePattern,args) + .with(X_OPAQUE_ID_FIELD_NAME, xOpaqueId); + } } 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 b9060fa8207dc..e4315e8d5b614 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -16,15 +16,17 @@ * 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; @@ -34,36 +36,62 @@ /** * A base class for custom log4j logger messages. Carries additional fields which will populate JSON fields in logs. */ -public 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 ESLogMessage of(String messagePattern, Object... arguments){ + return new ESLogMessage(messagePattern, arguments); } - public ESLogMessage with(String key, Object value) { - fields.put(key, value); + public ESLogMessage argAndField(String key, Object value) { + this.arguments.add(value); + super.with(key,value); return this; } - public static String escapeJson(String text) { - byte[] sourceEscaped = JSON_STRING_ENCODER.quoteAsUTF8(text); - return new String(sourceEscaped, Charset.defaultCharset()); + + public ESLogMessage field(String key, Object value) { + super.with(key,value); + return this; } - public Map getFields(){ - return fields; + public ESLogMessage withFields(Map prepareMap) { + prepareMap.forEach(this::field); + return this; } - public String getValueFor(String key) { - Object value = fields.get(key); - return value!=null ? value.toString() : null; + @Override + protected void appendMap(final StringBuilder sb) { + String message = ParameterizedMessage.format(messagePattern, arguments.toArray()); + sb.append(message); + } + + //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()); +// ParameterFormatter.recursiveDeepToString(getIndexedReadOnlyStringMap().getValueAt(i), sb, null); + StringBuilders.escapeJson(sb, start); + sb.append(Chars.DQUOTE); + } } public static String inQuotes(String s) { @@ -84,39 +112,8 @@ public static String asJsonArray(Stream stream) { .collect(Collectors.joining(", ")) + "]"; } - public static ESLogMessageBuilder message(String messagePattern){ - return new ESLogMessageBuilder().message(messagePattern); - } - - public static class ESLogMessageBuilder { - private String parametrizedMessage; - private List parameters = new ArrayList<>(); - private Map fields = new LinkedHashMap<>(); - - public ESLogMessageBuilder message(String parametrizedMessage){ - this.parametrizedMessage = parametrizedMessage; - return this; - } - - public ESLogMessageBuilder param(Object object){ - parameters.add(object); - return this; - } - - public ESLogMessageBuilder paramField(String key, Object value){ - parameters.add(value); - fields.put(key,value); - return this; - } - - public ESLogMessageBuilder field(String key, Object value){ - fields.put(key,value); - return this; - } - - public ESLogMessage build(){ - return new ESLogMessage(fields, parametrizedMessage, parameters.toArray()) ; - } - + 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/common/logging/ParameterizedStructuredMessage.java b/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java deleted file mode 100644 index 4eb4adba1787a..0000000000000 --- a/server/src/main/java/org/elasticsearch/common/logging/ParameterizedStructuredMessage.java +++ /dev/null @@ -1,121 +0,0 @@ -package org.elasticsearch.common.logging; - -import org.apache.logging.log4j.message.MapMessage; -import org.apache.logging.log4j.message.ParameterizedMessage; -import org.apache.logging.log4j.util.Chars; -import org.apache.logging.log4j.util.StringBuilders; -import org.apache.logging.log4j.util.Supplier; -import org.apache.logging.log4j.util.TriConsumer; -import org.elasticsearch.action.admin.cluster.reroute.ClusterRerouteRequestBuilder; -import org.elasticsearch.index.query.SimpleQueryStringBuilder; - -import java.util.ArrayList; -import java.util.Collections; -import java.util.LinkedHashMap; -import java.util.List; -import java.util.Map; - -public class ParameterizedStructuredMessage extends MapMessage { - - private static final String MESSAGE = "message"; - private Supplier message; - - private String messagePattern; - private List arguments = new ArrayList<>(); - - public ParameterizedStructuredMessage(Supplier message, Map map) { - super(map); - this.message = message; - } - - public ParameterizedStructuredMessage(String messagePattern, Object... arguments) { - super(new LinkedHashMap<>()); - this.messagePattern = messagePattern; - Collections.addAll(this.arguments, arguments); - } - - public static ParameterizedStructuredMessage of2(String messagePattern, Object... arguments){ - return new ParameterizedStructuredMessage(messagePattern, arguments); - } - - public ParameterizedStructuredMessage with(String key, Object value) { - this.arguments.add(value); - super.with(key,value); - return this; - } - - public ParameterizedStructuredMessage field(String key, Object value) { - super.with(key,value); - return this; - } - - - public static ParameterizedStructuredMessageBuilder of(String messagePattern, Object... arguments) { - return new ParameterizedStructuredMessageBuilder(messagePattern, arguments); - } - - @Override - protected void appendMap(final StringBuilder sb) { - String message = ParameterizedMessage.format(messagePattern, arguments.toArray()); - sb.append(message); - } - - //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()); -// ParameterFormatter.recursiveDeepToString(getIndexedReadOnlyStringMap().getValueAt(i), sb, null); - StringBuilders.escapeJson(sb, start); - sb.append(Chars.DQUOTE); - } - } - - public static class ParameterizedStructuredMessageBuilder { - - private String messagePattern; - private List arguments = new ArrayList<>(); - private Map fields = new LinkedHashMap<>(); - - public ParameterizedStructuredMessageBuilder(String messagePattern, Object[] arguments) { - this.messagePattern = messagePattern; - Collections.addAll(this.arguments, arguments); - } - - public ParameterizedStructuredMessageBuilder with(String key, Object value) { - this.arguments.add(value); - fields.put(key, value); - return this; - } - - public ParameterizedStructuredMessageBuilder field(String key, Object value) { - fields.put(key, value); - return this; - } - - public ParameterizedStructuredMessage build() { - Supplier messageSupplier = () -> ParameterizedMessage.format(messagePattern, arguments.toArray()); - -// if(fields.containsKey(MESSAGE) == false){ -// with(MESSAGE, new Object(){ -// @Override -// public String toString() { -// return messageSupplier.get(); -// } -// }); -// -// -// } - return new ParameterizedStructuredMessage(messageSupplier, fields); - } - } -} diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index faeb9d3bc26e8..90ae1362cb612 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,24 +153,35 @@ 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) { - IndexingSlowLogMessage(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { - super(prepareMap(index,doc,tookInNanos,reformat,maxSourceCharsToLog), - message(index,doc,tookInNanos,reformat,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); + + return ESLogMessage.of(plaintextMessage) + .withFields(jsonFields); } +// IndexingSlowLogMessage(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { +// super(prepareMap(index,doc,tookInNanos,reformat,maxSourceCharsToLog), +// message(index,doc,tookInNanos,reformat,maxSourceCharsToLog)); +// } + private static Map prepareMap(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { Map map = new HashMap<>(); diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java index f3db24a89f82a..59716b8d45e25 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 ESLogMessage.of(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 { @@ -220,6 +224,8 @@ private static String message(SearchContext context, long tookInNanos) { } return sb.toString(); } + + } private void setQueryWarnThreshold(TimeValue warnThreshold) { 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"))); From 2025181e5b6c711ce738a0a41e942acb77a7dfac Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Fri, 4 Oct 2019 18:15:58 +0200 Subject: [PATCH 11/12] cleanup --- .../org/elasticsearch/common/logging/JsonLoggerTests.java | 6 +----- .../java/org/elasticsearch/index/IndexingSlowLog.java | 8 +------- .../main/java/org/elasticsearch/index/SearchSlowLog.java | 2 -- 3 files changed, 2 insertions(+), 14 deletions(-) diff --git a/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java b/qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java index 5f11f6d565543..ddf0c755c716c 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 @@ -80,10 +80,7 @@ public void tearDown() throws Exception { } public void testDeprecatedMessage() throws IOException { final Logger testLogger = LogManager.getLogger("deprecation.test"); - testLogger.info(ESLogMessage.of("deprecated message1") - .with("x-opaque-id","someId")); - -// new DeprecatedMessage("deprecated message1", "someId")); + 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"); @@ -198,7 +195,6 @@ public void testCustomMessageWithMultipleFields() throws IOException { .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)) { diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index 90ae1362cb612..f277eaa933bdf 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java @@ -173,15 +173,9 @@ public static ESLogMessage of( //message for json logs is provided by jsonFields String plaintextMessage = message(index, doc, tookInNanos, reformat, maxSourceCharsToLog); - return ESLogMessage.of(plaintextMessage) - .withFields(jsonFields); + return ESLogMessage.of(plaintextMessage).withFields(jsonFields); } -// IndexingSlowLogMessage(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { -// super(prepareMap(index,doc,tookInNanos,reformat,maxSourceCharsToLog), -// message(index,doc,tookInNanos,reformat,maxSourceCharsToLog)); -// } - private static Map prepareMap(Index index, ParsedDocument doc, long tookInNanos, boolean reformat, int maxSourceCharsToLog) { Map map = new HashMap<>(); diff --git a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java index 59716b8d45e25..8b7ed297955e0 100644 --- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java @@ -224,8 +224,6 @@ private static String message(SearchContext context, long tookInNanos) { } return sb.toString(); } - - } private void setQueryWarnThreshold(TimeValue warnThreshold) { From 40cd0ef804e73e78ab88e1c4a2a6bb696faa0589 Mon Sep 17 00:00:00 2001 From: Przemyslaw Gomulka Date: Tue, 8 Oct 2019 12:06:38 +0200 Subject: [PATCH 12/12] logger checker --- .../common/logging/JsonLoggerTests.java | 10 +++--- .../routing/allocation/AllocationService.java | 2 +- .../common/logging/DeprecatedMessage.java | 6 ++-- .../common/logging/ESLogMessage.java | 5 --- .../elasticsearch/index/IndexingSlowLog.java | 2 +- .../elasticsearch/index/SearchSlowLog.java | 2 +- .../loggerusage/ESLoggerUsageChecker.java | 35 +++++++++++++------ .../test/loggerusage/ESLoggerUsageTests.java | 26 +++++++++++--- .../test/loggerusage/TestMessage.java | 33 ----------------- 9 files changed, 58 insertions(+), 63 deletions(-) delete mode 100644 test/logger-usage/src/test/java/org/elasticsearch/test/loggerusage/TestMessage.java 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 ddf0c755c716c..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 @@ -107,7 +107,7 @@ public void testMessageOverrideWithNoValue() throws IOException { //Expected is that it will be emptied final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ESLogMessage.of("some message")); + 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"); @@ -130,9 +130,9 @@ public void testBuildingMessage() throws IOException { final Logger testLogger = LogManager.getLogger("test"); - testLogger.info(ESLogMessage.of("some message {} {}", "value0") + testLogger.info(new ESLogMessage("some message {} {}", "value0") .argAndField("key1","value1") - .argAndField("key2","value2")); + .field("key2","value2")); final Path path = PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".json"); @@ -158,7 +158,7 @@ public void testBuildingMessage() throws IOException { public void testMessageOverride() throws IOException { final Logger testLogger = LogManager.getLogger("custom.test"); - testLogger.info(ESLogMessage.of("some message") + testLogger.info(new ESLogMessage("some message") .with("message","overriden")); @@ -191,7 +191,7 @@ public void testMessageOverride() throws IOException { 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(ESLogMessage.of("some message") + testLogger.info(new ESLogMessage("some message") .with("field1","value1") .with("field2","value2")); 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 6a804556d2377..6dc24d1fb8b17 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 @@ -379,7 +379,7 @@ private void logClusterHealthStateChange(ClusterStateHealth previousStateHealth, ClusterHealthStatus previousHealth = previousStateHealth.getStatus(); ClusterHealthStatus currentHealth = newStateHealth.getStatus(); if (!previousHealth.equals(currentHealth)) { - logger.info(ESLogMessage.of("Cluster health status changed from [{}] to [{}] (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/DeprecatedMessage.java b/server/src/main/java/org/elasticsearch/common/logging/DeprecatedMessage.java index a4082e26043bb..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,6 +20,7 @@ package org.elasticsearch.common.logging; import org.elasticsearch.common.Strings; +import org.elasticsearch.common.SuppressLoggerChecks; /** * A logger message used by {@link DeprecationLogger}. @@ -28,12 +29,13 @@ public class DeprecatedMessage { private static final String X_OPAQUE_ID_FIELD_NAME = "x-opaque-id"; + @SuppressLoggerChecks(reason = "safely delegates to logger") public static ESLogMessage of(String xOpaqueId, String messagePattern, Object... args){ if (Strings.isNullOrEmpty(xOpaqueId)) { - return ESLogMessage.of(messagePattern,args); + return new ESLogMessage(messagePattern, args); } - return ESLogMessage.of(messagePattern,args) + return new ESLogMessage(messagePattern, args) .with(X_OPAQUE_ID_FIELD_NAME, xOpaqueId); } } 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 e4315e8d5b614..532a9a5ddee93 100644 --- a/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java +++ b/server/src/main/java/org/elasticsearch/common/logging/ESLogMessage.java @@ -48,10 +48,6 @@ public ESLogMessage(String messagePattern, Object... arguments) { Collections.addAll(this.arguments, arguments); } - public static ESLogMessage of(String messagePattern, Object... arguments){ - return new ESLogMessage(messagePattern, arguments); - } - public ESLogMessage argAndField(String key, Object value) { this.arguments.add(value); super.with(key,value); @@ -88,7 +84,6 @@ protected void asJson(StringBuilder sb) { sb.append(Chars.DQUOTE).append(':').append(Chars.DQUOTE); start = sb.length(); sb.append(getIndexedReadOnlyStringMap().getValueAt(i).toString()); -// ParameterFormatter.recursiveDeepToString(getIndexedReadOnlyStringMap().getValueAt(i), sb, null); StringBuilders.escapeJson(sb, start); sb.append(Chars.DQUOTE); } diff --git a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java index f277eaa933bdf..dc69718927bde 100644 --- a/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java @@ -173,7 +173,7 @@ public static ESLogMessage of( //message for json logs is provided by jsonFields String plaintextMessage = message(index, doc, tookInNanos, reformat, maxSourceCharsToLog); - return ESLogMessage.of(plaintextMessage).withFields(jsonFields); + 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 8b7ed297955e0..1e16fb7749306 100644 --- a/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java +++ b/server/src/main/java/org/elasticsearch/index/SearchSlowLog.java @@ -158,7 +158,7 @@ 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 ESLogMessage.of(plaintextMessage) + return new ESLogMessage(plaintextMessage) .withFields(jsonFields); } 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); - } -}