Make Elasticsearch JSON logs ECS compliant

buildSrc/version.properties

@@ -16,6 +16,7 @@ supercsv          = 2.4.0
 # when updating log4j, please update also docs/java-api/index.asciidoc
 log4j             = 2.11.1
 slf4j             = 1.6.2
+ecsLogging        = 0.1.3
 
 # when updating the JNA version, also update the version in buildSrc/build.gradle
 jna               = 4.5.1

distribution/docker/src/docker/config/log4j2.properties

@@ -6,15 +6,15 @@ logger.action.level = debug
 
 appender.rolling.type = Console
 appender.rolling.name = rolling
-appender.rolling.layout.type = ESJsonLayout
+appender.rolling.layout.type = ECSJsonLayout
 appender.rolling.layout.type_name = server
 
 rootLogger.level = info
 rootLogger.appenderRef.rolling.ref = rolling
 
 appender.deprecation_rolling.type = Console
 appender.deprecation_rolling.name = deprecation_rolling
-appender.deprecation_rolling.layout.type = ESJsonLayout
+appender.deprecation_rolling.layout.type = ECSJsonLayout
 appender.deprecation_rolling.layout.type_name = deprecation
 
 logger.deprecation.name = org.elasticsearch.deprecation
@@ -24,9 +24,8 @@ logger.deprecation.additivity = false
 
 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 = ECSJsonLayout
 appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
-appender.index_search_slowlog_rolling.layout.overrideFields=message
 
 logger.index_search_slowlog_rolling.name = index.search.slowlog
 logger.index_search_slowlog_rolling.level = trace
@@ -35,9 +34,8 @@ logger.index_search_slowlog_rolling.additivity = false
 
 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 = ECSJsonLayout
 appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
-appender.index_indexing_slowlog_rolling.layout.overrideFields=message
 
 logger.index_indexing_slowlog.name = index.indexing.slowlog.index
 logger.index_indexing_slowlog.level = trace

distribution/docker/src/docker/config/oss/log4j2.properties

@@ -6,15 +6,15 @@ logger.action.level = debug
 
 appender.rolling.type = Console
 appender.rolling.name = rolling
-appender.rolling.layout.type = ESJsonLayout
+appender.rolling.layout.type = ECSJsonLayout
 appender.rolling.layout.type_name = server
 
 rootLogger.level = info
 rootLogger.appenderRef.rolling.ref = rolling
 
 appender.deprecation_rolling.type = Console
 appender.deprecation_rolling.name = deprecation_rolling
-appender.deprecation_rolling.layout.type = ESJsonLayout
+appender.deprecation_rolling.layout.type = ECSJsonLayout
 appender.deprecation_rolling.layout.type_name = deprecation
 
 logger.deprecation.name = org.elasticsearch.deprecation
@@ -24,7 +24,7 @@ logger.deprecation.additivity = false
 
 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 = ECSJsonLayout
 appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
 
 logger.index_search_slowlog_rolling.name = index.search.slowlog
@@ -34,7 +34,7 @@ logger.index_search_slowlog_rolling.additivity = false
 
 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 = ECSJsonLayout
 appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
 
 logger.index_indexing_slowlog.name = index.indexing.slowlog.index

distribution/src/config/log4j2.properties

@@ -9,7 +9,7 @@ appender.console.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%ma
 appender.rolling.type = RollingFile
 appender.rolling.name = rolling
 appender.rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_server.json
-appender.rolling.layout.type = ESJsonLayout
+appender.rolling.layout.type = ECSJsonLayout
 appender.rolling.layout.type_name = server
 
 appender.rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}-%d{yyyy-MM-dd}-%i.json.gz
@@ -61,7 +61,7 @@ rootLogger.appenderRef.rolling_old.ref = rolling_old
 appender.deprecation_rolling.type = RollingFile
 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 = ECSJsonLayout
 appender.deprecation_rolling.layout.type_name = deprecation
 
 appender.deprecation_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation-%i.json.gz
