Skip to content

Commit

Permalink
Serialize stack traces in error.stack_trace (#28)
Browse files Browse the repository at this point in the history
  • Loading branch information
@felixbarny
felixbarny authored Sep 18, 2019
1 parent 7e441fb commit 43f3803
Show file tree
Hide file tree
Showing 14 changed files with 368 additions and 78 deletions.
48 changes: 45 additions & 3 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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?
Expand All @@ -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)
Expand Down Expand Up @@ -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())|
Expand Down Expand Up @@ -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"));
}
```
163 changes: 150 additions & 13 deletions ecs-logging-core/src/main/java/co/elastic/logging/EcsJsonSerializer.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -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');
}
Expand All @@ -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("\", ");
}

Expand Down Expand Up @@ -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() {

}
}
}
14 changes: 8 additions & 6 deletions ecs-logging-core/src/test/java/co/elastic/logging/AbstractEcsLoggingTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
Loading

0 comments on commit 43f3803

Please sign in to comment.