metric logger change

fix elapsed time in metric logger

Issue-ID: CCSDK-2337
Signed-off-by: Smokowski, Kevin (ks6305) <kevin.smokowski@att.com>
Change-Id: I81c27bbead8614e2927aa9eddef3621559eb7cc0

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 @@
             <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 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