From c0a40b89c4635e57e02d9be89d2eda9c7a58295d Mon Sep 17 00:00:00 2001 From: "Smokowski, Kevin (ks6305)" Date: Wed, 17 Jun 2020 09:22:15 -0500 Subject: MetricLogger MDC changes Generate RequestID if not previously set. Generate a unique InvocationID for each request. Issue-ID: CCSDK-2455 Signed-off-by: Smokowski, Kevin (ks6305) Change-Id: I3bd8f90efbf98b4bf2a6464d94682bcd80cdd948 --- .../org/onap/ccsdk/sli/core/sli/MetricLogger.java | 22 ++++++++--- .../onap/ccsdk/sli/core/sli/TestMetricLogger.java | 44 +++++++++++++++++----- 2 files changed, 51 insertions(+), 15 deletions(-) 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 0966c0bf..577b7340 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 @@ -32,6 +32,8 @@ import java.time.format.DateTimeFormatter; import java.time.temporal.ChronoUnit; import java.util.Date; import java.util.TimeZone; +import java.util.UUID; + import org.onap.logging.ref.slf4j.ONAPLogConstants; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -82,8 +84,18 @@ public class MetricLogger { String msg) { 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 transaction is initialized by an external client this will already be set by the audit servlet filter + // If the transaction is initialized by CCSDK this code will handle generating a new UUID + String requestId = MDC.get(ONAPLogConstants.MDCs.REQUEST_ID); + if (requestId == null || requestId.isEmpty()) { + MDC.put(ONAPLogConstants.MDCs.REQUEST_ID, UUID.randomUUID().toString()); + } + + String randomInvocationId = UUID.randomUUID().toString(); + MDC.put(ONAPLogConstants.MDCs.INVOCATION_ID, randomInvocationId); + MDC.put(ONAPLogConstants.MDCs.CLIENT_INVOCATION_ID, randomInvocationId); + if (svcInstanceId != null) { MDC.put(ONAPLogConstants.MDCs.SERVICE_INSTANCE_ID, svcInstanceId); } @@ -101,13 +113,11 @@ public class MetricLogger { this.lastMsg = msg; //During invoke status will always be INPROGRESS MDC.put(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE, ONAPLogConstants.ResponseStatus.INPROGRESS.toString()); + MDC.put(ONAPLogConstants.MDCs.ELAPSED_TIME, "0"); METRIC.info(INVOKE, "Invoke"); } 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); } @@ -122,7 +132,7 @@ public class MetricLogger { try { DateTimeFormatter timeFormatter = DateTimeFormatter.ISO_ZONED_DATE_TIME; ZonedDateTime entryTimestamp = - ZonedDateTime.parse(MDC.get(ONAPLogConstants.MDCs.ENTRY_TIMESTAMP), timeFormatter); + ZonedDateTime.parse(MDC.get(ONAPLogConstants.MDCs.INVOKE_TIMESTAMP), timeFormatter); String elapedTime = Long.toString(ChronoUnit.MILLIS.between(entryTimestamp, endTime)); MDC.put(ONAPLogConstants.MDCs.ELAPSED_TIME,elapedTime); } catch (Exception e) { @@ -149,5 +159,7 @@ public class MetricLogger { MDC.remove(ONAPLogConstants.MDCs.RESPONSE_STATUS_CODE); MDC.remove(ONAPLogConstants.MDCs.RESPONSE_CODE); MDC.remove(ONAPLogConstants.MDCs.RESPONSE_DESCRIPTION); + MDC.remove(ONAPLogConstants.MDCs.ELAPSED_TIME); } + } 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 b5090eaa..37d2fc8c 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 @@ -25,16 +25,7 @@ public class TestMetricLogger { 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 public final void testAsIso8601Date() { logger.asIso8601(new Date()); @@ -58,4 +49,37 @@ public class TestMetricLogger { output = logger.formatString("one,two,three,"); assertEquals("one\\,two\\,three\\,", output); } + + @Test + public void generateInvocationId() { + logger.logRequest("svcInstance1", "svcName", "svcPartner", "targetEntity", "targetServiceName", "targetVirtualEntity", "hello-world"); + assertNotNull(MDC.get(ONAPLogConstants.MDCs.CLIENT_INVOCATION_ID)); + assertNotNull(MDC.get(ONAPLogConstants.MDCs.INVOCATION_ID)); + } + + @Test + public void generateRequestId() { + logger.logRequest("svcInstance1", "svcName", "svcPartner", "targetEntity", "targetServiceName", "targetVirtualEntity", "hello-world"); + assertNotNull(MDC.get(ONAPLogConstants.MDCs.REQUEST_ID)); + } + + @Test + public void overrideInvocationId() { + String oldUUID = UUID.randomUUID().toString(); + MDC.put(ONAPLogConstants.MDCs.CLIENT_INVOCATION_ID, oldUUID); + MDC.put(ONAPLogConstants.MDCs.INVOCATION_ID, oldUUID); + + logger.logRequest("svcInstance1", "svcName", "svcPartner", "targetEntity", "targetServiceName", "targetVirtualEntity", "hello-world"); + String newUUID = MDC.get(ONAPLogConstants.MDCs.CLIENT_INVOCATION_ID); + assertFalse(oldUUID.equals(newUUID)); + newUUID = MDC.get(ONAPLogConstants.MDCs.INVOCATION_ID); + assertFalse(oldUUID.equals(newUUID)); + } + + @Test + public void persistRequestId() { + String oldUUID = UUID.randomUUID().toString(); + MDC.put(ONAPLogConstants.MDCs.REQUEST_ID, oldUUID); + assertEquals(oldUUID, MDC.get(ONAPLogConstants.MDCs.REQUEST_ID)); + } } -- cgit 1.2.3-korg