diff options
3 files changed, 52 insertions, 15 deletions
diff --git a/sli/common/pom.xml b/sli/common/pom.xml index 5fb0b5ff..16efd0e5 100755 --- a/sli/common/pom.xml +++ b/sli/common/pom.xml @@ -60,6 +60,17 @@ <groupId>org.onap.logging-analytics</groupId> <artifactId>logging-slf4j</artifactId> </dependency> + <!-- log4j dependencies are needed to test MDC in junit tests --> + <dependency> + <groupId>org.apache.logging.log4j</groupId> + <artifactId>log4j-slf4j-impl</artifactId> + <scope>test</scope> + </dependency> + <dependency> + <groupId>org.apache.logging.log4j</groupId> + <artifactId>log4j-core</artifactId> + <scope>test</scope> + </dependency> <dependency> <groupId>com.google.code.gson</groupId> <artifactId>gson</artifactId> diff --git a/sli/common/src/main/java/org/onap/ccsdk/sli/core/sli/MetricLogger.java b/sli/common/src/main/java/org/onap/ccsdk/sli/core/sli/MetricLogger.java index 518316d5..0966c0bf 100755 --- a/sli/common/src/main/java/org/onap/ccsdk/sli/core/sli/MetricLogger.java +++ b/sli/common/src/main/java/org/onap/ccsdk/sli/core/sli/MetricLogger.java @@ -26,6 +26,10 @@ package org.onap.ccsdk.sli.core.sli; import java.text.DateFormat; import java.text.SimpleDateFormat; +import java.time.ZoneOffset; +import java.time.ZonedDateTime; +import java.time.format.DateTimeFormatter; +import java.time.temporal.ChronoUnit; import java.util.Date; import java.util.TimeZone; import org.onap.logging.ref.slf4j.ONAPLogConstants; @@ -55,6 +59,7 @@ public class MetricLogger { } + @Deprecated public static String asIso8601(Date date) { TimeZone tz = TimeZone.getTimeZone("UTC"); DateFormat df = new SimpleDateFormat("yyy-MM-dd'T'HH:mm:ss.SS'+00:00'"); @@ -62,6 +67,7 @@ public class MetricLogger { return df.format(date); } + @Deprecated public static String asIso8601(long tsInMillis) { return MetricLogger.asIso8601(new Date(tsInMillis)); } @@ -74,9 +80,10 @@ public class MetricLogger { public void logRequest(String svcInstanceId, String targetEntity, String targetServiceName, String targetElement, String msg) { - long start = System.currentTimeMillis(); - MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP, MetricLogger.asIso8601(start)); - + String timeNow = ZonedDateTime.now(ZoneOffset.UTC).format(DateTimeFormatter.ISO_INSTANT); + MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP, timeNow); + MDC.put(ONAPLogConstants.MDCs.ENTRY_TIMESTAMP, timeNow); + if (svcInstanceId != null) { MDC.put(ONAPLogConstants.MDCs.SERVICE_INSTANCE_ID, svcInstanceId); } @@ -97,9 +104,9 @@ public class MetricLogger { METRIC.info(INVOKE, "Invoke"); } - public void logResponse(String statusCode, String responseCode, String responseDescription) { - long start = System.currentTimeMillis(); - MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP, MetricLogger.asIso8601(start)); + public void logResponse(String statusCode, String responseCode, String responseDescription) { + String timeNow = ZonedDateTime.now(ZoneOffset.UTC).format(DateTimeFormatter.ISO_INSTANT); + MDC.put(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP, timeNow); if (statusCode != null) { MDC.put(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE, statusCode); @@ -110,9 +117,17 @@ public class MetricLogger { if (responseDescription != null) { MDC.put(ONAPLogConstants.MDCs.RESPONSE_DESCRIPTION, formatString(responseDescription)); } - long end = System.currentTimeMillis(); - MDC.put(ONAPLogConstants.MDCs.LOG_TIMESTAMP, MetricLogger.asIso8601(end)); - MDC.put(ONAPLogConstants.MDCs.ELAPSED_TIME, Long.toString(end - start)); + ZonedDateTime endTime = ZonedDateTime.now(ZoneOffset.UTC); + MDC.put(ONAPLogConstants.MDCs.LOG_TIMESTAMP, endTime.format(DateTimeFormatter.ISO_INSTANT)); + try { + DateTimeFormatter timeFormatter = DateTimeFormatter.ISO_ZONED_DATE_TIME; + ZonedDateTime entryTimestamp = + ZonedDateTime.parse(MDC.get(ONAPLogConstants.MDCs.ENTRY_TIMESTAMP), timeFormatter); + String elapedTime = Long.toString(ChronoUnit.MILLIS.between(entryTimestamp, endTime)); + MDC.put(ONAPLogConstants.MDCs.ELAPSED_TIME,elapedTime); + } catch (Exception e) { + //pass + } METRIC.info(INVOKE_RETURN, formatString(lastMsg)); resetContext(); } diff --git a/sli/common/src/test/java/org/onap/ccsdk/sli/core/sli/TestMetricLogger.java b/sli/common/src/test/java/org/onap/ccsdk/sli/core/sli/TestMetricLogger.java index 4b371cf8..b5090eaa 100755 --- a/sli/common/src/test/java/org/onap/ccsdk/sli/core/sli/TestMetricLogger.java +++ b/sli/common/src/test/java/org/onap/ccsdk/sli/core/sli/TestMetricLogger.java @@ -2,8 +2,12 @@ package org.onap.ccsdk.sli.core.sli; import static org.junit.Assert.*; import java.util.Date; +import java.util.UUID; + import org.junit.Before; import org.junit.Test; +import org.onap.logging.ref.slf4j.ONAPLogConstants; +import org.slf4j.MDC; public class TestMetricLogger { @@ -11,17 +15,24 @@ public class TestMetricLogger { @Before public void setUp() throws Exception { - logger = new MetricLogger(); - logger.resetContext(); - logger.logRequest("svcInstance1", "svcName", "svcPartner", "targetEntity", "targetServiceName", "targetVirtualEntity", "hello-world"); - logger.logResponse("200", "200", "SUCCESS"); - + MetricLogger.resetContext(); } @Test public final void testGetRequestID() { - logger.getRequestID(); + UUID uuid = UUID.randomUUID(); + MDC.put(ONAPLogConstants.MDCs.REQUEST_ID, uuid.toString()); + assertEquals(uuid.toString(),logger.getRequestID()); + } + + @Test + public final void elapsedTime() { + logger.logRequest("svcInstance1", "svcName", "svcPartner", "targetEntity", "targetServiceName", "targetVirtualEntity", "hello-world"); + logger.logResponse("200", "200", "SUCCESS"); + Long elapsedTime = Long.valueOf(MDC.get(ONAPLogConstants.MDCs.ELAPSED_TIME)); + assertNotNull(elapsedTime); + assertTrue(elapsedTime > 1); } @Test |