@@ -71,35 +71,19 @@ appender.deprecation_rolling.policies.size.size = 1GB
 appender.deprecation_rolling.strategy.type = DefaultRolloverStrategy
 appender.deprecation_rolling.strategy.max = 4
 #################################################
-######## Deprecation -  old style pattern #######
-appender.deprecation_rolling_old.type = RollingFile
-appender.deprecation_rolling_old.name = deprecation_rolling_old
-appender.deprecation_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_deprecation.log
-appender.deprecation_rolling_old.layout.type = PatternLayout
-appender.deprecation_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n
-
-appender.deprecation_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
-  _deprecation-%i.log.gz
-appender.deprecation_rolling_old.policies.type = Policies
-appender.deprecation_rolling_old.policies.size.type = SizeBasedTriggeringPolicy
-appender.deprecation_rolling_old.policies.size.size = 1GB
-appender.deprecation_rolling_old.strategy.type = DefaultRolloverStrategy
-appender.deprecation_rolling_old.strategy.max = 4
-#################################################
+
 logger.deprecation.name = org.elasticsearch.deprecation
 logger.deprecation.level = warn
 logger.deprecation.appenderRef.deprecation_rolling.ref = deprecation_rolling
-logger.deprecation.appenderRef.deprecation_rolling_old.ref = deprecation_rolling_old
 logger.deprecation.additivity = false
 
 ######## Search slowlog JSON ####################
 appender.index_search_slowlog_rolling.type = RollingFile
 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 = ECSJsonLayout
 appender.index_search_slowlog_rolling.layout.type_name = index_search_slowlog
-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
@@ -109,36 +93,21 @@ appender.index_search_slowlog_rolling.policies.size.size = 1GB
 appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
 appender.index_search_slowlog_rolling.strategy.max = 4
 #################################################
-######## Search slowlog -  old style pattern ####
-appender.index_search_slowlog_rolling_old.type = RollingFile
-appender.index_search_slowlog_rolling_old.name = index_search_slowlog_rolling_old
-appender.index_search_slowlog_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
-  _index_search_slowlog.log
-appender.index_search_slowlog_rolling_old.layout.type = PatternLayout
-appender.index_search_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n
-
-appender.index_search_slowlog_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
-  _index_search_slowlog-%i.log.gz
-appender.index_search_slowlog_rolling_old.policies.type = Policies
-appender.index_search_slowlog_rolling_old.policies.size.type = SizeBasedTriggeringPolicy
-appender.index_search_slowlog_rolling_old.policies.size.size = 1GB
-appender.index_search_slowlog_rolling_old.strategy.type = DefaultRolloverStrategy
-appender.index_search_slowlog_rolling_old.strategy.max = 4
+
 #################################################
 logger.index_search_slowlog_rolling.name = index.search.slowlog
 logger.index_search_slowlog_rolling.level = trace
 logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
-logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling_old.ref = index_search_slowlog_rolling_old
 logger.index_search_slowlog_rolling.additivity = false
 
 ######## Indexing slowlog JSON ##################
 appender.index_indexing_slowlog_rolling.type = RollingFile
 appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
 appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
   _index_indexing_slowlog.json
-appender.index_indexing_slowlog_rolling.layout.type = ESJsonLayout
+appender.index_indexing_slowlog_rolling.layout.type = ECSJsonLayout
 appender.index_indexing_slowlog_rolling.layout.type_name = index_indexing_slowlog
-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
@@ -148,25 +117,9 @@ appender.index_indexing_slowlog_rolling.policies.size.size = 1GB
 appender.index_indexing_slowlog_rolling.strategy.type = DefaultRolloverStrategy
 appender.index_indexing_slowlog_rolling.strategy.max = 4
 #################################################
