Add includeOrigin flag

depends on elastic/ecs#563 closes elastic#3
felixbarny · Sep 18, 2019 · 3230f31 · 3230f31
1 parent 33ae6d4
commit 3230f31
Show file tree

Hide file tree

Showing 14 changed files with 106 additions and 22 deletions.
diff --git a/README.md b/README.md
@@ -20,7 +20,7 @@ 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":[
+{"@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.name":"DirectJDKLog.java","function":"log","file.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)",
@@ -81,6 +81,9 @@ We recommend using this library to log into a JSON log file and let Filebeat sen
 |[`@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.origin.file.name`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html)|[StackTraceElement#getFileName()](https://docs.oracle.com/javase/6/docs/api/java/lang/StackTraceElement.html#getFileName())|
+|[`log.origin.file.line`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html)|[`[StackTraceElement#getLineNumber()]()`](https://docs.oracle.com/javase/6/docs/api/java/lang/StackTraceElement.html#getLineNumber())|
+|[`log.origin.function`](https://www.elastic.co/guide/en/ecs/current/ecs-log.html)|[`[StackTraceElement#getMethodName()]()`](https://docs.oracle.com/javase/6/docs/api/java/lang/StackTraceElement.html#getMethodName())|
 |[`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())|
 |[`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())|

diff --git a/ecs-logging-core/src/main/java/co/elastic/logging/EcsJsonSerializer.java b/ecs-logging-core/src/main/java/co/elastic/logging/EcsJsonSerializer.java
@@ -119,6 +119,25 @@ public static void serializeTagEnd(StringBuilder builder) {
         builder.append("],");
     }
 
+    public static void serializeOrigin(StringBuilder builder, StackTraceElement stackTraceElement) {
+        if (stackTraceElement != null) {
+            serializeOrigin(builder, stackTraceElement.getFileName(), stackTraceElement.getMethodName(), stackTraceElement.getLineNumber());
+        }
+    }
+
+    public static void serializeOrigin(StringBuilder builder, String fileName, String methodName, int lineNumber) {
+        builder.append("\"log.origin\":{");
+        builder.append("\"file.name\":\"");
+        JsonUtils.quoteAsString(fileName, builder);
+        builder.append("\",");
+        builder.append("\"function\":\"");
+        JsonUtils.quoteAsString(methodName, builder);
+        builder.append("\",");
+        builder.append("\"file.line\":");
+        builder.append(lineNumber);
+        builder.append("},");
+    }
+
     public static void serializeLabels(StringBuilder builder, Map<String, ?> labels, Set<String> topLevelLabels) {
         if (!labels.isEmpty()) {
             for (Map.Entry<String, ?> entry : labels.entrySet()) {

diff --git a/ecs-logging-core/src/test/java/co/elastic/logging/AbstractEcsLoggingTest.java b/ecs-logging-core/src/test/java/co/elastic/logging/AbstractEcsLoggingTest.java
@@ -93,6 +93,14 @@ void testLogException() throws Exception {
         assertThat(stackTrace).contains("at co.elastic.logging.AbstractEcsLoggingTest.testLogException");
     }
 
+    @Test
+    void testLogOrigin() throws Exception {
+        debug("test");
+        assertThat(getLastLogLine().get("log.origin").get("file.name").textValue()).endsWith(".java");
+        assertThat(getLastLogLine().get("log.origin").get("function").textValue()).isEqualTo("debug");
+        assertThat(getLastLogLine().get("log.origin").get("file.line").intValue()).isPositive();
+    }
+
     public abstract void putMdc(String key, String value);
 
     public boolean putNdc(String message) {

diff --git a/log4j-ecs-layout/src/main/java/co/elastic/logging/log4j/EcsLayout.java b/log4j-ecs-layout/src/main/java/co/elastic/logging/log4j/EcsLayout.java
@@ -26,6 +26,7 @@
 
 import co.elastic.logging.EcsJsonSerializer;
 import org.apache.log4j.Layout;
+import org.apache.log4j.spi.LocationInfo;
 import org.apache.log4j.spi.LoggingEvent;
 import org.apache.log4j.spi.ThrowableInformation;
 
@@ -37,6 +38,7 @@ public class EcsLayout extends Layout {
     private boolean stackTraceAsArray = false;
     private String serviceName;
     private Set<String> topLevelLabels = new HashSet<String>(EcsJsonSerializer.DEFAULT_TOP_LEVEL_LABELS);
+    private boolean includeOrigin;
 
     @Override
     public String format(LoggingEvent event) {
@@ -49,6 +51,12 @@ public String format(LoggingEvent event) {
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         EcsJsonSerializer.serializeLabels(builder, event.getProperties(), topLevelLabels);
         EcsJsonSerializer.serializeTag(builder, event.getNDC());
+        if (includeOrigin) {
+            LocationInfo locationInformation = event.getLocationInformation();
+            if (locationInformation != null) {
+                EcsJsonSerializer.serializeOrigin(builder, locationInformation.getFileName(), locationInformation.getMethodName(), getLineNumber(locationInformation));
+            }
+        }
         ThrowableInformation throwableInformation = event.getThrowableInformation();
         if (throwableInformation != null) {
             EcsJsonSerializer.serializeException(builder, throwableInformation.getThrowable(), stackTraceAsArray);
@@ -57,6 +65,19 @@ public String format(LoggingEvent event) {
         return builder.toString();
     }
 
+    private static int getLineNumber(LocationInfo locationInformation) {
+        int lineNumber = -1;
+        String lineNumberString = locationInformation.getLineNumber();
+        if (!LocationInfo.NA.equals(lineNumberString)) {
+            try {
+                lineNumber = Integer.parseInt(lineNumberString);
+            } catch (NumberFormatException e) {
+                // ignore
+            }
+        }
+        return lineNumber;
+    }
+
     @Override
     public boolean ignoresThrowable() {
         return false;
@@ -71,6 +92,10 @@ public void setServiceName(String serviceName) {
         this.serviceName = serviceName;
     }
 
+    public void setIncludeOrigin(boolean includeOrigin) {
+        this.includeOrigin = includeOrigin;
+    }
+
     public void setStackTraceAsArray(boolean stackTraceAsArray) {
         this.stackTraceAsArray = stackTraceAsArray;
     }

diff --git a/log4j-ecs-layout/src/test/java/co/elastic/logging/log4j/ListAppender.java b/log4j-ecs-layout/src/test/java/co/elastic/logging/log4j/ListAppender.java
@@ -31,11 +31,11 @@
 import java.util.List;
 
 class ListAppender extends AppenderSkeleton {
-    private List<LoggingEvent> logEvents = new ArrayList<>();
+    private List<String> logEvents = new ArrayList<>();
 
     @Override
     protected void append(LoggingEvent event) {
-        logEvents.add(event);
+        logEvents.add(layout.format(event));
     }
 
     @Override
@@ -45,10 +45,10 @@ public void close() {
 
     @Override
     public boolean requiresLayout() {
-        return false;
+        return true;
     }
 
-    public List<LoggingEvent> getLogEvents() {
+    public List<String> getLogEvents() {
         return logEvents;
     }
 }
diff --git a/log4j-ecs-layout/src/test/java/co/elastic/logging/log4j/Log4jEcsLayoutTest.java b/log4j-ecs-layout/src/test/java/co/elastic/logging/log4j/Log4jEcsLayoutTest.java
@@ -31,14 +31,11 @@
 import org.apache.log4j.MDC;
 import org.apache.log4j.NDC;
 import org.junit.jupiter.api.AfterEach;
-import org.junit.jupiter.api.Assertions;
 import org.junit.jupiter.api.Assumptions;
 import org.junit.jupiter.api.BeforeEach;
 
 import java.io.IOException;
 
-import static org.assertj.core.api.Assertions.assertThat;
-
 class Log4jEcsLayoutTest extends AbstractEcsLoggingTest {
 
     private Logger logger;
@@ -54,6 +51,8 @@ void setUp() {
         ecsLayout = new EcsLayout();
         ecsLayout.setServiceName("test");
         ecsLayout.setStackTraceAsArray(true);
+        ecsLayout.setIncludeOrigin(true);
+        appender.setLayout(ecsLayout);
     }
 
     @BeforeEach
@@ -87,7 +86,7 @@ public void error(String message, Throwable t) {
 
     @Override
     public JsonNode getLastLogLine() throws IOException {
-        return objectMapper.readTree(ecsLayout.format(appender.getLogEvents().get(0)));
+        return objectMapper.readTree(appender.getLogEvents().get(0));
     }
 
 }
diff --git a/log4j2-ecs-layout/README.md b/log4j2-ecs-layout/README.md
@@ -47,6 +47,7 @@ Instead of the usual `<PatternLayout/>`, use `<EcsLayout serviceName="my-app"/>`
 |serviceName      |String |       |Sets the `service.name` field so you can filter your logs by a particular service |
 |includeMarkers   |boolean|`false`|Log [Markers](https://logging.apache.org/log4j/2.0/manual/markers.html) as `tags` |
 |stackTraceAsArray|boolean|`false`|Serializes the `error.stack_trace` as a JSON array where each element is in a new line to improve readability. Note that this requires a slightly more complex [Filebeat configuration](../README.md#when-stacktraceasarray-is-enabled).|
+|includeOrigin    |boolean|`false`|If `true`, adds the `log.origin.file`, `log.origin.function` and `log.origin.line` fields. Note that you also have to set `includeLocation="true"` on your loggers and appenders if you are using the async ones. |
 
 To include any custom field in the output, use following syntax:
 

diff --git a/log4j2-ecs-layout/src/main/java/co/elastic/logging/log4j2/EcsLayout.java b/log4j2-ecs-layout/src/main/java/co/elastic/logging/log4j2/EcsLayout.java
@@ -83,15 +83,17 @@ public void accept(final String key, final Object value, final StringBuilder str
     private final PatternFormatter[][] fieldValuePatternFormatter;
     private final Set<String> topLevelLabels;
     private final boolean stackTraceAsArray;
-    private String serviceName;
-    private boolean includeMarkers;
+    private final String serviceName;
+    private final boolean includeMarkers;
+    private final boolean includeOrigin;
     private final ConcurrentMap<Class<? extends MultiformatMessage>, Boolean> supportsJson = new ConcurrentHashMap<Class<? extends MultiformatMessage>, Boolean>();
 
-    private EcsLayout(Configuration config, String serviceName, boolean includeMarkers, KeyValuePair[] additionalFields, Collection<String> topLevelLabels, boolean stackTraceAsArray) {
+    private EcsLayout(Configuration config, String serviceName, boolean includeMarkers, KeyValuePair[] additionalFields, Collection<String> topLevelLabels, boolean includeOrigin, boolean stackTraceAsArray) {
         super(config, UTF_8, null, null);
         this.serviceName = serviceName;
         this.includeMarkers = includeMarkers;
         this.topLevelLabels = new HashSet<String>(topLevelLabels);
+        this.includeOrigin = includeOrigin;
         this.stackTraceAsArray = stackTraceAsArray;
         this.topLevelLabels.add("trace.id");
         this.topLevelLabels.add("transaction.id");
@@ -138,6 +140,9 @@ private StringBuilder toText(LogEvent event, StringBuilder builder, boolean gcFr
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         serializeLabels(event, builder);
         serializeTags(event, builder);
+        if (includeOrigin) {
+            EcsJsonSerializer.serializeOrigin(builder, event.getSource());
+        }
         EcsJsonSerializer.serializeException(builder, event.getThrown(), stackTraceAsArray);
         EcsJsonSerializer.serializeObjectEnd(builder);
         return builder;
@@ -310,6 +315,8 @@ public static class Builder extends AbstractStringLayout.Builder<EcsLayout.Build
         private KeyValuePair[] additionalFields;
         @PluginElement("TopLevelLabels")
         private String[] topLevelLabels;
+        @PluginBuilderAttribute("includeOrigin")
+        private boolean includeOrigin;
 
         Builder() {
             super();
@@ -328,6 +335,10 @@ public boolean isIncludeMarkers() {
             return includeMarkers;
         }
 
+        public boolean isIncludeOrigin() {
+            return includeOrigin;
+        }
+
         public String[] getTopLevelLabels() {
             return topLevelLabels;
         }
@@ -357,14 +368,19 @@ public EcsLayout.Builder setIncludeMarkers(final boolean includeMarkers) {
             return asBuilder();
         }
 
+        public EcsLayout.Builder setIncludeOrigin(final boolean includeOrigin) {
+            this.includeOrigin = includeOrigin;
+            return asBuilder();
+        }
+
         public EcsLayout.Builder setStackTraceAsArray(boolean stackTraceAsArray) {
             this.stackTraceAsArray = stackTraceAsArray;
             return asBuilder();
         }
 
         @Override
         public EcsLayout build() {
-            return new EcsLayout(getConfiguration(), serviceName, includeMarkers, additionalFields, topLevelLabels == null ? Collections.<String>emptyList() : Arrays.<String>asList(topLevelLabels), stackTraceAsArray);
+            return new EcsLayout(getConfiguration(), serviceName, includeMarkers, additionalFields, topLevelLabels == null ? Collections.<String>emptyList() : Arrays.<String>asList(topLevelLabels), includeOrigin, stackTraceAsArray);
         }
 
         public boolean isStackTraceAsArray() {

diff --git a/log4j2-ecs-layout/src/test/java/co/elastic/logging/log4j2/Log4j2EcsLayoutTest.java b/log4j2-ecs-layout/src/test/java/co/elastic/logging/log4j2/Log4j2EcsLayoutTest.java
@@ -68,6 +68,7 @@ void setUp() {
                 .setConfiguration(ctx.getConfiguration())
                 .setServiceName("test")
                 .setIncludeMarkers(true)
+                .setIncludeOrigin(true)
                 .setStackTraceAsArray(true)
                 .setAdditionalFields(new KeyValuePair[]{
                         new KeyValuePair("cluster.uuid", "9fe9134b-20b0-465e-acf9-8cc09ac9053b"),

diff --git a/log4j2-ecs-layout/src/test/resources/log4j2-test.xml b/log4j2-ecs-layout/src/test/resources/log4j2-test.xml
@@ -5,7 +5,7 @@
     </Properties>
     <Appenders>
         <List name="TestAppender">
-            <EcsLayout serviceName="test" includeMarkers="true" stackTraceAsArray="true">
+            <EcsLayout serviceName="test" includeMarkers="true" includeOrigin="true" stackTraceAsArray="true">
                 <KeyValuePair key="cluster.uuid" value="9fe9134b-20b0-465e-acf9-8cc09ac9053b"/>
                 <KeyValuePair key="node.id" value="${node.id}"/>
                 <KeyValuePair key="empty" value="${empty}"/>

diff --git a/logback-ecs-encoder/README.md b/logback-ecs-encoder/README.md
@@ -65,3 +65,4 @@ All you have to do is to use the `co.elastic.logging.logback.EcsEncoder` instead
 |serviceName      |String |       |Sets the `service.name` field so you can filter your logs by a particular service |
 |includeMarkers   |boolean|`false`|Log [Markers](https://www.slf4j.org/api/org/slf4j/Marker.html) as `tags` |
 |stackTraceAsArray|boolean|`false`|Serializes the `error.stack_trace` as a JSON array where each element is in a new line to improve readability. Note that this requires a slightly more complex [Filebeat configuration](../README.md#when-stacktraceasarray-is-enabled).|
+|includeOrigin    |boolean|`false`|If `true`, adds the `log.origin.file`, `log.origin.function` and `log.origin.line` fields|
diff --git a/logback-ecs-encoder/src/main/java/co/elastic/logging/logback/EcsEncoder.java b/logback-ecs-encoder/src/main/java/co/elastic/logging/logback/EcsEncoder.java
@@ -45,6 +45,7 @@ public class EcsEncoder extends EncoderBase<ILoggingEvent> {
     private boolean includeMarkers = false;
     private ThrowableProxyConverter throwableProxyConverter;
     private Set<String> topLevelLabels = new HashSet<String>(EcsJsonSerializer.DEFAULT_TOP_LEVEL_LABELS);
+    private boolean includeOrigin;
 
     @Override
     public byte[] headerBytes() {
@@ -69,6 +70,12 @@ public byte[] encode(ILoggingEvent event) {
         EcsJsonSerializer.serializeThreadName(builder, event.getThreadName());
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         EcsJsonSerializer.serializeLabels(builder, event.getMDCPropertyMap(), topLevelLabels);
+        if (includeOrigin) {
+            StackTraceElement[] callerData = event.getCallerData();
+            if (callerData != null && callerData.length > 0) {
+                EcsJsonSerializer.serializeOrigin(builder, callerData[0]);
+            }
+        }
         IThrowableProxy throwableProxy = event.getThrowableProxy();
         if (throwableProxy instanceof ThrowableProxy) {
             EcsJsonSerializer.serializeException(builder, ((ThrowableProxy) throwableProxy).getThrowable(), stackTraceAsArray);
@@ -115,4 +122,8 @@ public void setIncludeMarkers(boolean includeMarkers) {
     public void setStackTraceAsArray(boolean stackTraceAsArray) {
         this.stackTraceAsArray = stackTraceAsArray;
     }
+
+    public void setIncludeOrigin(boolean includeOrigin) {
+        this.includeOrigin = includeOrigin;
+    }
 }
diff --git a/logback-ecs-encoder/src/test/java/co/elastic/logging/logback/EcsEncoderTest.java b/logback-ecs-encoder/src/test/java/co/elastic/logging/logback/EcsEncoderTest.java
@@ -25,35 +25,34 @@
 package co.elastic.logging.logback;
 
 import ch.qos.logback.classic.LoggerContext;
-import ch.qos.logback.classic.spi.ILoggingEvent;
-import ch.qos.logback.core.read.ListAppender;
 import com.fasterxml.jackson.databind.JsonNode;
 import org.junit.jupiter.api.BeforeEach;
 
 import java.io.IOException;
 
 class EcsEncoderTest extends AbstractEcsEncoderTest {
 
-    private ListAppender<ILoggingEvent> appender;
-    private EcsEncoder ecsEncoder;
+    private OutputStreamAppender appender;
 
     @BeforeEach
     void setUp() {
         LoggerContext context = new LoggerContext();
         logger = context.getLogger(getClass());
-        appender = new ListAppender<>();
+        appender = new OutputStreamAppender();
         appender.setContext(context);
-        appender.start();
         logger.addAppender(appender);
-        ecsEncoder = new EcsEncoder();
+        EcsEncoder ecsEncoder = new EcsEncoder();
         ecsEncoder.setServiceName("test");
         ecsEncoder.setIncludeMarkers(true);
         ecsEncoder.setStackTraceAsArray(true);
+        ecsEncoder.setIncludeOrigin(true);
         ecsEncoder.start();
+        appender.setEncoder(ecsEncoder);
+        appender.start();
     }
 
     @Override
     public JsonNode getLastLogLine() throws IOException {
-        return objectMapper.readTree(ecsEncoder.encode(appender.list.get(0)));
+        return objectMapper.readTree(appender.getBytes());
     }
 }
diff --git a/logback-ecs-encoder/src/test/resources/logback-config.xml b/logback-ecs-encoder/src/test/resources/logback-config.xml
@@ -4,6 +4,7 @@
         <encoder class="co.elastic.logging.logback.EcsEncoder">
             <serviceName>test</serviceName>
             <includeMarkers>true</includeMarkers>
+            <includeOrigin>true</includeOrigin>
             <stackTraceAsArray>true</stackTraceAsArray>
         </encoder>
     </appender>