Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Serialize stack traces in error.stack_trace #28

Merged
merged 3 commits into from
Sep 18, 2019
Merged

Serialize stack traces in error.stack_trace #28

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
3bce698
Serialize stack traces in error.stack_trace
felixbarny Sep 16, 2019
d72f247
Add filebeat config example when stackTraceAsArray is enabled
felixbarny Sep 17, 2019
910bea9
Update docs
felixbarny Sep 17, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 45 additions & 3 deletions README.md
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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