Skip to content

Commit

Permalink
Refactor ESLogMessage to not define fields upfront (#46702)
Browse files Browse the repository at this point in the history 
* refactor ESLogMessage and overriding fields

* rename esmessagefields to overrideFields

* javadoc

* simplify custom message class creation

* line length

* small cleanup and rename of ESJsonField

* working with builder

* parametrized map - basing on ecs

* builder

* refactoring and cleanup

* cleanup

* logger checker
  • Loading branch information
@pgomulka
pgomulka authored Oct 10, 2019
1 parent 9e30a57 commit a4a7967
Show file tree
Hide file tree
Showing 19 changed files with 410 additions and 240 deletions.
5 changes: 2 additions & 3 deletions distribution/docker/docker-build-context/src/docker/config/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -27,7 +26,7 @@ appender.index_search_slowlog_rolling.type = Console
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
appender.index_search_slowlog_rolling.layout.type = ESJsonLayout
appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,stats,search_type,total_shards,source,id
appender.index_search_slowlog_rolling.layout.overrideFields=message

logger.index_search_slowlog_rolling.name = index.search.slowlog
logger.index_search_slowlog_rolling.level = trace
Expand All @@ -38,7 +37,7 @@ appender.index_indexing_slowlog_rolling.type = Console
appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout
appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source
appender.index_indexing_slowlog_rolling.layout.overrideFields=message

logger.index_indexing_slowlog.name = index.indexing.slowlog.index
logger.index_indexing_slowlog.level = trace
Expand Down
5 changes: 2 additions & 3 deletions distribution/src/config/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -104,7 +103,7 @@ appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:f
.cluster_name}_index_search_slowlog.json
appender.index_search_slowlog_rolling.layout.type = ESJsonLayout
appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
appender.index_search_slowlog_rolling.layout.esmessagefields=message,took,took_millis,total_hits,stats,search_type,total_shards,source,id
appender.index_search_slowlog_rolling.layout.overrideFields=message

appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\
.cluster_name}_index_search_slowlog-%i.json.gz
Expand Down Expand Up @@ -143,7 +142,7 @@ appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys
_index_indexing_slowlog.json
appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout
appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
appender.index_indexing_slowlog_rolling.layout.esmessagefields=message,took,took_millis,doc_type,id,routing,source
appender.index_indexing_slowlog_rolling.layout.overrideFields=message

appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
_index_indexing_slowlog-%i.json.gz
Expand Down
28 changes: 4 additions & 24 deletions qa/logging-config/src/test/java/org/elasticsearch/common/logging/ESJsonLayoutTests.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,38 +50,18 @@ public void testLayout() {
"\"node.name\": \"%node_name\", " +
"\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" +
"%notEmpty{, %node_and_cluster_id }" +
"%exceptionAsJson }" + System.lineSeparator()));
}

public void testLayoutWithAdditionalFields() {
ESJsonLayout server = ESJsonLayout.newBuilder()
.setType("server")
.setESMessageFields("x-opaque-id,someOtherField")
.build();
String conversionPattern = server.getPatternLayout().getConversionPattern();

assertThat(conversionPattern, Matchers.equalTo(
"{" +
"\"type\": \"server\", " +
"\"timestamp\": \"%d{yyyy-MM-dd'T'HH:mm:ss,SSSZZ}\", " +
"\"level\": \"%p\", " +
"\"component\": \"%c{1.}\", " +
"\"cluster.name\": \"${sys:es.logs.cluster_name}\", " +
"\"node.name\": \"%node_name\", " +
"\"message\": \"%notEmpty{%enc{%marker}{JSON} }%enc{%.-10000m}{JSON}\"" +
"%notEmpty{, \"x-opaque-id\": \"%ESMessageField{x-opaque-id}\"}" +
"%notEmpty{, \"someOtherField\": \"%ESMessageField{someOtherField}\"}" +
"%notEmpty{, %node_and_cluster_id }" +
"%notEmpty{, %CustomMapFields{} }" +
"%exceptionAsJson }" + System.lineSeparator()));
}