-######## Indexing slowlog -  old style pattern ##
-appender.index_indexing_slowlog_rolling_old.type = RollingFile
-appender.index_indexing_slowlog_rolling_old.name = index_indexing_slowlog_rolling_old
-appender.index_indexing_slowlog_rolling_old.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
-  _index_indexing_slowlog.log
-appender.index_indexing_slowlog_rolling_old.layout.type = PatternLayout
-appender.index_indexing_slowlog_rolling_old.layout.pattern = [%d{ISO8601}][%-5p][%-25c{1.}] [%node_name]%marker %m%n
-
-appender.index_indexing_slowlog_rolling_old.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}\
-  _index_indexing_slowlog-%i.log.gz
-appender.index_indexing_slowlog_rolling_old.policies.type = Policies
-appender.index_indexing_slowlog_rolling_old.policies.size.type = SizeBasedTriggeringPolicy
-appender.index_indexing_slowlog_rolling_old.policies.size.size = 1GB
-appender.index_indexing_slowlog_rolling_old.strategy.type = DefaultRolloverStrategy
-appender.index_indexing_slowlog_rolling_old.strategy.max = 4
-#################################################
+
 
 logger.index_indexing_slowlog.name = index.indexing.slowlog.index
 logger.index_indexing_slowlog.level = trace
 logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling
-logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling_old.ref = index_indexing_slowlog_rolling_old
 logger.index_indexing_slowlog.additivity = false

qa/die-with-dignity/src/main/java/org/elasticsearch/DieWithDignityPlugin.java

