print user-id in partner name record of audit log

Issue-ID: VID-253

Also add more verifications for audit log format

Change-Id: I00976a63fd1a795a972c13ad975d6a71248e5c8b
Signed-off-by: Eylon Malin <eylon.malin@intl.att.com>

4 files changed, 126 insertions, 13 deletions

diff --git a/vid-app-common/src/main/java/org/onap/vid/controller/WebConfig.java b/vid-app-common/src/main/java/org/onap/vid/controller/WebConfig.java
index 91fb94231..096dba39f 100644
--- a/vid-app-common/src/main/java/org/onap/vid/controller/WebConfig.java
+++ b/vid-app-common/src/main/java/org/onap/vid/controller/WebConfig.java
@@ -66,6 +66,7 @@ import org.onap.vid.services.PombaService;
 import org.onap.vid.services.PombaServiceImpl;
 import org.onap.vid.utils.JoshworksJacksonObjectMapper;
 import org.onap.vid.utils.Logging;
+import org.onap.vid.utils.SystemPropertiesWrapper;
 import org.springframework.beans.factory.annotation.Qualifier;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
@@ -222,6 +223,7 @@ public class WebConfig implements WebMvcConfigurer {
 
     @Override
     public void addInterceptors(InterceptorRegistry registry) {
-        registry.addInterceptor(new VidLoggingInterceptor());
+        registry.addInterceptor(new VidLoggingInterceptor(
+            new ControllersUtils(new SystemPropertiesWrapper())));
     }
 }
diff --git a/vid-app-common/src/main/java/org/onap/vid/logging/VidLoggingInterceptor.java b/vid-app-common/src/main/java/org/onap/vid/logging/VidLoggingInterceptor.java
index abc7048da..fe8b470ec 100644
--- a/vid-app-common/src/main/java/org/onap/vid/logging/VidLoggingInterceptor.java
+++ b/vid-app-common/src/main/java/org/onap/vid/logging/VidLoggingInterceptor.java
@@ -24,8 +24,12 @@ import java.net.InetAddress;
 import java.net.UnknownHostException;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
+import org.apache.commons.lang3.StringUtils;
+import org.onap.logging.filter.base.MDCSetup;
+import org.onap.logging.filter.base.SimpleMap;
 import org.onap.logging.filter.spring.LoggingInterceptor;
 import org.onap.logging.ref.slf4j.ONAPLogConstants.MDCs;
+import org.onap.vid.controller.ControllersUtils;
 import org.slf4j.MDC;
 import org.springframework.web.servlet.ModelAndView;
 
