Change MDC datetime formatter to Zulu time

Change-Id: I0e771e0ec10d1972290c44e8e0740309ac83bc52
Signed-off-by: Luke Parker <lparker@amdocs.com>
Issue-ID: LOG-115

10 files changed, 109 insertions, 59 deletions

diff --git a/reference/logging-slf4j-demo/README.md b/reference/logging-slf4j-demo/README.md
index 4434964..83f9f80 100644
--- a/reference/logging-slf4j-demo/README.md
+++ b/reference/logging-slf4j-demo/README.md
@@ -2,31 +2,6 @@
 
 This project gives an example of ONAP-compliant logging using SLF4J logging.
 
-## Adapter
-
-In ```org.onap.logging.ref.slf4j.common```, there are TWO classes:
-1. ```org.onap.logging.ref.slf4j.common.ONAPLogConstants```, providing declarations of standard ONAP Markers, MDCs and HTTP headers.
-2. ```org.onap.logging.ref.slf4j.common.ONAPLogAdapter```, providing a lightweight, compliant implementation of the ONAP logging spec.
-
-The adapter provides:
-1. A loosely-coupled SLF4j logging wrapper:
- * To be used for logging ONAP ```entry```, ```exit``` and ```invoke``` behavior.
- * Devolving all *application* logging to the component, via the regular SLF4J ```Logger``` facade.
-2. Customization options:
- * *Cheap*, by way of bean properties. This is suited to most Use Cases.
- * *Sophisticated*:
-    * By OPTIONALLY implementing one of a number of adapters:
-      * ```RequestAdapter``` to read incoming headers.
-      * ```ServiceDescriptor``` for reporting attributes of the current service.
-      * ```ResponseDescriptor``` for reporting outcomes.
-      * ```RequestBuilder``` for setting southbound request headers.
-    * By OPTIONALLY overriding methods like ```ONAPLogAdapter#setMDCs(RequestAdapter)```.
-
-Note that:
-* The adapter implementation uses static inner classes in order to fit in a single source file. This was an objective. 
-
-## WAR
-
 Building produces a simple (spring-boot](https://projects.spring.io/spring-boot/) example WAR, which can be launched from this directory with:
 
 ```bash
@@ -45,6 +20,6 @@ The purpose of this WAR is to demonstrate minimalist ONAP-compliant logging for
 
 ## Tests
 
-Tests for:
-1. Code in the (potentially) reusable ``common`` package.
-2. Validating that emitted logs can be used to generate an unambiguous call graph.
+Tests for verifying that emitted logs can be used to generate an unambiguous call graph.
+
+Note that these run in-process, despite the WAR packaging. The intent is to enable tests via HTTP transports.
diff --git a/reference/logging-slf4j-demo/src/main/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplication.java b/reference/logging-slf4j-demo/src/main/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplication.java
index 146f66b..ff2fa2f 100644
--- a/reference/logging-slf4j-demo/src/main/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplication.java
+++ b/reference/logging-slf4j-demo/src/main/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplication.java
@@ -31,7 +31,7 @@ import org.springframework.boot.autoconfigure.SpringBootApplication;
 public class SLF4JRefApplication {
 
     /** System property override, read by embedded Logback configuration. */
-    public static final String SLF4J_OUTPUT_DIRECTORY = "SLF4J_OUTPUT_DIRECTORY";
+    public static final String TESTNG_SLF4J_OUTPUT_DIRECTORY = "TESTNG_SLF4J_OUTPUT_DIRECTORY";
 
     /**
      * Launch from CLI.
@@ -48,7 +48,7 @@ public class SLF4JRefApplication {
      * overridden by tests, but not in services.)
      */
     static void initOutputDirectory() {
-        System.getProperties().setProperty(SLF4J_OUTPUT_DIRECTORY,
-                System.getProperty(SLF4J_OUTPUT_DIRECTORY, "."));
+        System.getProperties().setProperty(TESTNG_SLF4J_OUTPUT_DIRECTORY,
+                System.getProperty(TESTNG_SLF4J_OUTPUT_DIRECTORY, "."));
     }
 }
\ No newline at end of file
diff --git a/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/CallGraphTest.java b/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/CallGraphTest.java
index 3d123e0..cc52cf3 100644
--- a/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/CallGraphTest.java
+++ b/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/CallGraphTest.java
@@ -58,7 +58,7 @@ public class CallGraphTest {
     public static void setUp() throws Exception {
         AbstractComponentTest.setInProcess();
         sDir = Files.createTempDirectory(CallGraphTest.class.getName()).toFile();
-        System.getProperties().setProperty("SLF4J_OUTPUT_DIRECTORY", sDir.getAbsolutePath());
+        System.getProperties().setProperty("TESTNG_SLF4J_OUTPUT_DIRECTORY", sDir.getAbsolutePath());
         LoggerFactory.getLogger(CallGraphTest.class).info("Starting.");
     }
 
diff --git a/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplicationTest.java b/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplicationTest.java
index a01cbe8..43f8746 100644
--- a/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplicationTest.java
+++ b/reference/logging-slf4j-demo/src/test/java/org/onap/logging/ref/slf4j/demo/SLF4JRefApplicationTest.java
@@ -34,14 +34,14 @@ public class SLF4JRefApplicationTest {
 
     @Test
     public void testProperty() {
-        assertThat(SLF4JRefApplication.SLF4J_OUTPUT_DIRECTORY,
-                is("SLF4J_OUTPUT_DIRECTORY"));
+        assertThat(SLF4JRefApplication.TESTNG_SLF4J_OUTPUT_DIRECTORY,
+                is("TESTNG_SLF4J_OUTPUT_DIRECTORY"));
     }
 
     @Test
     public void testInitOutputDirectory() throws Exception {
         SLF4JRefApplication.initOutputDirectory();
-        assertThat(System.getProperty(SLF4JRefApplication.SLF4J_OUTPUT_DIRECTORY),
+        assertThat(System.getProperty(SLF4JRefApplication.TESTNG_SLF4J_OUTPUT_DIRECTORY),
                 notNullValue());
     }
 }
diff --git a/reference/logging-slf4j-demo/src/main/resources/logback.xml b/reference/logging-slf4j-demo/src/test/resources/logback.xml
index 554d712..ba86e54 100644
--- a/reference/logging-slf4j-demo/src/main/resources/logback.xml
+++ b/reference/logging-slf4j-demo/src/test/resources/logback.xml
@@ -17,7 +17,7 @@
     </appender>
 
     <appender name="FILE" class="ch.qos.logback.core.FileAppender">
-        <file>${SLF4J_OUTPUT_DIRECTORY}/output.log</file>
+        <file>${TESTNG_SLF4J_OUTPUT_DIRECTORY}/output.log</file>
         <encoder>
             <pattern>${pattern}</pattern>
         </encoder>
diff --git a/reference/logging-slf4j/README.md b/reference/logging-slf4j/README.md
index 2796a21..bbad3b3 100644
--- a/reference/logging-slf4j/README.md
+++ b/reference/logging-slf4j/README.md
@@ -25,26 +25,13 @@ The adapter provides:
 Note that:
 * The adapter implementation uses static inner classes in order to fit in a single source file. This was an objective. 
 
-## WAR
-
-Building produces a simple (spring-boot](https://projects.spring.io/spring-boot/) example WAR, which can be launched from this directory with:
-
-```bash
-$ java -war target/*war
-```
-
-The example WAR in ```logging-slf4j-demo``` publishes four web services:
-1. ```services/alpha```
-2. ```services/beta```
-3. ```services/gamma```
-4. ```services/delta```
+The purpose of the WAR is to demonstrate minimalist ONAP-compliant logging for web components, but a secondary purpose is to demonstrate that the call graph can be generated for a (mostly) representative set of interacting REST services.
 
-... each of which can invoke the others.
+## Configuration
 
-The purpose of the WAR is to demonstrate minimalist ONAP-compliant logging for web components, but a secondary purpose is to demonstrate that the call graph can be generated for a (mostly) representative set of interacting REST services.
+Note that the bundled SLF4J configuration *isn't* meant to be normative. Close enough as makes no difference for
+the purposes of tests, but be aware that it might not always be up-to-date.
 
 ## Tests
 
-Tests for:
-1. Code in the (potentially) reusable ``common`` package.
-2. Validating that emitted logs can be used to generate an unambiguous call graph.
+TestNG tests for contract + output of SLF4J reference impl.
diff --git a/reference/logging-slf4j/src/main/java/org/onap/logging/ref/slf4j/ONAPLogAdapter.java b/reference/logging-slf4j/src/main/java/org/onap/logging/ref/slf4j/ONAPLogAdapter.java
index 50693cb..d26cd13 100644
--- a/reference/logging-slf4j/src/main/java/org/onap/logging/ref/slf4j/ONAPLogAdapter.java
+++ b/reference/logging-slf4j/src/main/java/org/onap/logging/ref/slf4j/ONAPLogAdapter.java
@@ -21,7 +21,9 @@
 
 package org.onap.logging.ref.slf4j;
 
-import java.time.LocalDateTime;
+import java.time.ZoneOffset;
+import java.time.ZonedDateTime;
+import java.time.format.DateTimeFormatter;
 import java.util.UUID;
 
 import javax.servlet.http.HttpServletRequest;
@@ -315,7 +317,9 @@ public class ONAPLogAdapter {
         // depending on where you need them to appear, OR extend the
         // ServiceDescriptor to add them.
 
-        MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP, LocalDateTime.now().toString());
+        MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP,
+                ZonedDateTime.now(ZoneOffset.UTC)
+                        .format(DateTimeFormatter.ISO_INSTANT));
         MDC.put(ONAPLogConstants.MDCs.REQUEST_ID, requestID);
         MDC.put(ONAPLogConstants.MDCs.INVOCATION_ID, invocationID);
         MDC.put(ONAPLogConstants.MDCs.PARTNER_NAME, partnerName);
diff --git a/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterOutputTest.java b/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterOutputTest.java
index bab74bb..d8c2419 100644
--- a/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterOutputTest.java
+++ b/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterOutputTest.java
@@ -28,6 +28,41 @@ import java.nio.file.Files;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.UUID;
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.core.Is.is;
+import static org.hamcrest.core.IsEqual.equalTo;
+import static org.hamcrest.core.IsNot.not;
+import static org.hamcrest.core.IsSame.sameInstance;
+import static org.hamcrest.core.StringContains.containsString;
+import static org.hamcrest.core.StringEndsWith.endsWith;
+import static org.hamcrest.core.Every.everyItem;
+import static org.hamcrest.core.IsInstanceOf.instanceOf;
+import static org.hamcrest.core.IsNull.notNullValue;
+import static org.hamcrest.core.IsNull.nullValue;
+import static org.hamcrest.core.StringStartsWith.startsWith;
+import static org.hamcrest.beans.HasProperty.hasProperty;
+import static org.hamcrest.number.IsCloseTo.closeTo;
+import static org.hamcrest.number.OrderingComparison.greaterThan;
+import static org.hamcrest.number.OrderingComparison.greaterThanOrEqualTo;
+import static org.hamcrest.number.OrderingComparison.lessThan;
+import static org.hamcrest.number.OrderingComparison.lessThanOrEqualTo;
+import static org.hamcrest.collection.IsArray.array;
+import static org.hamcrest.collection.IsArrayContaining.hasItemInArray;
+import static org.hamcrest.collection.IsArrayContainingInAnyOrder.arrayContainingInAnyOrder;
+import static org.hamcrest.collection.IsIn.isIn;
+import static org.hamcrest.collection.IsIn.isOneOf;
+import static org.hamcrest.collection.IsMapContaining.hasKey;
+import static org.hamcrest.collection.IsMapContaining.hasEntry;
+import static org.hamcrest.collection.IsMapContaining.hasValue;
+import static org.hamcrest.text.IsEqualIgnoringWhiteSpace.equalToIgnoringWhiteSpace;
+import static org.hamcrest.text.IsEqualIgnoringCase.equalToIgnoringCase;
+import static org.hamcrest.text.IsEmptyString.isEmptyOrNullString;
+import static org.hamcrest.text.IsEmptyString.isEmptyString;
+import static org.hamcrest.text.StringContainsInOrder.stringContainsInOrder;
+import static org.hamcrest.xml.HasXPath.hasXPath;
+
+import org.testng.Assert;
+import org.testng.annotations.Test;
 
 import javax.xml.bind.DatatypeConverter;
 
@@ -61,7 +96,7 @@ public class ONAPLogAdapterOutputTest {
     @BeforeSuite
     public static void setUp() throws Exception {
         sDir = Files.createTempDirectory(ONAPLogAdapterOutputTest.class.getName()).toFile();
-        System.getProperties().setProperty("SLF4J_OUTPUT_DIRECTORY", sDir.getAbsolutePath());
+        System.getProperties().setProperty("TESTNG_SLF4J_OUTPUT_DIRECTORY", sDir.getAbsolutePath());
         LoggerFactory.getLogger(ONAPLogAdapterOutputTest.class).info("Starting.");
     }
 
@@ -121,7 +156,9 @@ public class ONAPLogAdapterOutputTest {
         assertThat(lines.get(0), containsString("ENTRY"));
         final String [] line0 = lines.get(0).split("\t", -1);
         assertThat(line0.length, is(9));
-        DatatypeConverter.parseDateTime(line0[0]);
+        final long sanity = DatatypeConverter.parseDateTime(line0[0]).getTimeInMillis();
+        assertThat(Math.abs(System.currentTimeMillis() - sanity), lessThan(5000L));
+        assertThat(line0[0], endsWith("Z"));
         assertThat(line0[1].trim().length(), greaterThan(1));
         assertThat(line0[2], is("INFO"));
         assertThat(line0[3], is(this.getClass().getName()));
@@ -136,6 +173,7 @@ public class ONAPLogAdapterOutputTest {
         final String [] line1 = lines.get(1).split("\t", -1);
         assertThat(line1.length, is(9));
         DatatypeConverter.parseDateTime(line1[0]);
+        assertThat(line1[0], endsWith("Z"));
         assertThat(line1[1].trim().length(), greaterThan(1));
         assertThat(line1[2], is("WARN"));
         assertThat(line1[3], is(this.getClass().getName()));
@@ -150,6 +188,7 @@ public class ONAPLogAdapterOutputTest {
         final String [] line2 = lines.get(2).split("\t", -1);
         assertThat(line2.length, is(9));
         DatatypeConverter.parseDateTime(line2[0]);
+        assertThat(line2[0], endsWith("Z"));
         assertThat(line2[1].trim().length(), greaterThan(1));
         assertThat(line2[2], is("ERROR"));
         assertThat(line2[3], is(this.getClass().getName()));
diff --git a/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterTest.java b/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterTest.java
index ad22603..b14df9f 100644
--- a/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterTest.java
+++ b/reference/logging-slf4j/src/test/java/org/onap/logging/ref/slf4j/ONAPLogAdapterTest.java
@@ -25,6 +25,8 @@ import java.util.HashMap;
 import java.util.Map;
 import java.util.UUID;
 
+import javax.xml.bind.DatatypeConverter;
+
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
@@ -33,6 +35,41 @@ import org.springframework.mock.web.MockHttpServletRequest;
 import org.testng.Assert;
 import org.testng.annotations.AfterMethod;
 import org.testng.annotations.Test;
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.core.Is.is;
+import static org.hamcrest.core.IsEqual.equalTo;
+import static org.hamcrest.core.IsNot.not;
+import static org.hamcrest.core.IsSame.sameInstance;
+import static org.hamcrest.core.StringContains.containsString;
+import static org.hamcrest.core.StringEndsWith.endsWith;
+import static org.hamcrest.core.Every.everyItem;
+import static org.hamcrest.core.IsInstanceOf.instanceOf;
+import static org.hamcrest.core.IsNull.notNullValue;
+import static org.hamcrest.core.IsNull.nullValue;
+import static org.hamcrest.core.StringStartsWith.startsWith;
+import static org.hamcrest.beans.HasProperty.hasProperty;
+import static org.hamcrest.number.IsCloseTo.closeTo;
+import static org.hamcrest.number.OrderingComparison.greaterThan;
+import static org.hamcrest.number.OrderingComparison.greaterThanOrEqualTo;
+import static org.hamcrest.number.OrderingComparison.lessThan;
+import static org.hamcrest.number.OrderingComparison.lessThanOrEqualTo;
+import static org.hamcrest.collection.IsArray.array;
+import static org.hamcrest.collection.IsArrayContaining.hasItemInArray;
+import static org.hamcrest.collection.IsArrayContainingInAnyOrder.arrayContainingInAnyOrder;
+import static org.hamcrest.collection.IsIn.isIn;
+import static org.hamcrest.collection.IsIn.isOneOf;
+import static org.hamcrest.collection.IsMapContaining.hasKey;
+import static org.hamcrest.collection.IsMapContaining.hasEntry;
+import static org.hamcrest.collection.IsMapContaining.hasValue;
+import static org.hamcrest.text.IsEqualIgnoringWhiteSpace.equalToIgnoringWhiteSpace;
+import static org.hamcrest.text.IsEqualIgnoringCase.equalToIgnoringCase;
+import static org.hamcrest.text.IsEmptyString.isEmptyOrNullString;
+import static org.hamcrest.text.IsEmptyString.isEmptyString;
+import static org.hamcrest.text.StringContainsInOrder.stringContainsInOrder;
+import static org.hamcrest.xml.HasXPath.hasXPath;
+
+import org.testng.Assert;
+import org.testng.annotations.Test;
 
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.core.Is.is;
@@ -116,6 +153,14 @@ public class ONAPLogAdapterTest {
             assertThat(mdcs.get("ServiceName"), is("uri123"));
             assertThat(mdcs.get("ServerFQDN"), is("local123"));
             assertThat(mdcs.get("ClientIPAddress"), is("remote123"));
+
+            // Timestamp format and value:
+
+            final String invokeTimestampString = mdcs.get("InvokeTimestamp");
+            assertThat(invokeTimestampString, notNullValue());
+            assertThat(invokeTimestampString, endsWith("Z"));
+            final long invokeTimestamp = DatatypeConverter.parseDateTime(invokeTimestampString).getTimeInMillis();
+            assertThat(Math.abs(System.currentTimeMillis() - invokeTimestamp), lessThan(5000L));
         }
         finally {
             MDC.clear();
diff --git a/reference/logging-slf4j/src/test/resources/logback.xml b/reference/logging-slf4j/src/test/resources/logback.xml
index 554d712..ba86e54 100644
--- a/reference/logging-slf4j/src/test/resources/logback.xml
+++ b/reference/logging-slf4j/src/test/resources/logback.xml
@@ -17,7 +17,7 @@
     </appender>
 
     <appender name="FILE" class="ch.qos.logback.core.FileAppender">
-        <file>${SLF4J_OUTPUT_DIRECTORY}/output.log</file>
+        <file>${TESTNG_SLF4J_OUTPUT_DIRECTORY}/output.log</file>
         <encoder>
             <pattern>${pattern}</pattern>
         </encoder>