Changes to the audit logging implementation

Changes to the API and implementation, fixed
issues, added javadoc and unit tests, changed
scope of some dependencies to "provided" to
prevent transitive when not needed.

Change-Id: Ib76ae2f921846c2115fcc5cc61b93625307a7c65
Issue-ID: SDC-772
Signed-off-by: vempo <vitaliy.emporopulo@amdocs.com>

4 files changed, 249 insertions, 93 deletions

diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapper.java b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapper.java
index 416af8fff1..a8ada8777f 100644
--- a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapper.java
+++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapper.java
@@ -16,40 +16,50 @@
 
 package org.openecomp.sdc.logging.slf4j;
 
+import java.text.Format;
+import java.text.SimpleDateFormat;
 import org.openecomp.sdc.logging.api.AuditData;
 import org.openecomp.sdc.logging.api.Logger;
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
 
-import java.text.SimpleDateFormat;
-import java.util.Date;
-
-import static org.openecomp.sdc.logging.slf4j.SLF4JLoggingServiceProvider.PREFIX;
-
 /**
  * @author EVITALIY
  * @since 08 Jan 18
  */
 class SLF4JLoggerWrapper implements Logger {
 
-    private static final String BEGIN_TIMESTAMP = PREFIX + "BeginTimestamp";
-    private static final String END_TIMESTAMP = PREFIX + "EndTimestamp";
-    private static final String ELAPSED_TIME = PREFIX + "ElapsedTime";
-    private static final String STATUS_CODE = PREFIX + "StatusCode";
-    private static final String RESPONSE_CODE = PREFIX + "ResponseCode";
-    private static final String RESPONSE_DESCRIPTION = PREFIX + "ResponsDescription";
-    private static final String CLIENT_IP_ADDRESS = PREFIX + "ClientIpAddress";
-
     //The specified format presents time in UTC formatted per ISO 8601, as required by ONAP logging guidelines
-    private final SimpleDateFormat DATE_FORMAT = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSSXXX");
+
+    private static final String DATE_TIME_PATTERN = "yyyy-MM-dd'T'HH:mm:ss.SSSXXX";
+    private static final String PREFIX = "";
+
+    static final String BEGIN_TIMESTAMP = PREFIX + "BeginTimestamp";
+    static final String END_TIMESTAMP = PREFIX + "EndTimestamp";
+    static final String ELAPSED_TIME = PREFIX + "ElapsedTime";
+    static final String STATUS_CODE = PREFIX + "StatusCode";
+    static final String RESPONSE_CODE = PREFIX + "ResponseCode";
+    static final String RESPONSE_DESCRIPTION = PREFIX + "ResponseDescription";
+    static final String CLIENT_IP_ADDRESS = PREFIX + "ClientIpAddress";
+
+    private static final String[] ALL_MDC_FIELDS = {
+        BEGIN_TIMESTAMP, END_TIMESTAMP, ELAPSED_TIME, STATUS_CODE,
+        RESPONSE_CODE, RESPONSE_DESCRIPTION, CLIENT_IP_ADDRESS
+    };
+
     private final org.slf4j.Logger logger;
 
+    SLF4JLoggerWrapper(org.slf4j.Logger delegate) {
+        this.logger = delegate;
+    }
+
+    // May cause http://www.slf4j.org/codes.html#loggerNameMismatch
     SLF4JLoggerWrapper(Class<?> clazz) {
-        logger = LoggerFactory.getLogger(clazz);
+        this(LoggerFactory.getLogger(clazz));
     }
 
     SLF4JLoggerWrapper(String className) {
-        logger = LoggerFactory.getLogger(className);
+        this(LoggerFactory.getLogger(className));
     }
 
     @Override
@@ -96,42 +106,41 @@ class SLF4JLoggerWrapper implements Logger {
     public void audit(AuditData data) {
 
         if (data == null) {
-            return;
+            return; // not failing if null
         }
 
-        MDC.put(BEGIN_TIMESTAMP, DATE_FORMAT.format(new Date(data.getStartTime())));
-        MDC.put(END_TIMESTAMP,   DATE_FORMAT.format(new Date(data.getEndTime())));
-        MDC.put(ELAPSED_TIME,    String.valueOf(data.getEndTime() - data.getStartTime()));
+        putTimes(data);
+        putIfNotNull(RESPONSE_CODE, data.getResponseCode());
+        putIfNotNull(RESPONSE_DESCRIPTION, data.getResponseDescription());
+        putIfNotNull(CLIENT_IP_ADDRESS, data.getClientIpAddress());
 
         if (data.getStatusCode() != null) {
-            MDC.put(STATUS_CODE, data.getStatusCode() == AuditData.StatusCode.COMPLETE ? "COMPLETE" : "ERROR");
-        }
-
-        if (data.getResponseCode() != null) {
-            MDC.put(RESPONSE_CODE, data.getResponseCode());
-        }
-
-        if (data.getResponseDescription() != null) {
-            MDC.put(RESPONSE_DESCRIPTION, data.getResponseDescription());
-        }
-
-        if (data.getClientIpAddress() != null) {
-            MDC.put(CLIENT_IP_ADDRESS, data.getClientIpAddress());
+            MDC.put(STATUS_CODE, data.getStatusCode().name());
         }
 
         try {
             logger.info(Markers.AUDIT, "");
         } finally {
-            MDC.remove(BEGIN_TIMESTAMP);
-            MDC.remove(END_TIMESTAMP);
-            MDC.remove(ELAPSED_TIME);
-            MDC.remove(STATUS_CODE);
-            MDC.remove(RESPONSE_CODE);
-            MDC.remove(RESPONSE_DESCRIPTION);
-            MDC.remove(CLIENT_IP_ADDRESS);
+            for (String k : ALL_MDC_FIELDS) {
+                MDC.remove(k);
+            }
         }
     }
 
+    private void putIfNotNull(String key, String value) {
+        if (value != null) {
+            MDC.put(key, value);
+        }
+    }
+
+    private void putTimes(AuditData data) {
+        // SimpleDateFormat is not thread-safe and cannot be a constant
+        Format dateTimeFormat = new SimpleDateFormat(DATE_TIME_PATTERN);
+        MDC.put(BEGIN_TIMESTAMP, dateTimeFormat.format(data.getStartTime()));
+        MDC.put(END_TIMESTAMP, dateTimeFormat.format(data.getEndTime()));
+        MDC.put(ELAPSED_TIME, String.valueOf(data.getEndTime() - data.getStartTime()));
+    }
+
     @Override
     public boolean isDebugEnabled() {
         return logger.isDebugEnabled();
diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggingServiceProvider.java b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggingServiceProvider.java
index 86b2297371..fbda93cf61 100644
--- a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggingServiceProvider.java
+++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/main/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggingServiceProvider.java
@@ -28,13 +28,7 @@ import org.slf4j.MDC;
  */
 public class SLF4JLoggingServiceProvider implements LoggingServiceProvider {
 
-    public static final String PREFIX = "";
     private static final String KEY_CANNOT_BE_NULL = "Key cannot be null";
-    private static final String REQUEST_ID = PREFIX + "RequestId";
-    private static final String SERVICE_NAME = PREFIX + "ServiceName";
-    private static final String PARTNER_NAME = PREFIX + "PartnerName";
-
-    private static final String[] ALL_FIELDS = { REQUEST_ID, SERVICE_NAME, PARTNER_NAME };
 
     @Override
     public Logger getLogger(String className) {
@@ -74,14 +68,12 @@ public class SLF4JLoggingServiceProvider implements LoggingServiceProvider {
     @Override
     public Runnable copyToRunnable(Runnable runnable) {
         Objects.requireNonNull(runnable, "Runnable cannot be null");
-        // TODO: Copy only the fields this service is responsible for
         return new MDCRunnableWrapper(runnable);
     }
 
     @Override
     public <V> Callable<V> copyToCallable(Callable<V> callable) {
         Objects.requireNonNull(callable, "Runnable cannot be null");
-        // TODO: Copy only the fields this service is responsible for
         return new MDCCallableWrapper<>(callable);
     }
 
diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/LogFileCreationTest.java b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/LogFileCreationTest.java
index 4595e567c8..14dab13c9e 100644
--- a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/LogFileCreationTest.java
+++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/LogFileCreationTest.java
@@ -21,8 +21,17 @@ import org.openecomp.sdc.logging.api.Logger;
 import org.openecomp.sdc.logging.api.LoggerFactory;
 import org.testng.annotations.Test;
 
+/**
+ * This is only for manual testing to make sure that a log file is created as expected.
+ * To run change {@link #ENABLED} to 'true'
+ *
+ * @author evitaliy
+ * @since 13/09/2016.
+ */
 public class LogFileCreationTest {
+
     private static final boolean ENABLED = false; // for manual testing change to 'true'
+
     private static final Logger LOGGER = LoggerFactory.getLogger(LogFileCreationTest.class);
 
     @Test(enabled = ENABLED)
@@ -32,8 +41,7 @@ public class LogFileCreationTest {
 
     @Test(enabled = ENABLED)
     public void testAudit() {
-        SpyAuditData auditData = new SpyAuditData();
-        LOGGER.audit(auditData);
+        LOGGER.audit(AuditData.builder().build());
     }
 
     @Test(enabled = ENABLED)
@@ -55,47 +63,4 @@ public class LogFileCreationTest {
     public void testError() {
         LOGGER.error("This is error");
     }
-
-    private class SpyAuditData implements AuditData {
-        @Override
-        public long getStartTime() {
-
-            return 0;
-
-        }
-
-        @Override
-        public long getEndTime(){
-
-            return 0;
-        }
-
-        @Override
-        public StatusCode getStatusCode(){
-
-            return null;
-
-        }
-
-        @Override
-        public String getResponseCode(){
-
-            return null;
-
-        }
-
-        @Override
-        public String getResponseDescription(){
-
-            return null;
-
-        }
-
-        @Override
-        public String getClientIpAddress(){
-
-            return null;
-
-        }
-    }
 }
diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapperTest.java b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapperTest.java
new file mode 100644
index 0000000000..a4a5e5c72c
--- /dev/null
+++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapperTest.java
@@ -0,0 +1,190 @@
+/*
+ * Copyright © 2016-2018 European Support Limited
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.openecomp.sdc.logging.slf4j;
+
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.BEGIN_TIMESTAMP;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.CLIENT_IP_ADDRESS;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.ELAPSED_TIME;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.END_TIMESTAMP;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.RESPONSE_CODE;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.RESPONSE_DESCRIPTION;
+import static org.openecomp.sdc.logging.slf4j.SLF4JLoggerWrapper.STATUS_CODE;
+import static org.testng.Assert.assertEquals;
+import static org.testng.Assert.assertNotNull;
+import static org.testng.Assert.assertNull;
+
+import java.lang.reflect.InvocationHandler;
+import java.lang.reflect.Method;
+import java.lang.reflect.Proxy;
+import java.util.Arrays;
+import java.util.Map;
+import org.openecomp.sdc.logging.api.AuditData;
+import org.openecomp.sdc.logging.api.StatusCode;
+import org.slf4j.Logger;
+import org.slf4j.MDC;
+import org.testng.annotations.Test;
+
+/**
+ * @author EVITALIY
+ * @since 05 Mar 18
+ */
+public class SLF4JLoggerWrapperTest {
+
+    @Test
+    public void auditDoesNotFailWhenInputNull() {
+        new SLF4JLoggerWrapper(this.getClass()).audit(null);
+    }
+
+    @Test
+    public void beginTimeAvailableWhenPassed() {
+        SpyLogger spy = createSpy();
+        long start = System.currentTimeMillis();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().startTime(start).build());
+        assertNotNull(spy.mdc().get(BEGIN_TIMESTAMP));
+    }
+
+    @Test
+    public void entTimeAvailableWhenPassed() {
+        SpyLogger spy = createSpy();
+        long end = System.currentTimeMillis();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().endTime(end).build());
+        assertNotNull(spy.mdc().get(END_TIMESTAMP));
+    }
+
+    @Test
+    public void elapsedTimeAvailableWhenPassed() {
+        SpyLogger spy = createSpy();
+        long start = System.currentTimeMillis();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder()
+            .startTime(start).endTime(start).build());
+        assertNotNull(spy.mdc().get(ELAPSED_TIME));
+    }
+
+    @Test
+    public void statusCodeAvailableWhenPassed() {
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().statusCode(StatusCode.COMPLETE).build());
+        assertEquals(spy.mdc().get(STATUS_CODE), StatusCode.COMPLETE.name());
+    }
+
+    @Test
+    public void statusCodeEmptyWhenNotPassed() {
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().build());
+        assertNull(spy.mdc().get(STATUS_CODE));
+    }
+
+    @Test
+    public void responseCodeAvailableWhenPassed() {
+        final String responseCode = "SpyResponse";
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().responseCode(responseCode).build());
+        assertEquals(spy.mdc().get(RESPONSE_CODE), responseCode);
+    }
+
+    @Test
+    public void responseCodeEmptyWhenNotPassed() {
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().build());
+        assertNull(spy.mdc().get(RESPONSE_CODE));
+    }
+
+    @Test
+    public void responseDescriptionAvailableWhenPassed() {
+        final String responseDescription = "SpyDescription";
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().responseDescription(responseDescription).build());
+        assertEquals(spy.mdc().get(RESPONSE_DESCRIPTION), responseDescription);
+    }
+
+    @Test
+    public void responseDescriptionEmptyWhenNotPassed() {
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().build());
+        assertNull(spy.mdc().get(RESPONSE_DESCRIPTION));
+    }
+
+    @Test
+    public void clientIpAddressAvailableWhenPassed() {
+        final String ipAddress = "10.56.20.20";
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().clientIpAddress(ipAddress).build());
+        assertEquals(spy.mdc().get(CLIENT_IP_ADDRESS), ipAddress);
+    }
+
+    @Test
+    public void clientIpAddressEmptyWhenNotPassed() {
+        SpyLogger spy = createSpy();
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().build());
+        assertNull(spy.mdc().get(CLIENT_IP_ADDRESS));
+    }
+
+    @Test
+    public void elapsedTimeEqualsDifferenceBetweenStartAndEnd() {
+        SpyLogger spy = createSpy();
+        final long diff = 1024;
+        long start = System.currentTimeMillis();
+        long end = start + diff;
+        new SLF4JLoggerWrapper(spy).audit(AuditData.builder().startTime(start).endTime(end).build());
+        assertEquals(spy.mdc().get(ELAPSED_TIME), Long.toString(diff));
+    }
+
+    interface SpyLogger extends Logger {
+
+        Map<String, String> mdc();
+    }
+
+    /**
+     * Creates a in instance of Logger that can be used to track MDC changes as part of an invocation of
+     * Logger.audit().
+     *
+     * @return object that implements {@link SpyLogger}
+     */
+    private static SpyLogger createSpy() {
+
+        // build a dynamic proxy to avoid implementing the long list of Logger methods
+        // when we actually need just Logger.info() with the audit marker
+        ClassLoader classLoader = Thread.currentThread().getContextClassLoader();
+        return SpyLogger.class.cast(
+                Proxy.newProxyInstance(classLoader, new Class<?>[]{SpyLogger.class}, new SpyingInvocationHandler()));
+    }
+
+    private static class SpyingInvocationHandler implements InvocationHandler {
+
+        private Map<String, String> mdc;
+
+        @Override
+        public Object invoke(Object proxy, Method method, Object[] args) {
+
+            // return the remembered MDC for spying
+            if (method.getName().equals("mdc")) {
+                return mdc;
+            }
+
+            // filter out everything that's not related to audit
+            if (!method.getName().equals("info") || args.length == 0 || !args[0].equals(Markers.AUDIT)) {
+                throw new UnsupportedOperationException("Method " + method.getName() + " with arguments " +
+                    Arrays.toString(args) + " wasn't supposed to be called");
+            }
+
+            // remember the MDC that was active during the invocation
+            mdc = MDC.getCopyOfContextMap();
+
+            return null;
+        }
+    }
+}
\ No newline at end of file