Make logs more human-readable (#5)

- Format timestamp as ISO-8601 string
- first three properties are `@timestamp`, `log.level` and `message`
- Add padding for `log.level`, so that `message`s align

README.md

@@ -15,9 +15,9 @@ This library helps to log ECS-compatible JSON into a file
 
 Example:
 ```
-{"@timestamp":1565093352375,"service.name":"spring-petclinic","process.thread.name":"restartedMain","log.level":"INFO","event.dataset":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","message":"Tomcat started on port(s): 8080 (http) with context path ''"}
-{"@timestamp":1565093352379,"service.name":"spring-petclinic","process.thread.name":"restartedMain","log.level":"INFO","event.dataset":"org.springframework.samples.petclinic.PetClinicApplication","message":"Started PetClinicApplication in 7.095 seconds (JVM running for 9.082)"}
-{"@timestamp":1565100520199,"service.name":"spring-petclinic","process.thread.name":"http-nio-8080-exec-8","log.level":"INFO","event.dataset":"org.springframework.samples.petclinic.owner.OwnerController","transaction.id":"28b7fb8d5aba51f1","trace.id":"2869b25b5469590610fea49ac04af7da","message":"init find form"}
+{"@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","event.dataset":"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","event.dataset":"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","event.dataset":"org.springframework.samples.petclinic.owner.OwnerController","transaction.id":"28b7fb8d5aba51f1","trace.id":"2869b25b5469590610fea49ac04af7da"}
 ```
 
 ## Why ECS logging?

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

@@ -12,14 +12,17 @@
 public class EcsJsonSerializer {
 
     public static final List<String> DEFAULT_TOP_LEVEL_LABELS = Arrays.asList("trace.id", "transaction.id", "span.id");
+    private static final TimestampSerializer TIMESTAMP_SERIALIZER = new TimestampSerializer();
 
     public static CharSequence toNullSafeString(final CharSequence s) {
         return s == null ? "" : s;
     }
 
     public static void serializeObjectStart(StringBuilder builder, long timeMillis) {
         builder.append('{');
-        builder.append("\"@timestamp\":").append(timeMillis).append(",");
+        builder.append("\"@timestamp\":\"");
+        TIMESTAMP_SERIALIZER.serializeEpochTimestampAsIsoDateTime(builder, timeMillis);
+        builder.append("\", ");
     }
 
     public static void serializeObjectEnd(StringBuilder builder) {
@@ -50,7 +53,7 @@ public static void serializeFormattedMessage(StringBuilder builder, String messa
             builder.append("\\n");
             JsonUtils.quoteAsString(formatThrowable(t), builder);
         }
-        builder.append("\",");
+        builder.append("\", ");
     }
 
     public static void serializeServiceName(StringBuilder builder, String serviceName) {
@@ -59,8 +62,17 @@ public static void serializeServiceName(StringBuilder builder, String serviceNam
         }
     }
 
-    public static void serializeLogLevel(StringBuilder builder, Object level) {
-        builder.append("\"log.level\":\"").append(level).append("\",");
+    public static void serializeLogLevel(StringBuilder builder, String level) {
+        builder.append("\"log.level\":");
+        // add padding so that all levels line up
+        //  WARN
+        // ERROR
+        for (int i = 5 - level.length(); i > 0; i--) {
+            builder.append(' ');
+        }
+        builder.append('\"');
+        builder.append(level);
+        builder.append("\", ");
     }
 
     public static void serializeTag(StringBuilder builder, String tag) {

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

@@ -0,0 +1,113 @@
+package co.elastic.logging;
+
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.TimeZone;
+
+/**
+ * This class serializes an epoch timestamp in milliseconds to a ISO 8601 date time sting,
+ * for example {@code 1970-01-01T00:00:00.000Z}
+ * <p>
+ * The main advantage of this class is that is able to serialize the timestamp in a garbage free way,
+ * i.e. without object allocations and that it is faster than {@link java.text.DateFormat#format(Date)}.
+ * </p>
+ * <p>
+ * The most complex part when formatting a ISO date is to determine the actual year,
+ * month and date as you have to account for leap years.
+ * Leveraging the fact that for a whole day this stays the same
+ * and that logging only requires to serialize the current timestamp and not arbitrary ones,
+ * we offload this task to {@link java.text.DateFormat#format(Date)} and cache the result.
+ * So we only have to serialize the time part of the ISO timestamp which is easy
+ * as a day has exactly {@code 1000 * 60 * 60 * 24} milliseconds.
+ * Also, we don't have to worry about leap seconds when dealing with the epoch timestamp.
+ * </p>
+ * <p>
+ * This class is thread safe.
+ * </p>
+ */
+class TimestampSerializer {
+
+    private static final long MILLIS_PER_SECOND = 1000;
+    private static final long MILLIS_PER_MINUTE = MILLIS_PER_SECOND * 60;
+    private static final long MILLIS_PER_HOUR = MILLIS_PER_MINUTE * 60;
+    private static final long MILLIS_PER_DAY = MILLIS_PER_HOUR * 24;
+    private static final char TIME_SEPARATOR = 'T';
+    private static final char TIME_ZONE_SEPARATOR = 'Z';
+    private static final char COLON = ':';
+    private static final char DOT = '.';
+    private static final char ZERO = '0';
+
+    private volatile CachedDate cachedDate = new CachedDate(System.currentTimeMillis());
+
+    void serializeEpochTimestampAsIsoDateTime(StringBuilder builder, long epochTimestamp) {
+        CachedDate cachedDateLocal = cachedDate;
+        if (cachedDateLocal == null || !cachedDateLocal.isDateCached(epochTimestamp)) {
+            cachedDate = cachedDateLocal = new CachedDate(epochTimestamp);
+        }
+        builder.append(cachedDateLocal.getCachedDateIso());
+
+        builder.append(TIME_SEPARATOR);
+
+        // hours
+        long remainder = epochTimestamp % MILLIS_PER_DAY;
+        serializeWithLeadingZero(builder, remainder / MILLIS_PER_HOUR, 2);
+        builder.append(COLON);
+
+        // minutes
+        remainder %= MILLIS_PER_HOUR;
+        serializeWithLeadingZero(builder, remainder / MILLIS_PER_MINUTE, 2);
+        builder.append(COLON);
+
+        // seconds
+        remainder %= MILLIS_PER_MINUTE;
+        serializeWithLeadingZero(builder, remainder / MILLIS_PER_SECOND, 2);
+        builder.append(DOT);
+
+        // milliseconds
+        remainder %= MILLIS_PER_SECOND;
+        serializeWithLeadingZero(builder, remainder, 3);
+
+        builder.append(TIME_ZONE_SEPARATOR);
+    }
+
+    private void serializeWithLeadingZero(StringBuilder builder, long value, int minLength) {
+        for (int i = minLength - 1; i > 0; i--) {
+            if (value < Math.pow(10, i)) {
+                builder.append(ZERO);
+            }
+        }
+        builder.append(value);
+    }
+
+    private static class CachedDate {
+        private final String cachedDateIso;
+        private final long startOfCachedDate;
+        private final long endOfCachedDate;
+
+        private CachedDate(long epochTimestamp) {
+            SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd");
+            dateFormat.setTimeZone(TimeZone.getTimeZone("UTC"));
+            cachedDateIso = dateFormat.format(new Date(epochTimestamp));
+            startOfCachedDate = atStartOfDay(epochTimestamp);
+            endOfCachedDate = atEndOfDay(epochTimestamp);
+        }
+
+        private static long atStartOfDay(long epochTimestamp) {
+            return epochTimestamp - epochTimestamp % MILLIS_PER_DAY;
+        }
+
+        private static long atEndOfDay(long epochTimestamp) {
+            return atStartOfDay(epochTimestamp) + MILLIS_PER_DAY - 1;
+        }
+
+        private boolean isDateCached(long epochTimestamp) {
+            return epochTimestamp >= startOfCachedDate && epochTimestamp <= endOfCachedDate;
+        }
+
+        public String getCachedDateIso() {
+            return cachedDateIso;
+        }
+    }
+
+}
+

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

@@ -3,14 +3,19 @@
 
 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 static org.assertj.core.api.Assertions.assertThat;
+import static org.assertj.core.api.Assertions.within;
 
 public abstract class AbstractEcsLoggingTest {
 
@@ -21,7 +26,7 @@ void testMetadata() throws Exception {
         debug("test");
         assertThat(getLastLogLine().get("process.thread.name").textValue()).isEqualTo(Thread.currentThread().getName());
         assertThat(getLastLogLine().get("service.name").textValue()).isEqualTo("test");
-        assertThat(getLastLogLine().get("@timestamp").longValue()).isGreaterThan(0);
+        assertThat(Instant.parse(getLastLogLine().get("@timestamp").textValue())).isCloseTo(Instant.now(), within(1, ChronoUnit.MINUTES));
         assertThat(getLastLogLine().get("log.level").textValue()).isEqualTo("DEBUG");
     }
 

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

@@ -0,0 +1,59 @@
+package co.elastic.logging;
+
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+
+import java.time.Instant;
+import java.time.LocalDateTime;
+import java.time.ZoneId;
+import java.time.ZoneOffset;
+import java.time.format.DateTimeFormatter;
+import java.time.temporal.ChronoUnit;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+class TimestampSerializerTest {
+
+    private TimestampSerializer dateSerializer;
+    private DateTimeFormatter dateTimeFormatter = DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSS'Z'").withZone(ZoneId.of("UTC"));
+
+
+    @BeforeEach
+    void setUp() {
+        dateSerializer = new TimestampSerializer();
+    }
+
+    @Test
+    void testSerializeEpochTimestampAsIsoDateTime() {
+        long timestamp = 0;
+        long lastTimestampToCheck = LocalDateTime.now()
+                .plus(1, ChronoUnit.YEARS)
+                .toInstant(ZoneOffset.UTC)
+                .toEpochMilli();
+        // interval is approximately a hour but not exactly
+        // to get different values for the minutes, seconds and milliseconds
+        long interval = 997 * 61 * 61;
+        for (; timestamp <= lastTimestampToCheck; timestamp += interval) {
+            assertDateFormattingIsCorrect(Instant.ofEpochMilli(timestamp));
+        }
+        StringBuilder builder = new StringBuilder();
+        dateSerializer.serializeEpochTimestampAsIsoDateTime(builder, 1565093352375L);
+        System.out.println(builder);
+        builder.setLength(0);
+        dateSerializer.serializeEpochTimestampAsIsoDateTime(builder, 1565093352379L);
+        System.out.println(builder);
+        builder.setLength(0);
+        dateSerializer.serializeEpochTimestampAsIsoDateTime(builder, 1565100520199L);
+        System.out.println(builder);
+    }
+
+
+
+    private void assertDateFormattingIsCorrect(Instant instant) {
+        StringBuilder builder = new StringBuilder();
+        dateSerializer.serializeEpochTimestampAsIsoDateTime(builder, instant.toEpochMilli());
+        assertThat(builder.toString()).isEqualTo(dateTimeFormatter.format(instant));
+    }
+
+
+}

log4j-ecs-layout/src/main/java/co/elastic/logging/log4j/EcsLayout.java

@@ -16,14 +16,14 @@ public class EcsLayout extends Layout {
     public String format(LoggingEvent event) {
         StringBuilder builder = new StringBuilder();
         EcsJsonSerializer.serializeObjectStart(builder, event.getTimeStamp());
+        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel().toString());
+        Throwable thrown = event.getThrowableInformation() != null ? event.getThrowableInformation().getThrowable() : null;
+        EcsJsonSerializer.serializeFormattedMessage(builder, event.getRenderedMessage(), thrown);
         EcsJsonSerializer.serializeServiceName(builder, serviceName);
         EcsJsonSerializer.serializeThreadName(builder, event.getThreadName());
-        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel());
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         EcsJsonSerializer.serializeLabels(builder, event.getProperties(), topLevelLabels);
         EcsJsonSerializer.serializeTag(builder, event.getNDC());
-        Throwable thrown = event.getThrowableInformation() != null ? event.getThrowableInformation().getThrowable() : null;
-        EcsJsonSerializer.serializeFormattedMessage(builder, event.getRenderedMessage(), thrown);
         EcsJsonSerializer.serializeObjectEnd(builder);
         return builder.toString();
     }

log4j2-ecs-layout/src/main/java/co/elastic/logging/log4j2/EcsLayout.java

@@ -105,13 +105,13 @@ public void encode(LogEvent event, ByteBufferDestination destination) {
 
     private StringBuilder toText(LogEvent event, StringBuilder builder, boolean gcFree) {
         EcsJsonSerializer.serializeObjectStart(builder, event.getTimeMillis());
+        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel().toString());
+        serializeMessage(builder, gcFree, event.getMessage(), event.getThrown());
         EcsJsonSerializer.serializeServiceName(builder, serviceName);
         EcsJsonSerializer.serializeThreadName(builder, event.getThreadName());
-        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel());
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         serializeLabels(event, builder);
         serializeTags(event, builder);
-        serializeMessage(builder, gcFree, event.getMessage(), event.getThrown());
         EcsJsonSerializer.serializeObjectEnd(builder);
         return builder;
     }
@@ -172,8 +172,7 @@ private void serializeMessage(StringBuilder builder, boolean gcFree, Message mes
             builder.append("\\n");
             JsonUtils.quoteAsString(formatThrowable(thrown), builder);
         }
-        builder.append('\"');
-        builder.append(',');
+        builder.append("\", ");
 
     }
 

logback-ecs-encoder/src/main/java/co/elastic/logging/logback/EcsEncoder.java

@@ -32,22 +32,22 @@ public void start() {
     public byte[] encode(ILoggingEvent event) {
         StringBuilder builder = new StringBuilder();
         EcsJsonSerializer.serializeObjectStart(builder, event.getTimeStamp());
+        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel().toString());
+        EcsJsonSerializer.serializeFormattedMessage(builder, event.getFormattedMessage(), null);
+        serializeException(event, builder);
         EcsJsonSerializer.serializeServiceName(builder, serviceName);
         EcsJsonSerializer.serializeThreadName(builder, event.getThreadName());
-        EcsJsonSerializer.serializeLogLevel(builder, event.getLevel());
         EcsJsonSerializer.serializeLoggerName(builder, event.getLoggerName());
         EcsJsonSerializer.serializeLabels(builder, event.getMDCPropertyMap(), topLevelLabels);
-        EcsJsonSerializer.serializeFormattedMessage(builder, event.getFormattedMessage(), null);
-        serializeException(event, builder);
         EcsJsonSerializer.serializeObjectEnd(builder);
         // all these allocations kinda hurt
         return builder.toString().getBytes(StandardCharsets.UTF_8);
     }
 
     private void serializeException(ILoggingEvent event, StringBuilder builder) {
         if (event.getThrowableProxy() != null) {
-            // remove ",
-            builder.setLength(builder.length() - 2);
+            // remove `", `
+            builder.setLength(builder.length() - 3);
             builder.append("\\n");
             JsonUtils.quoteAsString(throwableProxyConverter.convert(event), builder);
             builder.append("\",");