From 180d84761326fae9c222211d09b4f7496a40f974 Mon Sep 17 00:00:00 2001 From: "Smokowski, Kevin (ks6305)" Date: Fri, 24 Apr 2020 18:53:31 +0000 Subject: metric logger change fix elapsed time in metric logger Issue-ID: CCSDK-2337 Signed-off-by: Smokowski, Kevin (ks6305) Change-Id: I81c27bbead8614e2927aa9eddef3621559eb7cc0 --- sli/common/pom.xml | 11 ++++++++ .../org/onap/ccsdk/sli/core/sli/MetricLogger.java | 33 ++++++++++++++++------ .../onap/ccsdk/sli/core/sli/TestMetricLogger.java | 23 +++++++++++---- 3 files changed, 52 insertions(+), 15 deletions(-) diff --git a/sli/common/pom.xml b/sli/common/pom.xml index 5fb0b5ff0..16efd0e56 100755 --- a/sli/common/pom.xml +++ b/sli/common/pom.xml @@ -60,6 +60,17 @@ org.onap.logging-analytics logging-slf4j + + + org.apache.logging.log4j + log4j-slf4j-impl + test + + + org.apache.logging.log4j + log4j-core + test + com.google.code.gson gson 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 518316d56..0966c0bfe 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 4b371cf8f..b5090eaa2 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 -- cgit 1.2.3-korg