From bca830c8ee8cc574bd3f05e0599c56d05ba011e2 Mon Sep 17 00:00:00 2001 From: Luke Parker Date: Tue, 19 Jun 2018 23:35:33 +1000 Subject: Change MDC datetime formatter to Zulu time Change-Id: I0e771e0ec10d1972290c44e8e0740309ac83bc52 Signed-off-by: Luke Parker Issue-ID: LOG-115 --- reference/logging-slf4j-demo/README.md | 31 ++------------- .../ref/slf4j/demo/SLF4JRefApplication.java | 6 +-- .../src/main/resources/logback.xml | 35 ----------------- .../org/onap/logging/ref/slf4j/CallGraphTest.java | 2 +- .../ref/slf4j/demo/SLF4JRefApplicationTest.java | 6 +-- .../src/test/resources/logback.xml | 35 +++++++++++++++++ reference/logging-slf4j/README.md | 23 +++-------- .../org/onap/logging/ref/slf4j/ONAPLogAdapter.java | 8 +++- .../ref/slf4j/ONAPLogAdapterOutputTest.java | 43 ++++++++++++++++++++- .../onap/logging/ref/slf4j/ONAPLogAdapterTest.java | 45 ++++++++++++++++++++++ .../logging-slf4j/src/test/resources/logback.xml | 2 +- 11 files changed, 143 insertions(+), 93 deletions(-) delete mode 100644 reference/logging-slf4j-demo/src/main/resources/logback.xml create mode 100644 reference/logging-slf4j-demo/src/test/resources/logback.xml 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/main/resources/logback.xml b/reference/logging-slf4j-demo/src/main/resources/logback.xml deleted file mode 100644 index 554d712..0000000 --- a/reference/logging-slf4j-demo/src/main/resources/logback.xml +++ /dev/null @@ -1,35 +0,0 @@ - - - - - - - - - - - - - - - ${pattern} - - - - - ${SLF4J_OUTPUT_DIRECTORY}/output.log - - ${pattern} - - - - - - - - - - - - - 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/test/resources/logback.xml b/reference/logging-slf4j-demo/src/test/resources/logback.xml new file mode 100644 index 0000000..ba86e54 --- /dev/null +++ b/reference/logging-slf4j-demo/src/test/resources/logback.xml @@ -0,0 +1,35 @@ + + + + + + + + + + + + + + + ${pattern} + + + + + ${TESTNG_SLF4J_OUTPUT_DIRECTORY}/output.log + + ${pattern} + + + + + + + + + + + + + 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 @@ - ${SLF4J_OUTPUT_DIRECTORY}/output.log + ${TESTNG_SLF4J_OUTPUT_DIRECTORY}/output.log ${pattern} -- cgit 1.2.3-korg