diff options
Diffstat (limited to 'openecomp-be/lib/openecomp-sdc-logging-lib/openecomp-sdc-logging-core')
5 files changed, 252 insertions, 93 deletions
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 @@ <groupId>org.aspectj</groupId> <artifactId>aspectjrt</artifactId> <version>${aspectj.version}</version> + <scope>provided</scope> </dependency> <dependency> <groupId>org.slf4j</groupId> @@ -32,11 +33,13 @@ <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>${logback.version}</version> + <scope>provided</scope> </dependency> <dependency> <groupId>javax.servlet</groupId> <artifactId>servlet-api</artifactId> <version>${servlet.version}</version> + <scope>provided</scope> </dependency> <!-- for testing --> 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 |