From 3c70622ea8d9144aaffa0bb498e696e13094415b Mon Sep 17 00:00:00 2001 From: amckenzie Date: Tue, 12 Jun 2018 15:15:39 +0100 Subject: [PATCH] Improve logging --- .../src/main/resources/log4j.properties | 7 -- .../tools/replay/AsyncStreamDispatcher.java | 24 +++++- .../framework/tools/replay/LoggingMdc.java | 18 +++++ .../tools/replay/ProgressLogger.java | 4 + .../src/main/resources/log4j.properties | 14 ---- .../replay/AsyncStreamDispatcherTest.java | 22 +++++- .../tools/replay/LoggingMdcTest.java | 78 +++++++++++++++++++ .../tools/replay/ProgressLoggerTest.java | 8 ++ framework-tools-replay/standalone-ds.xml | 22 +++--- .../src/test/resources/standalone-ds.xml | 14 ++-- .../listener/FrameworkToolsTestListener.java | 2 +- 11 files changed, 167 insertions(+), 46 deletions(-) delete mode 100644 archive-loader-fraction/src/main/resources/log4j.properties create mode 100644 framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/LoggingMdc.java delete mode 100644 framework-tools-replay/src/main/resources/log4j.properties create mode 100644 framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java diff --git a/archive-loader-fraction/src/main/resources/log4j.properties b/archive-loader-fraction/src/main/resources/log4j.properties deleted file mode 100644 index e9b2392..0000000 --- a/archive-loader-fraction/src/main/resources/log4j.properties +++ /dev/null @@ -1,7 +0,0 @@ -# Set root logger level to DEBUG and its only appender to A1. -log4j.rootLogger=INFO, A1 -# A1 is set to be a ConsoleAppender. -log4j.appender.A1=org.apache.log4j.ConsoleAppender -# A1 uses PatternLayout. -log4j.appender.A1.layout=org.apache.log4j.PatternLayout -log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n \ No newline at end of file diff --git a/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java index b582ace..15f5172 100644 --- a/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java +++ b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java @@ -15,11 +15,17 @@ import javax.ejb.TransactionAttribute; import javax.inject.Inject; +import org.slf4j.Logger; +import org.slf4j.MDC; + @Stateless public class AsyncStreamDispatcher { private static final int PAGE_SIZE = 1000; private static final long FIRST_POSITION = 1L; + + private static final String STREAM_ID_MDC_KEY = "streamId"; + private static final String EVENT_DATA_MDC_KEY = "eventData"; @Inject private TransactionalEnvelopeDispatcher envelopeDispatcher; @@ -36,9 +42,13 @@ public class AsyncStreamDispatcher { @Inject private ProgressLogger progressLogger; + @Inject + private LoggingMdc loggingMdc; + @TransactionAttribute(NOT_SUPPORTED) public UUID dispatch(final UUID streamId) { + loggingMdc.put(STREAM_ID_MDC_KEY, "streamId: " + streamId); progressLogger.logStart(streamId); try { @@ -53,6 +63,8 @@ public UUID dispatch(final UUID streamId) { progressLogger.logCompletion(streamId); + loggingMdc.clear(); + return streamId; } @@ -64,7 +76,6 @@ private void replayAllEventsOf(final UUID streamId) { } } - @TransactionAttribute(REQUIRED) private void replayBatchOfEvents(final UUID streamId, final long position) { try (final Stream eventStream = jsonEnvelopeJdbcRepository.pageEventStream(streamId, position, PAGE_SIZE)) { eventStream.forEach(jsonEnvelope -> dispatchEnvelope(jsonEnvelope, streamId)); @@ -72,7 +83,18 @@ private void replayBatchOfEvents(final UUID streamId, final long position) { } private void dispatchEnvelope(final JsonEnvelope jsonEnvelope, final UUID streamId) { + + loggingMdc.put(EVENT_DATA_MDC_KEY, "event: " + jsonEnvelope.toString()); + + doDispatch(jsonEnvelope, streamId); + + loggingMdc.remove(EVENT_DATA_MDC_KEY); + } + + @TransactionAttribute(REQUIRED) + private void doDispatch(final JsonEnvelope jsonEnvelope, final UUID streamId) { try { + progressLogger.logDispatch(); envelopeDispatcher.dispatch(jsonEnvelope); progressLogger.logSuccess(streamId, jsonEnvelope); } catch (final MissingHandlerException ex) { diff --git a/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/LoggingMdc.java b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/LoggingMdc.java new file mode 100644 index 0000000..595c4d9 --- /dev/null +++ b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/LoggingMdc.java @@ -0,0 +1,18 @@ +package uk.gov.justice.framework.tools.replay; + +import org.slf4j.MDC; + +public class LoggingMdc { + + public void put(final String key, final String value) { + MDC.put(key, value); + } + + public void remove(final String key) { + MDC.remove(key); + } + + public void clear() { + MDC.clear(); + } +} diff --git a/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/ProgressLogger.java b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/ProgressLogger.java index e700d54..99b0a93 100644 --- a/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/ProgressLogger.java +++ b/framework-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/ProgressLogger.java @@ -26,6 +26,10 @@ public void logStart(final UUID streamId) { logger.info("Starting processing of stream: {}", streamId); } + public void logDispatch() { + logger.info("Dispatching event"); + } + public void logSuccess(final UUID streamId, final JsonEnvelope jsonEnvelope) { sucessCount++; diff --git a/framework-tools-replay/src/main/resources/log4j.properties b/framework-tools-replay/src/main/resources/log4j.properties deleted file mode 100644 index 0f1c3db..0000000 --- a/framework-tools-replay/src/main/resources/log4j.properties +++ /dev/null @@ -1,14 +0,0 @@ -# Set root logger level to DEBUG and its only appender to CONSOLE. -log4j.rootLogger=INFO, CONSOLE -log4j.logger.org.hibernate=WARN, CONSOLE -log4j.logger.uk.gov.justice=DEBUG, CONSOLE - -# CONSOLE is set to be a ConsoleAppender. -log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender -# CONSOLE uses PatternLayout. -log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout -log4j.appender.CONSOLE.layout.ConversionPattern=%d{dd MMM yyyy HH:mm:ss} %-5p: %c %x - %m%n - - - - diff --git a/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java index 69526c8..d8684cc 100644 --- a/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java +++ b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java @@ -19,6 +19,9 @@ import java.util.UUID; import java.util.stream.Stream; +import javax.inject.Inject; + +import org.junit.Ignore; import org.junit.Test; import org.junit.runner.RunWith; import org.mockito.InOrder; @@ -46,6 +49,9 @@ public class AsyncStreamDispatcherTest { @Mock private ProgressLogger progressLogger; + @Mock + private LoggingMdc loggingMdc; + @InjectMocks private AsyncStreamDispatcher asyncStreamDispatcher; @@ -67,17 +73,31 @@ public void shouldGetTheEventsOfAStreamDispatchThemAllThenUpdateTheStreamStatus( assertThat(asyncStreamDispatcher.dispatch(streamId), is(streamId)); - final InOrder inOrder = inOrder(progressLogger, envelopeDispatcher, streamStatusRepository, progressLogger); + final InOrder inOrder = inOrder(loggingMdc, progressLogger, envelopeDispatcher, streamStatusRepository, progressLogger); + inOrder.verify(loggingMdc).put("streamId", "streamId: " + streamId); inOrder.verify(progressLogger).logStart(streamId); + inOrder.verify(loggingMdc).put("eventData", "event: " + jsonEnvelope_1.toString()); + inOrder.verify(progressLogger).logDispatch(); inOrder.verify(envelopeDispatcher).dispatch(jsonEnvelope_1); inOrder.verify(progressLogger).logSuccess(streamId, jsonEnvelope_1); + inOrder.verify(loggingMdc).remove("eventData"); + + inOrder.verify(loggingMdc).put("eventData", "event: " + jsonEnvelope_2.toString()); + inOrder.verify(progressLogger).logDispatch(); inOrder.verify(envelopeDispatcher).dispatch(jsonEnvelope_2); inOrder.verify(progressLogger).logSuccess(streamId, jsonEnvelope_2); + inOrder.verify(loggingMdc).remove("eventData"); + + inOrder.verify(loggingMdc).put("eventData", "event: " + jsonEnvelope_3.toString()); + inOrder.verify(progressLogger).logDispatch(); inOrder.verify(envelopeDispatcher).dispatch(jsonEnvelope_3); inOrder.verify(progressLogger).logSuccess(streamId, jsonEnvelope_3); + inOrder.verify(loggingMdc).remove("eventData"); + inOrder.verify(streamStatusRepository).insert(streamStatus); inOrder.verify(progressLogger).logCompletion(streamId); + inOrder.verify(loggingMdc).clear(); } @Test diff --git a/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java new file mode 100644 index 0000000..ede444b --- /dev/null +++ b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java @@ -0,0 +1,78 @@ +package uk.gov.justice.framework.tools.replay; + +import static org.hamcrest.CoreMatchers.nullValue; +import static org.junit.Assert.*; + +import org.junit.runner.RunWith; +import org.mockito.runners.MockitoJUnitRunner; + +import static org.hamcrest.CoreMatchers.is; +import static org.hamcrest.CoreMatchers.sameInstance; +import static org.junit.Assert.assertThat; +import static org.mockito.Mockito.when; + +import org.junit.Test; +import org.junit.runner.RunWith; +import org.mockito.InjectMocks; +import org.mockito.Mock; +import org.mockito.runners.MockitoJUnitRunner; +import org.slf4j.MDC; + +import static org.hamcrest.CoreMatchers.equalTo; +import static org.hamcrest.CoreMatchers.is; +import static org.junit.Assert.assertThat; +import static org.mockito.Mockito.*; + + +@RunWith(MockitoJUnitRunner.class) +public class LoggingMdcTest { + + + @InjectMocks + private LoggingMdc loggingMdc; + + @Test + public void shouldWrapTheMdcStaticCall() throws Exception { + + final String key_1 = "key_1"; + final String value_1 = "value_1"; + final String key_2 = "key_2"; + final String value_2 = "value_2"; + + loggingMdc.put(key_1, value_1); + loggingMdc.put(key_2, value_2); + + assertThat(MDC.get(key_1), is(value_1)); + assertThat(MDC.get(key_2), is(value_2)); + + loggingMdc.remove(key_1); + + assertThat(MDC.get(key_1), is(nullValue())); + assertThat(MDC.get(key_2), is(value_2)); + + loggingMdc.remove(key_2); + + assertThat(MDC.get(key_1), is(nullValue())); + assertThat(MDC.get(key_2), is(nullValue())); + } + + @Test + public void shouldClearTheMdc() throws Exception { + + final String key_1 = "key_1"; + final String value_1 = "value_1"; + final String key_2 = "key_2"; + final String value_2 = "value_2"; + + loggingMdc.put(key_1, value_1); + loggingMdc.put(key_2, value_2); + + assertThat(MDC.get(key_1), is(value_1)); + assertThat(MDC.get(key_2), is(value_2)); + + loggingMdc.clear(); + + assertThat(MDC.get(key_1), is(nullValue())); + assertThat(MDC.get(key_2), is(nullValue())); + } +} diff --git a/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/ProgressLoggerTest.java b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/ProgressLoggerTest.java index 86ec83e..19a376a 100644 --- a/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/ProgressLoggerTest.java +++ b/framework-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/ProgressLoggerTest.java @@ -45,6 +45,14 @@ public void shouldLogTheStartOfTheProcess() throws Exception { verify(logger).info("Starting processing of stream: {}", streamId); } + @Test + public void shouldLogTheDispatchOfAnEvent() throws Exception { + + progressLogger.logDispatch(); + + verify(logger).info("Dispatching event"); + } + @Test public void shouldLogSuccessOnlyIfTheProgressCheckerAllowsIt() throws Exception { diff --git a/framework-tools-replay/standalone-ds.xml b/framework-tools-replay/standalone-ds.xml index 230170e..63289fa 100644 --- a/framework-tools-replay/standalone-ds.xml +++ b/framework-tools-replay/standalone-ds.xml @@ -64,32 +64,31 @@ - - + - + - + - + - + - + - + @@ -101,17 +100,14 @@ - + - - - - + diff --git a/replay-tool-test/replay-tool-integration-test/src/test/resources/standalone-ds.xml b/replay-tool-test/replay-tool-integration-test/src/test/resources/standalone-ds.xml index 65866dd..f3e4a3f 100644 --- a/replay-tool-test/replay-tool-integration-test/src/test/resources/standalone-ds.xml +++ b/replay-tool-test/replay-tool-integration-test/src/test/resources/standalone-ds.xml @@ -64,9 +64,8 @@ - - + @@ -74,13 +73,13 @@ - + - + @@ -101,17 +100,14 @@ - + - - - - + diff --git a/replay-tool-test/replay-tool-it-example-listener/src/main/java/uk/gov/justice/framework/tools/listener/FrameworkToolsTestListener.java b/replay-tool-test/replay-tool-it-example-listener/src/main/java/uk/gov/justice/framework/tools/listener/FrameworkToolsTestListener.java index 899044b..0442142 100644 --- a/replay-tool-test/replay-tool-it-example-listener/src/main/java/uk/gov/justice/framework/tools/listener/FrameworkToolsTestListener.java +++ b/replay-tool-test/replay-tool-it-example-listener/src/main/java/uk/gov/justice/framework/tools/listener/FrameworkToolsTestListener.java @@ -31,8 +31,8 @@ public class FrameworkToolsTestListener { @Handles("framework.update-user") public void handle(final JsonEnvelope envelope) { - logger.debug("Replaying event: " + envelope); testViewstoreRepository.save(fromJsonEnvelope(envelope)); + logger.debug("Event saved"); } private User fromJsonEnvelope(final JsonEnvelope envelope) {