Serialize stack traces in error.stack_trace (#28)

Author: felixbarny

README.md

@@ -20,6 +20,15 @@ Example:
 {"@timestamp":"2019-08-06T12:09:12.375Z", "log.level": "INFO", "message":"Tomcat started on port(s): 8080 (http) with context path ''", "service.name":"spring-petclinic","process.thread.name":"restartedMain","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer"}
 {"@timestamp":"2019-08-06T12:09:12.379Z", "log.level": "INFO", "message":"Started PetClinicApplication in 7.095 seconds (JVM running for 9.082)", "service.name":"spring-petclinic","process.thread.name":"restartedMain","log.logger":"org.springframework.samples.petclinic.PetClinicApplication"}
 {"@timestamp":"2019-08-06T14:08:40.199Z", "log.level":"DEBUG", "message":"init find form", "service.name":"spring-petclinic","process.thread.name":"http-nio-8080-exec-8","log.logger":"org.springframework.samples.petclinic.owner.OwnerController","transaction.id":"28b7fb8d5aba51f1","trace.id":"2869b25b5469590610fea49ac04af7da"}
+{"@timestamp":"2019-09-17T13:16:48.038Z", "log.level":"ERROR", "message":"Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: Expected: controller used to showcase what happens when an exception is thrown] with root cause", "process.thread.name":"http-nio-8080-exec-1","log.logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[dispatcherServlet]","log.origin":{"file":"DirectJDKLog.java","function":"log","line":175},"error.code":"java.lang.RuntimeException","error.message":"Expected: controller used to showcase what happens when an exception is thrown","error.stack_trace":[
+	"java.lang.RuntimeException: Expected: controller used to showcase what happens when an exception is thrown",
+	"\tat org.springframework.samples.petclinic.system.CrashController.triggerException(CrashController.java:33)",
+	"\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)",
+	"\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)",
+	"\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)",
+	"\tat java.lang.reflect.Method.invoke(Method.java:498)",
+	"\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)",
+	"\tat java.lang.Thread.run(Thread.java:748)"]}
 ```
 
 ## Why ECS logging?
@@ -32,6 +41,7 @@ Example:
   The log4j2 `EcsLayout` does not allocate any memory (unless the log event contains an `Exception`)
 * Decently human-readable JSON structure \
   The first three fields are always `@timestamp`, `log.level` and `message`.
+  It's also possible to format stack traces so that each element is rendered in a new line.
 * Use the Kibana [Logs UI](https://www.elastic.co/guide/en/kibana/7.3/xpack-logs.html) without additional configuration \
   As this library adheres to [ECS](https://www.elastic.co/guide/en/ecs/current/ecs-reference.html), the Logs UI knows which fields to show
 * Out-of-the-box correlation of logs and traces via the Logs UI and APM UI when using the [Elastic APM Java agent](https://www.elastic.co/guide/en/apm/agent/java/current/index.html)
@@ -69,10 +79,12 @@ We recommend using this library to log into a JSON log file and let Filebeat sen
 |ECS field | Log4j2 API  |
 |----------|-------------|
 |[`@timestamp`](https://www.elastic.co/guide/en/ecs/current/ecs-base.html) | [`LogEvent#getTimeMillis()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getTimeMillis()) |
-| [`log.level`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html) | [`LogEvent#getLevel()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getLevel()) |
-|[`log.logger`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html)|[`LogEvent#getLoggerName(`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getLoggerName())|
+|[`log.level`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html) | [`LogEvent#getLevel()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getLevel()) |
+|[`log.logger`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html)|[`LogEvent#getLoggerName()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getLoggerName())|
 |[`message`](https://www.elastic.co/guide/en/ecs/current/ecs-base.html)|[`LogEvent#getMessage()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getMessage())|
-|[`message`](https://www.elastic.co/guide/en/ecs/current/ecs-base.html)|[`LogEvent#getThrown()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getThrown())|
+|[`error.code`](https://www.elastic.co/guide/en/ecs/current/ecs-error.html)|[`Throwable#getClass()`](https://docs.oracle.com/javase/7/docs/api/java/lang/Object.html#getClass())|
+|[`error.message`](https://www.elastic.co/guide/en/ecs/current/ecs-error.html)|[`Throwable#getStackTrace()`](https://docs.oracle.com/javase/7/docs/api/java/lang/Throwable.html#getMessage())|
+|[`error.stack_trace`](https://www.elastic.co/guide/en/ecs/current/ecs-error.html)|[`Throwable#getStackTrace()`](https://docs.oracle.com/javase/7/docs/api/java/lang/Throwable.html#getStackTrace())|
 |[`process.thread.name`](https://www.elastic.co/guide/en/ecs/current/ecs-process.html)|[`LogEvent#getThreadName()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getThreadName()) |
 |[`labels`](https://www.elastic.co/guide/en/ecs/current/ecs-base.html)|[`LogEvent#getContextMap()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getContextMap())|
 |[`tags`](https://www.elastic.co/guide/en/ecs/current/ecs-base.html)|[`LogEvent#getContextStack()`](https://logging.apache.org/log4j/log4j-2.3/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getContextStack())|
@@ -123,3 +135,33 @@ For more information, check the [Filebeat documentation](https://www.elastic.co/
   - Set `Output type` to `Elasticsearch`
   - Configure the `hosts`
   - For secured Elasticsearch deployments (like Elastic cloud) set `Username` and `Password`
+
+#### When `stackTraceAsArray` is enabled
+
+Filebeat can normally only decoding JSON if there is one JSON object per line.
+When `stackTraceAsArray` is enabled, there will be a new line for each stack trace element which improves readability.
+But when combining the multiline settings with a `decode_json_fields` we can also handle multi-line JSON.
+
+```yaml
+filebeat.inputs:
+  - type: log
+    paths: /path/to/logs.json
+    multiline.pattern: '^{'
+    multiline.negate: true
+    multiline.match: after
+processors:
+  - decode_json_fields:
+      fields: message
+      target: ""
+      overwrite_keys: true
+  # flattens the array to a single string
+  - script:
+      when:
+        has_fields: ['error.stack_trace']
+      lang: javascript
+      id: my_filter
+      source: >
+        function process(event) {
+            event.Put("error.stack_trace", event.Get("error.stack_trace").join("\n"));
+        }
+```

ecs-logging-core/src/main/java/co/elastic/logging/EcsJsonSerializer.java

@@ -25,7 +25,7 @@
 package co.elastic.logging;
 
 import java.io.PrintWriter;
-import java.io.StringWriter;
+import java.io.Writer;
 import java.util.Arrays;
 import java.util.List;
 import java.util.Map;
@@ -35,6 +35,8 @@ public class EcsJsonSerializer {
 
     public static final List<String> DEFAULT_TOP_LEVEL_LABELS = Arrays.asList("trace.id", "transaction.id", "span.id", "error.id", "service.name");
     private static final TimestampSerializer TIMESTAMP_SERIALIZER = new TimestampSerializer();
+    private static final ThreadLocal<StringBuilder> messageStringBuilder = new ThreadLocal<StringBuilder>();
+    private static final  String NEW_LINE = System.getProperty("line.separator");
 
     public static CharSequence toNullSafeString(final CharSequence s) {
         return s == null ? "" : s;
@@ -48,8 +50,7 @@ public static void serializeObjectStart(StringBuilder builder, long timeMillis)
     }
 
     public static void serializeObjectEnd(StringBuilder builder) {
-        // last char is always a comma (,)
-        builder.setLength(builder.length() - 1);
+        removeIfEndsWith(builder, ",");
         builder.append('}');
         builder.append('\n');
     }
@@ -68,13 +69,9 @@ public static void serializeThreadName(StringBuilder builder, String threadName)
         }
     }
 
-    public static void serializeFormattedMessage(StringBuilder builder, String message, Throwable t) {
+    public static void serializeFormattedMessage(StringBuilder builder, String message) {
         builder.append("\"message\":\"");
         JsonUtils.quoteAsString(message, builder);
-        if (t != null) {
-            builder.append("\\n");
-            JsonUtils.quoteAsString(formatThrowable(t), builder);
-        }
         builder.append("\", ");
     }
 
@@ -138,22 +135,162 @@ public static void serializeLabels(StringBuilder builder, Map<String, ?> labels,
         }
     }
 
-    public static void serializeException(StringBuilder builder, Throwable thrown) {
+    public static void serializeException(StringBuilder builder, Throwable thrown, boolean stackTraceAsArray) {
         if (thrown != null) {
             builder.append("\"error.code\":\"");
             JsonUtils.quoteAsString(thrown.getClass().getName(), builder);
             builder.append("\",");
             builder.append("\"error.message\":\"");
-            JsonUtils.quoteAsString(formatThrowable(thrown), builder);
+            JsonUtils.quoteAsString(thrown.getMessage(), builder);
             builder.append("\",");
+            if (stackTraceAsArray) {
+                builder.append("\"error.stack_trace\":[").append(NEW_LINE);
+                formatThrowableAsArray(builder, thrown);
+                builder.append("]");
+            } else {
+                builder.append("\"error.stack_trace\":\"");
+                JsonUtils.quoteAsString(formatThrowable(thrown), builder);
+                builder.append("\"");
+            }
         }
     }
 
+    public static void serializeException(StringBuilder builder, String exceptionClassName, String exceptionMessage, String stackTrace, boolean stackTraceAsArray) {
+        builder.append("\"error.code\":\"");
+        JsonUtils.quoteAsString(exceptionClassName, builder);
+        builder.append("\",");
+        builder.append("\"error.message\":\"");
+        JsonUtils.quoteAsString(exceptionMessage, builder);
+        builder.append("\",");
+        if (stackTraceAsArray) {
+            builder.append("\"error.stack_trace\":[").append(NEW_LINE);
+            for (String line : stackTrace.split("\\n")) {
+                appendQuoted(builder, line);
+            }
+            builder.append("]");
+        } else {
+            builder.append("\"error.stack_trace\":\"");
+            JsonUtils.quoteAsString(stackTrace, builder);
+            builder.append("\"");
+        }
+    }
+
+    private static void appendQuoted(StringBuilder builder, CharSequence content) {
+        builder.append('"');
+        JsonUtils.quoteAsString(content, builder);
+        builder.append('"');
+    }
+
     private static CharSequence formatThrowable(final Throwable throwable) {
-        StringWriter sw = new StringWriter(2048);
-        final PrintWriter pw = new PrintWriter(sw);
+        StringBuilder buffer = getMessageStringBuilder();
+        final PrintWriter pw = new PrintWriter(new StringBuilderWriter(buffer));
         throwable.printStackTrace(pw);
         pw.flush();
-        return sw.toString();
+        return buffer;
+    }
+
+    private static void formatThrowableAsArray(final StringBuilder jsonBuilder, final Throwable throwable) {
+        final StringBuilder buffer = getMessageStringBuilder();
+        final PrintWriter pw = new PrintWriter(new StringBuilderWriter(buffer), true) {
+            @Override
+            public void println() {
+                flush();
+                jsonBuilder.append("\t\"");
+                JsonUtils.quoteAsString(buffer, jsonBuilder);
+                jsonBuilder.append("\",");
+                jsonBuilder.append(NEW_LINE);
+                buffer.setLength(0);
+            }
+        };
+        throwable.printStackTrace(pw);
+        removeIfEndsWith(jsonBuilder, NEW_LINE);
+        removeIfEndsWith(jsonBuilder, ",");
+    }
+
+    public static void removeIfEndsWith(StringBuilder sb, String ending) {
+        if (endsWith(sb, ending)) {
+            sb.setLength(sb.length() - ending.length());
+        }
+    }
+
+    public static boolean endsWith(StringBuilder sb, String ending) {
+        int endingLength = ending.length();
+        int startIndex = sb.length() - endingLength;
+        if (startIndex < 0) {
+            return false;
+        }
+        for (int i = 0; i < endingLength; i++) {
+            if (sb.charAt(startIndex + i) != ending.charAt(i)) {
+                return false;
+            }
+        }
+        return true;
+    }
+
+    public static StringBuilder getMessageStringBuilder() {
+        StringBuilder result = messageStringBuilder.get();
+        if (result == null) {
+            result = new StringBuilder(1024);
+            messageStringBuilder.set(result);
+        }
+        result.setLength(0);
+        return result;
+    }
+
+    private static class StringBuilderWriter extends Writer {
+
+        private final StringBuilder buffer;
+
+        StringBuilderWriter(StringBuilder buffer) {
+            this.buffer = buffer;
+        }
+
+        @Override
+        public Writer append(CharSequence csq) {
+            buffer.append(csq);
+            return this;
+        }
+
+        @Override
+        public void write(String str) {
+            buffer.append(str);
+        }
+
+        @Override
+        public void write(String str, int off, int len) {
+            buffer.append(str, off, len);
+        }
+
+        @Override
+        public Writer append(CharSequence csq, int start, int end) {
+            buffer.append(csq, start, end);
+            return this;
+        }
+
+        @Override
+        public Writer append(char c) {
+            buffer.append(c);
+            return this;
+        }
+
+        @Override
+        public void write(int c) {
+            buffer.append((char) c);
+        }
+
+        @Override
+        public void write(char[] cbuf, int off, int len) {
+            buffer.append(cbuf, off, len);
+        }
+
+        @Override
+        public void flush() {
+
+        }
+
+        @Override
+        public void close() {
+
+        }
     }
 }

ecs-logging-core/src/test/java/co/elastic/logging/AbstractEcsLoggingTest.java

@@ -27,16 +27,13 @@
 
 import com.fasterxml.jackson.databind.JsonNode;
 import com.fasterxml.jackson.databind.ObjectMapper;
-import org.assertj.core.data.TemporalOffset;
-import org.junit.jupiter.api.Disabled;
 import org.junit.jupiter.api.Test;
 
 import java.io.IOException;
-import java.io.PrintWriter;
-import java.io.StringWriter;
-import java.time.Duration;
 import java.time.Instant;
 import java.time.temporal.ChronoUnit;
+import java.util.stream.Collectors;
+import java.util.stream.StreamSupport;
 
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.within;
@@ -88,7 +85,12 @@ void testTopLevelLabels() throws Exception {
     void testLogException() throws Exception {
         error("test", new RuntimeException("test"));
         assertThat(getLastLogLine().get("log.level").textValue()).isEqualTo("ERROR");
-        assertThat(getLastLogLine().get("message").textValue()).contains("at co.elastic.logging.AbstractEcsLoggingTest.testLogException");
+        assertThat(getLastLogLine().get("error.message").textValue()).isEqualTo("test");
+        assertThat(getLastLogLine().get("error.code").textValue()).isEqualTo(RuntimeException.class.getName());
+        String stackTrace = StreamSupport.stream(getLastLogLine().get("error.stack_trace").spliterator(), false)
+                .map(JsonNode::textValue)
+                .collect(Collectors.joining("\n", "", "\n"));
+        assertThat(stackTrace).contains("at co.elastic.logging.AbstractEcsLoggingTest.testLogException");
     }
 
     public abstract void putMdc(String key, String value);