Merge pull request #78 from SAP/written_ts-nano

Add support for nanoseconds in written_ts

Author: KarstenSchnitter

cf-java-logging-support-log4j2/src/main/java/com/sap/hcp/cf/log4j2/converter/TimestampConverter.java

@@ -1,12 +1,20 @@
 package com.sap.hcp.cf.log4j2.converter;
 
+import java.time.Instant;
+
 import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.config.plugins.Plugin;
 import org.apache.logging.log4j.core.pattern.ConverterKeys;
 import org.apache.logging.log4j.core.pattern.LogEventPatternConverter;
 
 @Plugin(name = "TimestampConverter", category = "Converter")
 @ConverterKeys({ "tstamp" })
+/**
+ * This is a simple {@link LogEventPatternConverter} implementation that prints
+ * the timestamp as a long in nano second resolution. Note: nano second
+ * precision is only available from Java 9 or newer. Java 8 will only have milli
+ * seconds.
+ */
 public class TimestampConverter extends LogEventPatternConverter {
 
     public static final String WORD = "tstamp";
@@ -21,7 +29,9 @@ public static TimestampConverter newInstance(final String[] options) {
 
     @Override
     public void format(LogEvent event, StringBuilder toAppendTo) {
-        toAppendTo.append(System.currentTimeMillis() * 1000000);
+		Instant now = Instant.now();
+		long timestamp = now.getEpochSecond() * 1_000_000_000L + now.getNano();
+		toAppendTo.append(timestamp);
     }
 
 }

cf-java-logging-support-log4j2/src/test/java/com/sap/hcp/cf/logging/common/TestAppLog.java

@@ -1,12 +1,14 @@
 package com.sap.hcp.cf.logging.common;
 
 import static com.sap.hcp.cf.logging.common.converter.CustomFieldMatchers.hasCustomField;
+import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.contains;
 import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.lessThanOrEqualTo;
 import static org.hamcrest.core.Is.is;
 import static org.hamcrest.core.IsNull.notNullValue;
-import static org.junit.Assert.assertThat;
+
+import java.time.Instant;
 
 import org.junit.Test;
 import org.slf4j.Logger;
@@ -63,9 +65,9 @@ public void testMDC() {
         MDC.put(SOME_KEY, SOME_VALUE);
         MDC.put("testNumeric", "200");
         logMsg = "Running testMDC()";
-        long beforeTS = System.currentTimeMillis() * 1000000;
+		long beforeTS = now();
         LOGGER.info(logMsg);
-        long afterTS = System.currentTimeMillis() * 1000000;
+		long afterTS = now();
         assertThat(getMessage(), is(logMsg));
         assertThat(getField(Fields.COMPONENT_ID), is("-"));
         assertThat(getField(Fields.COMPONENT_NAME), is("-"));
@@ -78,7 +80,7 @@ public void testMDC() {
 	@Test
 	public void testUnregisteredCustomField() {
 		logMsg = "Running testUnregisteredCustomField()";
-		long beforeTS = System.currentTimeMillis() * 1000000;
+		long beforeTS = now();
 		LOGGER.info(logMsg, CustomField.customField(SOME_KEY, SOME_VALUE));
 		assertThat(getMessage(), is(logMsg));
 		assertThat(getField(SOME_KEY), is(SOME_VALUE));
@@ -96,7 +98,7 @@ public void testCustomFieldOverwritesMdc() throws Exception {
 		MDC.put(RETAINED_FIELD_KEY, SOME_VALUE);
 		MDC.put(SOME_KEY, SOME_VALUE);
 		logMsg = "Running testCustomFieldOverwritesMdc()";
-		long beforeTS = System.currentTimeMillis() * 1000000;
+		long beforeTS = now();
 		LOGGER.info(logMsg, CustomField.customField(CUSTOM_FIELD_KEY, SOME_OTHER_VALUE),
 				CustomField.customField(RETAINED_FIELD_KEY, SOME_OTHER_VALUE),
 				CustomField.customField(SOME_KEY, SOME_OTHER_VALUE));
@@ -137,4 +139,9 @@ public void testJSONMsg() {
         LOGGER.info(jsonMsg);
         assertThat(getMessage(), is(jsonMsg));
     }
+
+	private static long now() {
+		Instant now = Instant.now();
+		return now.getEpochSecond() * 1_000_000_000L + now.getNano();
+	}
 }

cf-java-logging-support-logback/src/main/java/com/sap/hcp/cf/logback/converter/TimestampConverter.java

@@ -1,11 +1,14 @@
 package com.sap.hcp.cf.logback.converter;
 
+import java.time.Instant;
+
 import ch.qos.logback.classic.pattern.ClassicConverter;
 import ch.qos.logback.classic.spi.ILoggingEvent;
 
 /**
- * This is a simple {@link ClassicConverter} implementation that print the
- * timestamp as a long in nano second resolution.
+ * This is a simple {@link ClassicConverter} implementation that prints the
+ * timestamp as a long in nano second resolution. Note: nano second precision is
+ * only available from Java 9 or newer. Java 8 will only have milli seconds.
  */
 public class TimestampConverter extends ClassicConverter {
 
@@ -14,7 +17,9 @@ public class TimestampConverter extends ClassicConverter {
     @Override
     public String convert(ILoggingEvent event) {
         StringBuilder appendTo = new StringBuilder();
-        appendTo.append(System.currentTimeMillis() * 1000000);
+		Instant now = Instant.now();
+		long timestamp = now.getEpochSecond() * 1_000_000_000L + now.getNano();
+		appendTo.append(timestamp);
         return appendTo.toString();
     }
 

cf-java-logging-support-logback/src/test/java/com/sap/hcp/cf/logging/common/TestAppLog.java

@@ -1,12 +1,14 @@
 package com.sap.hcp.cf.logging.common;
 
 import static com.sap.hcp.cf.logging.common.converter.CustomFieldMatchers.hasCustomField;
+import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.contains;
 import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.lessThanOrEqualTo;
 import static org.hamcrest.core.Is.is;
 import static org.hamcrest.core.IsNull.notNullValue;
-import static org.junit.Assert.assertThat;
+
+import java.time.Instant;
 
 import org.junit.Test;
 import org.slf4j.Logger;
@@ -64,7 +66,7 @@ public void testMDC() {
         MDC.put(SOME_KEY, SOME_VALUE);
         MDC.put("testNumeric", "200");
         logMsg = "Running testMDC()";
-        long beforeTS = System.currentTimeMillis() * 1000000;
+        long beforeTS = now();
         LOGGER.info(logMsg);
         assertThat(getMessage(), is(logMsg));
         assertThat(getField(Fields.COMPONENT_ID), is("-"));
@@ -80,7 +82,7 @@ public void testMDC() {
     @Test
 	public void testUnregisteredCustomField() {
 		logMsg = "Running testUnregisteredCustomField()";
-		long beforeTS = System.currentTimeMillis() * 1000000;
+		long beforeTS = now();
 		LOGGER.info(logMsg, CustomField.customField(SOME_KEY, SOME_VALUE));
 		assertThat(getMessage(), is(logMsg));
 		assertThat(getField(SOME_KEY), is(SOME_VALUE));
@@ -98,7 +100,7 @@ public void testCustomFieldOverwritesMdc() throws Exception {
 		MDC.put(RETAINED_FIELD_KEY, SOME_VALUE);
 		MDC.put(SOME_KEY, SOME_VALUE);
 		logMsg = "Running testCustomFieldOverwritesMdc()";
-		long beforeTS = System.currentTimeMillis() * 1000000;
+		long beforeTS = now();
 		LOGGER.info(logMsg, CustomField.customField(CUSTOM_FIELD_KEY, SOME_OTHER_VALUE),
 				CustomField.customField(RETAINED_FIELD_KEY, SOME_OTHER_VALUE),
 				CustomField.customField(SOME_KEY, SOME_OTHER_VALUE));
@@ -139,4 +141,9 @@ public void testJSONMsg() {
         LOGGER.info(jsonMsg);
         assertThat(getMessage(), is(jsonMsg));
     }
+    
+	private static long now() {
+		Instant now = Instant.now();
+		return now.getEpochSecond() * 1_000_000_000L + now.getNano();
+	}
 }

pom.xml

@@ -177,7 +177,7 @@
         <junit.version>4.13.1</junit.version>
         <mockito.version>1.9.5</mockito.version>
         <surefire.plugin.version>2.18.1</surefire.plugin.version>
-        <animal.sniffer.version>1.18</animal.sniffer.version>
+        <animal.sniffer.version>1.19</animal.sniffer.version>
         <exec.plugin.version>1.4.0</exec.plugin.version>
         <javadoc.plugin.version>3.1.1</javadoc.plugin.version>
         <gpg.plugin.version>1.6</gpg.plugin.version>
@@ -268,7 +268,7 @@
                 <configuration>
                     <signature>
                         <groupId>org.codehaus.mojo.signature</groupId>
-                        <artifactId>java16</artifactId>
+                        <artifactId>java18</artifactId>
                         <version>1.0</version>
                     </signature>
                 </configuration>