From e70e2318753cf6217fd809c4b9c9e4e8ce5d0da3 Mon Sep 17 00:00:00 2001 From: vempo Date: Mon, 5 Mar 2018 20:55:58 +0200 Subject: 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 --- .../org/openecomp/sdc/logging/api/AuditData.java | 190 ++++++++++++++++++--- .../org/openecomp/sdc/logging/api/StatusCode.java | 27 +++ .../openecomp/sdc/logging/api/AuditDataTest.java | 59 +++++++ .../sdc/logging/api/LoggerFactoryTest.java | 2 +- .../openecomp/sdc/logging/api/SpyAuditData.java | 63 ------- .../openecomp-sdc-logging-core/pom.xml | 3 + .../sdc/logging/slf4j/SLF4JLoggerWrapper.java | 89 +++++----- .../logging/slf4j/SLF4JLoggingServiceProvider.java | 8 - .../openecomp/sdc/logging/LogFileCreationTest.java | 55 ++---- .../sdc/logging/slf4j/SLF4JLoggerWrapperTest.java | 190 +++++++++++++++++++++ 10 files changed, 510 insertions(+), 176 deletions(-) create mode 100644 openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/main/java/org/openecomp/sdc/logging/api/StatusCode.java create mode 100644 openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/test/java/org/openecomp/sdc/logging/api/AuditDataTest.java delete mode 100644 openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/test/java/org/openecomp/sdc/logging/api/SpyAuditData.java create mode 100644 openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/src/test/java/org/openecomp/sdc/logging/slf4j/SLF4JLoggerWrapperTest.java diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/main/java/org/openecomp/sdc/logging/api/AuditData.java b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/main/java/org/openecomp/sdc/logging/api/AuditData.java index 7292762474..fdef45a57f 100644 --- a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/main/java/org/openecomp/sdc/logging/api/AuditData.java +++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-api/src/main/java/org/openecomp/sdc/logging/api/AuditData.java @@ -17,34 +17,186 @@ package org.openecomp.sdc.logging.api; /** - * @author KATYR + * Builder to populate audit data for logging according to + * calledMethods = new HashSet<>(); - - @Override - public long getStartTime() { - calledMethods.add("getStartTime"); - return 0; - } - - @Override - public long getEndTime() { - calledMethods.add("getEndTime"); - return 0; - } - - @Override - public AuditData.StatusCode getStatusCode() { - calledMethods.add("getEndTime"); - return null; - } - - @Override - public String getResponseCode() { - calledMethods.add("getResponseCode"); - return null; - } - - @Override - public String getResponseDescription() { - calledMethods.add("getResponseDescription"); - return null; - } - - @Override - public String getClientIpAddress() { - calledMethods.add("getClientIpAddress"); - return null; - } - - public boolean wasCalled(String method) { - return calledMethods.contains(method); - } -} diff --git a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/pom.xml b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/pom.xml index c6f2578129..2bbd0d2d01 100644 --- a/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/pom.xml +++ b/openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core/pom.xml @@ -22,6 +22,7 @@ org.aspectj aspectjrt ${aspectj.version} + provided org.slf4j @@ -32,11 +33,13 @@ ch.qos.logback logback-classic ${logback.version} + provided javax.servlet servlet-api ${servlet.version} + provided 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 Callable copyToCallable(Callable 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 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 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 -- cgit 1.2.3-korg