public void testLayoutWithAdditionalFieldOverride() {
ESJsonLayout server = ESJsonLayout.newBuilder()
.setType("server")
.setESMessageFields("message")
.setOverrideFields("message")
.build();
String conversionPattern = server.getPatternLayout().getConversionPattern();

//message field is removed as is expected to be provided by a field from a message
assertThat(conversionPattern, Matchers.equalTo(
"{" +
"\"type\": \"server\", " +
Expand All @@ -90,8 +70,8 @@ public void testLayoutWithAdditionalFieldOverride() {
"\"component\": \"%c{1.}\", " +
"\"cluster.name\": \"${sys:es.logs.cluster_name}\", " +
"\"node.name\": \"%node_name\"" +
"%notEmpty{, \"message\": \"%ESMessageField{message}\"}" +
"%notEmpty{, %node_and_cluster_id }" +
"%notEmpty{, %CustomMapFields{message} }" +
"%exceptionAsJson }" + System.lineSeparator()));
}
}
148 changes: 131 additions & 17 deletions qa/logging-config/src/test/java/org/elasticsearch/common/logging/JsonLoggerTests.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@
import org.junit.BeforeClass;

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.List;
import java.util.Map;
Expand Down Expand Up @@ -78,8 +79,8 @@ public void tearDown() throws Exception {
super.tearDown();
}
public void testDeprecatedMessage() throws IOException {
final Logger testLogger = LogManager.getLogger("test");
testLogger.info(new DeprecatedMessage("deprecated message1", "someId"));
final Logger testLogger = LogManager.getLogger("deprecation.test");
testLogger.info(DeprecatedMessage.of("someId","deprecated message1"));

final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_deprecated.json");
Expand All @@ -91,7 +92,7 @@ public void testDeprecatedMessage() throws IOException {
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message1"),
Expand All @@ -101,12 +102,126 @@ public void testDeprecatedMessage() throws IOException {
}
}

public void testMessageOverrideWithNoValue() throws IOException {
//message field is meant to be overriden (see custom.test config), but is not provided.
//Expected is that it will be emptied
final Logger testLogger = LogManager.getLogger("custom.test");

testLogger.info(new ESLogMessage("some message"));

final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_custom.json");
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());

assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "custom"),
hasEntry("level", "INFO"),
hasEntry("component", "c.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"))
)
);
}
}
public void testBuildingMessage() throws IOException {

public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
final Logger testLogger = LogManager.getLogger("test");
testLogger.info(new DeprecatedMessage("deprecated message1", "someId"));
testLogger.info(new DeprecatedMessage("deprecated message2", ""));
testLogger.info(new DeprecatedMessage("deprecated message3", null));

testLogger.info(new ESLogMessage("some message {} {}", "value0")
.argAndField("key1","value1")
.field("key2","value2"));

final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + ".json");
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());

assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "file"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "some message value0 value1"),
hasEntry("key1", "value1"),
hasEntry("key2", "value2"))
)
);
}
}

public void testMessageOverride() throws IOException {

final Logger testLogger = LogManager.getLogger("custom.test");
testLogger.info(new ESLogMessage("some message")
.with("message","overriden"));


final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_custom.json");
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());

assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "custom"),
hasEntry("level", "INFO"),
hasEntry("component", "c.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "overriden"))
)
);
}

final Path plaintextPath = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + "_plaintext.json");
List<String> lines = Files.readAllLines(plaintextPath);
assertThat(lines, contains("some message"));


}

public void testCustomMessageWithMultipleFields() throws IOException {
// if a field is defined to be overriden, it has to always be overriden in that appender.
final Logger testLogger = LogManager.getLogger("test");
testLogger.info(new ESLogMessage("some message")
.with("field1","value1")
.with("field2","value2"));

final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
System.getProperty("es.logs.cluster_name") + ".json");
try (Stream<Map<String, String>> stream = JsonLogsStream.mapStreamFrom(path)) {
List<Map<String, String>> jsonLogs = stream
.collect(Collectors.toList());

assertThat(jsonLogs, contains(
allOf(
hasEntry("type", "file"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("field1", "value1"),
hasEntry("field2", "value2"),
hasEntry("message", "some message"))
)
);
}
}


public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
final Logger testLogger = LogManager.getLogger("deprecation.test");
testLogger.info( DeprecatedMessage.of("someId","deprecated message1"));
testLogger.info( DeprecatedMessage.of("","deprecated message2"));
testLogger.info( DeprecatedMessage.of(null,"deprecated message3"));
testLogger.info("deprecated message4");

final Path path = PathUtils.get(System.getProperty("es.logs.base_path"),
Expand All @@ -119,15 +234,15 @@ 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"),
hasEntry("x-opaque-id", "someId")),
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"),
Expand All @@ -136,7 +251,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message3"),
Expand All @@ -145,7 +260,7 @@ public void testDeprecatedMessageWithoutXOpaqueId() throws IOException {
allOf(
hasEntry("type", "deprecation"),
hasEntry("level", "INFO"),
hasEntry("component", "test"),
hasEntry("component", "d.test"),
hasEntry("cluster.name", "elasticsearch"),
hasEntry("node.name", "sample-name"),
hasEntry("message", "deprecated message4"),
Expand Down Expand Up @@ -179,19 +294,19 @@ public void testJsonLayout() throws IOException {
}

public void testPrefixLoggerInJson() throws IOException {
Logger shardIdLogger = Loggers.getLogger("shardIdLogger", ShardId.fromString("[indexName][123]"));
Logger shardIdLogger = Loggers.getLogger("prefix.shardIdLogger", ShardId.fromString("[indexName][123]"));
shardIdLogger.info("This is an info message with a shardId");

Logger prefixLogger = new PrefixLogger(LogManager.getLogger("prefixLogger"), "PREFIX");
Logger prefixLogger = new PrefixLogger(LogManager.getLogger("prefix.prefixLogger"), "PREFIX");
prefixLogger.info("This is an info message with a prefix");

final Path path = clusterLogsPath();
try (Stream<JsonLogLine> stream = JsonLogsStream.from(path)) {
List<JsonLogLine> 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")
));
}
}
Expand Down Expand Up @@ -351,12 +466,11 @@ public void testDuplicateLogMessages() throws IOException {

private List<JsonLogLine> collectLines(Stream<JsonLogLine> stream) {
return stream
.skip(1)//skip the first line from super class
.collect(Collectors.toList());
}

private Path clusterLogsPath() {
return PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".log");
return PathUtils.get(System.getProperty("es.logs.base_path"), System.getProperty("es.logs.cluster_name") + ".json");
}

private void setupLogging(final String config) throws IOException, UserException {
Expand Down
Loading

0 comments on commit a4a7967

Please sign in to comment.