@@ -34,6 +38,11 @@ public class VidLoggingInterceptor extends LoggingInterceptor {
     static final String INBOUND_INVO_ID = "InboundInvoId";
 
     private static final String canonicalHostName = getCanonicalName();
+    private final ControllersUtils controllersUtils;
+
+    public VidLoggingInterceptor(ControllersUtils controllersUtils) {
+        this.controllersUtils = controllersUtils;
+    }
 
     private static String getCanonicalName() {
         try {
@@ -45,9 +54,30 @@ public class VidLoggingInterceptor extends LoggingInterceptor {
     }
 
     @Override
-    protected void additionalPreHandling(HttpServletRequest request)  {
+    protected void additionalPreHandling(HttpServletRequest request) {
         super.additionalPreHandling(request);
         storeInboundInvocationId();
+        fillPartnerNameWithUserId(request);
+    }
+
+    void fillPartnerNameWithUserId(HttpServletRequest request) {
+        String userId = controllersUtils.extractUserId(request);
+        if (StringUtils.isNotEmpty(userId)) {
+            MDC.put(MDCs.PARTNER_NAME, userId);
+        }
+    }
+
+    @Override
+    //this method override fix bug in logging library
+    //that may throw some exceptions, e.g. StringIndexOutOfBoundsException
+    protected String getBasicAuthUserName(SimpleMap headers) {
+        try {
+            return super.getBasicAuthUserName(headers);
+        } catch (Exception e) {
+            MDCSetup.logger.error("failed to getBasicAuthUserName", e);
+        }
+
+        return null;
     }
 
     /*
@@ -61,6 +91,7 @@ public class VidLoggingInterceptor extends LoggingInterceptor {
     public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
         restoreInvocationId();
         fixServerFQDN();
+        fillPartnerNameWithUserId(request);
         super.postHandle(request, response, handler, modelAndView);
     }
 
diff --git a/vid-app-common/src/test/java/org/onap/vid/logging/VidLoggingInterceptorTest.java b/vid-app-common/src/test/java/org/onap/vid/logging/VidLoggingInterceptorTest.java
index fc78ed714..c31d00df8 100644
--- a/vid-app-common/src/test/java/org/onap/vid/logging/VidLoggingInterceptorTest.java
+++ b/vid-app-common/src/test/java/org/onap/vid/logging/VidLoggingInterceptorTest.java
@@ -20,10 +20,22 @@
 
 package org.onap.vid.logging;
 
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
 import static org.onap.vid.logging.VidLoggingInterceptor.INBOUND_INVO_ID;
 import static org.testng.Assert.assertEquals;
+import static org.testng.AssertJUnit.assertNull;
 
+import java.util.HashMap;
+import javax.servlet.http.HttpServletRequest;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+import org.onap.logging.filter.base.SimpleHashMap;
+import org.onap.logging.filter.base.SimpleMap;
 import org.onap.logging.ref.slf4j.ONAPLogConstants;
+import org.onap.logging.ref.slf4j.ONAPLogConstants.MDCs;
+import org.onap.vid.controller.ControllersUtils;
 import org.slf4j.MDC;
 import org.testng.annotations.BeforeMethod;
 import org.testng.annotations.Test;
@@ -32,17 +44,58 @@ public class VidLoggingInterceptorTest {
 
     private VidLoggingInterceptor interceptor;
 
+    @Mock
+    private ControllersUtils controllersUtils;
+
     @BeforeMethod
     public void setup() {
-        interceptor = new VidLoggingInterceptor();
+        MockitoAnnotations.initMocks(this);
+        interceptor = new VidLoggingInterceptor(controllersUtils);
         MDC.clear();
     }
 
     @Test
     public void testAdditionalPreHandling() {
-        MDC.put(ONAPLogConstants.MDCs.INVOCATION_ID, "987");
-        interceptor.additionalPreHandling(null);
-        assertEquals(MDC.get(INBOUND_INVO_ID), "987");
+
+        //given
+        final String invoID = "987";
+        MDC.put(ONAPLogConstants.MDCs.INVOCATION_ID, invoID);
+        MDC.put(MDCs.PARTNER_NAME, "wrongPartnerName");
+        final String myUserId = "myUserId";
+        when(controllersUtils.extractUserId(any(HttpServletRequest.class)))
+            .thenReturn(myUserId);
+
+        //when
+        interceptor.additionalPreHandling(mock(HttpServletRequest.class));
+
+        //then
+        assertEquals(MDC.get(INBOUND_INVO_ID), invoID);
+        assertEquals(MDC.get(MDCs.PARTNER_NAME), myUserId);
+    }
+
+    @Test
+    public void whenNoUserId_previousPartnerNameIsPreserved() {
+        //given
+        final String prevPartnerName = "prevPartnerName";
+        MDC.put(MDCs.PARTNER_NAME, prevPartnerName);
+        final HttpServletRequest mockedRequest = mock(HttpServletRequest.class);
+        when(controllersUtils.extractUserId(any(HttpServletRequest.class)))
+            .thenReturn("");
+
+        //when
+        interceptor.additionalPreHandling(mockedRequest);
+
+        //then
+        assertEquals(MDC.get(MDCs.PARTNER_NAME), prevPartnerName);
+
+    }
+
+    @Test
+    public void givenNotValidAuthorizationHeader_whenGetBasicAuthUserName_noExceptionIsThrown() {
+        HashMap<String, String> hashMap = new HashMap<>();
+        hashMap.put("Authorization","abcdefghi");
+        SimpleMap headers = new SimpleHashMap(hashMap);
+        assertNull(interceptor.getBasicAuthUserName(headers));
     }
 
 }
diff --git a/vid-automation/src/test/java/org/onap/vid/more/LoggerFormatTest.java b/vid-automation/src/test/java/org/onap/vid/more/LoggerFormatTest.java
index 7a4eedfa9..6c4058f1e 100644
--- a/vid-automation/src/test/java/org/onap/vid/more/LoggerFormatTest.java
+++ b/vid-automation/src/test/java/org/onap/vid/more/LoggerFormatTest.java
@@ -9,9 +9,12 @@ import static org.hamcrest.Matchers.allOf;
 import static org.hamcrest.Matchers.contains;
 import static org.hamcrest.Matchers.containsInAnyOrder;
 import static org.hamcrest.Matchers.containsInRelativeOrder;
+import static org.hamcrest.Matchers.either;
+import static org.hamcrest.Matchers.emptyOrNullString;
 import static org.hamcrest.Matchers.greaterThan;
 import static org.hamcrest.Matchers.greaterThanOrEqualTo;
 import static org.hamcrest.Matchers.hasSize;
+import static org.hamcrest.Matchers.matchesPattern;
 import static vid.automation.test.services.SimulatorApi.retrieveRecordedRequests;
 
 import com.fasterxml.jackson.databind.JsonNode;
@@ -26,6 +29,7 @@ import java.util.Map;
 import org.apache.commons.lang3.StringUtils;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
+import org.jetbrains.annotations.NotNull;
 import org.onap.simulator.presetGenerator.presets.aai.PresetAAIGetSubscribersGet;
 import org.onap.vid.api.BaseApiTest;
 import org.springframework.web.client.RestTemplate;
@@ -55,7 +59,25 @@ public class LoggerFormatTest extends BaseApiTest {
 
     @Test
     public void validateAudit2019LogsFormat() {
-        validateLogsFormat(LogName.audit2019, "audit-ELS-2019.11");
+        String logLines = validateLogsFormat(LogName.audit2019, "audit-ELS-2019.11");
+        moreValidationsForAuditFormat(logLines);
+    }
+
+    //more validations for log format that logcheck doesn't verify
+    private void moreValidationsForAuditFormat(String logLines) {
+        splitLogLines(logLines).forEach(line->{
+            String[] records = line.split("\\|");
+            assertThat("server name shall be empty", records[5], emptyOrNullString());
+
+            //authenticated request shall logs with userId.
+            final String serviceName = records[6];
+            if (StringUtils.containsAny(serviceName, "aai", "mso")) {
+                assertThat("Partner name shall be userId", records[7], matchesPattern("^[A-Za-z0-9]{4,15}$"));
+            }
+
+            assertThat("Severity shall be empty", records[13], emptyOrNullString());
+            assertThat("marker", records[21], either(is("ENTRY")).or(is("EXIT")));
+        });
     }
 
     @Test(enabled = false) // no total-score is returned for error-log
@@ -72,11 +94,11 @@ public class LoggerFormatTest extends BaseApiTest {
         validateLogsFormat(logName, logName.name());
     }
 
-    private void validateLogsFormat(LogName logName, String logType) {
-        validateLogsFormat(logName, logType, 0.95);
+    private String validateLogsFormat(LogName logName, String logType) {
+        return validateLogsFormat(logName, logType, 0.95);
     }
 
-    private void validateLogsFormat(LogName logName, String logType, double score) {
+    private String validateLogsFormat(LogName logName, String logType, double score) {
 
         String logLines = getLogLines(logName);
         logger.info("logLines are: "+logLines);
@@ -88,6 +110,8 @@ public class LoggerFormatTest extends BaseApiTest {
 
         assertThat(total_records, greaterThan(30)); //make sure we have at least 30 total records
         assertThat((double)valid_records/total_records, is(greaterThanOrEqualTo(score)));
+
+        return logLines;
     }
 
     private String getLogLines(LogName logname) {
@@ -107,9 +131,7 @@ public class LoggerFormatTest extends BaseApiTest {
      */
     public static List<String> getLogLinesAsList(LogName logname, int maxRows, int minRows, RestTemplate restTemplate, URI uri) {
         String logLines = LoggerFormatTest.getLogLines(logname, maxRows, minRows, restTemplate, uri);
-
-        // Split
-        List<String> lines = new ArrayList<>(Arrays.asList(logLines.split("(\\r?\\n)")));
+        List<String> lines = splitLogLines(logLines);
 
         // Reverse
         reverse(lines);
@@ -117,6 +139,11 @@ public class LoggerFormatTest extends BaseApiTest {
         return lines;
     }
 
+    @NotNull
+    private static List<String> splitLogLines(String logLines) {
+        return new ArrayList<>(Arrays.asList(logLines.split("(\\r?\\n)")));
+    }
+
 
     /**
      * @return Chronological-ordered list of recent log-lines of a given requestId