@@ -42,13 +42,14 @@ public DieWithDignityPlugin() {
 
     @Override
     public List<RestHandler> getRestHandlers(
-            final Settings settings,
-            final RestController restController,
-            final ClusterSettings clusterSettings,
-            final IndexScopedSettings indexScopedSettings,
-            final SettingsFilter settingsFilter,
-            final IndexNameExpressionResolver indexNameExpressionResolver,
-            final Supplier<DiscoveryNodes> nodesInCluster) {
+        final Settings settings,
+        final RestController restController,
+        final ClusterSettings clusterSettings,
+        final IndexScopedSettings indexScopedSettings,
+        final SettingsFilter settingsFilter,
+        final IndexNameExpressionResolver indexNameExpressionResolver,
+        final Supplier<DiscoveryNodes> nodesInCluster
+    ) {
         return Collections.singletonList(new RestDieWithDignityAction());
     }
 

qa/die-with-dignity/src/test/java/org/elasticsearch/qa/die_with_dignity/DieWithDignityIT.java

@@ -39,18 +39,14 @@
 public class DieWithDignityIT extends ESRestTestCase {
 
     public void testDieWithDignity() throws Exception {
-        expectThrows(
-            IOException.class,
-            () -> client().performRequest(new Request("GET", "/_die_with_dignity"))
-        );
+        expectThrows(IOException.class, () -> client().performRequest(new Request("GET", "/_die_with_dignity")));
 
         // the Elasticsearch process should die and disappear from the output of jps
         assertBusy(() -> {
             final String jpsPath = PathUtils.get(System.getProperty("runtime.java.home"), "bin/jps").toString();
             final Process process = new ProcessBuilder().command(jpsPath, "-v").start();
 
-            try (InputStream is = process.getInputStream();
-                 BufferedReader in = new BufferedReader(new InputStreamReader(is, "UTF-8"))) {
+            try (InputStream is = process.getInputStream(); BufferedReader in = new BufferedReader(new InputStreamReader(is, "UTF-8"))) {
                 String line;
                 while ((line = in.readLine()) != null) {
                     assertThat(line, line, not(containsString("-Ddie.with.dignity.test")));
@@ -60,21 +56,24 @@ public void testDieWithDignity() throws Exception {
 
         // parse the logs and ensure that Elasticsearch died with the expected cause
         final List<String> lines = Files.readAllLines(PathUtils.get(System.getProperty("log")));
-
         final Iterator<String> it = lines.iterator();
 
         boolean fatalError = false;
         boolean fatalErrorInThreadExiting = false;
         try {
             while (it.hasNext() && (fatalError == false || fatalErrorInThreadExiting == false)) {
                 final String line = it.next();
-                if (line.matches(".*ERROR.*o\\.e\\.ExceptionsHelper.*integTest-0.*fatal error.*")) {
+                if (containsAll(line, ".*ERROR.*", ".*ExceptionsHelper.*", ".*integTest-0.*", ".*fatal error.*")) {
                     fatalError = true;
-                } else if (line.matches(".*ERROR.*o\\.e\\.b\\.ElasticsearchUncaughtExceptionHandler.*integTest-0.*"
-                    + "fatal error in thread \\[Thread-\\d+\\], exiting.*")) {
+                } else if (containsAll(
+                    line,
+                    ".*ERROR.*",
+                    ".*ElasticsearchUncaughtExceptionHandler.*",
+                    ".*integTest-0.*",
+                    ".*fatal error in thread \\[Thread-\\d+\\], exiting.*",
+                    ".*java.lang.OutOfMemoryError: die with dignity.*"
+                )) {
                     fatalErrorInThreadExiting = true;
-                    assertTrue(it.hasNext());
-                    assertThat(it.next(), containsString("java.lang.OutOfMemoryError: die with dignity"));
                 }
             }
 
@@ -88,6 +87,15 @@ public void testDieWithDignity() throws Exception {
         }
     }
 
+    private boolean containsAll(String line, String... subStrings) {
+        for (String subString : subStrings) {
+            if (line.matches(subString) == false) {
+                return false;
+            }
+        }
+        return true;
+    }
+
     private void debugLogs(Path path) throws IOException {
         try (BufferedReader reader = Files.newBufferedReader(path)) {
             reader.lines().forEach(line -> logger.info(line));
@@ -102,7 +110,8 @@ protected boolean preserveClusterUponCompletion() {
 
     @Override
     protected final Settings restClientSettings() {
-        return Settings.builder().put(super.restClientSettings())
+        return Settings.builder()
+            .put(super.restClientSettings())
             // increase the timeout here to 90 seconds to handle long waits for a green
             // cluster health. the waits for green need to be longer than a minute to
             // account for delayed shards

qa/evil-tests/src/test/java/org/elasticsearch/common/logging/EvilLoggerTests.java

@@ -195,8 +195,14 @@ public void testConcurrentDeprecationLogger() throws IOException, UserException,
                         "_deprecation.log";
         final List<String> deprecationEvents = Files.readAllLines(PathUtils.get(deprecationPath));
         // we appended an integer to each log message, use that for sorting
-        deprecationEvents.sort(Comparator.comparingInt(s -> Integer.parseInt(s.split("message")[1])));
+        Pattern pattern = Pattern.compile(".*message(\\d+)\"");
+        deprecationEvents.sort(Comparator.comparingInt(s -> {
+            Matcher matcher = pattern.matcher(s);
+            matcher.matches();
+            return Integer.parseInt(matcher.group(1));
+        }));
         assertThat(deprecationEvents.size(), equalTo(128));
+
         for (int i = 0; i < 128; i++) {
             assertLogLine(
                     deprecationEvents.get(i),

qa/logging-config/build.gradle

@@ -32,7 +32,10 @@ testClusters.integTest {
 
 integTest.runner {
   nonInputProperties.systemProperty 'tests.logfile',
-    "${-> testClusters.integTest.singleNode().getServerLog().absolutePath.replaceAll(".json", ".log")}"
+    "${-> testClusters.integTest.singleNode().getServerLog().absolutePath.replaceAll("_server.json", ".log")}"
+
+  nonInputProperties.systemProperty 'tests.jsonLogfile',
+    "${-> testClusters.integTest.singleNode().getServerLog()}"
 }
 
 test {