Improve logging

CJSCommonPlatform · Jun 12, 2018 · e0fb6c6 · e0fb6c6
1 parent dbc321e
commit e0fb6c6
Show file tree

Hide file tree

Showing 14 changed files with 158 additions and 71 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -5,6 +5,10 @@ on [Keep a CHANGELOG](http://keepachangelog.com/). This project adheres to
 
 ## [Unreleased]
 
+## [4.3.4] - 2018-06-06
+### Changed
+- Improved logging to include streamId and event metadata in MDC
+
 ## [4.3.3] - 2018-06-06
 ### Fixed
 - Fix for replaying of events into custom event listeners

diff --git a/archive-loader-fraction/src/main/resources/log4j.properties b/archive-loader-fraction/src/main/resources/log4j.properties
diff --git a/...ols-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java b/...ols-replay/src/main/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcher.java
@@ -20,6 +20,9 @@ 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 +39,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 +60,8 @@ public UUID dispatch(final UUID streamId) {
 
         progressLogger.logCompletion(streamId);
 
+        loggingMdc.clear();
+
         return streamId;
     }
 
@@ -64,15 +73,25 @@ private void replayAllEventsOf(final UUID streamId) {
         }
     }
 
-    @TransactionAttribute(REQUIRED)
     private void replayBatchOfEvents(final UUID streamId, final long position) {
         try (final Stream<JsonEnvelope> eventStream = jsonEnvelopeJdbcRepository.pageEventStream(streamId, position, PAGE_SIZE)) {
             eventStream.forEach(jsonEnvelope -> dispatchEnvelope(jsonEnvelope, streamId));
         }
     }
 
     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
@@ -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/...work-tools-replay/src/main/java/uk/gov/justice/framework/tools/replay/ProgressLogger.java b/...work-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
diff --git a/...replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java b/...replay/src/test/java/uk/gov/justice/framework/tools/replay/AsyncStreamDispatcherTest.java
@@ -46,6 +46,9 @@ public class AsyncStreamDispatcherTest {
     @Mock
     private ProgressLogger progressLogger;
 
+    @Mock
+    private LoggingMdc loggingMdc;
+
     @InjectMocks
     private AsyncStreamDispatcher asyncStreamDispatcher;
 
@@ -67,17 +70,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/...y/src/test/java/uk/gov/justice/framework/tools/replay/JsonEnvelopeJdbcRepositoryTest.java b/...y/src/test/java/uk/gov/justice/framework/tools/replay/JsonEnvelopeJdbcRepositoryTest.java
@@ -1,45 +1,27 @@
 package uk.gov.justice.framework.tools.replay;
 
-import static java.util.Arrays.asList;
 import static java.util.UUID.fromString;
 import static java.util.UUID.randomUUID;
 import static java.util.stream.Collectors.toList;
-import static java.util.stream.Stream.of;
-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.junit.Assert.fail;
+import static org.mockito.Mockito.mock;
 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 static org.hamcrest.CoreMatchers.equalTo;
-import static org.hamcrest.CoreMatchers.is;
-import static org.junit.Assert.assertThat;
-import static org.mockito.Mockito.*;
-
-import uk.gov.justice.services.eventsourcing.repository.jdbc.event.Event;
-import uk.gov.justice.services.eventsourcing.repository.jdbc.event.EventConverter;
-import uk.gov.justice.services.eventsourcing.repository.jdbc.event.EventJdbcRepository;
 import uk.gov.justice.services.eventsourcing.source.core.EventSource;
 import uk.gov.justice.services.eventsourcing.source.core.EventStream;
 import uk.gov.justice.services.messaging.JsonEnvelope;
 
-import java.util.Arrays;
 import java.util.List;
 import java.util.UUID;
-import java.util.stream.Collectors;
 import java.util.stream.Stream;
 
-import javax.inject.Inject;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.mockito.InjectMocks;
+import org.mockito.Mock;
+import org.mockito.runners.MockitoJUnitRunner;
 
 
 @RunWith(MockitoJUnitRunner.class)

diff --git a/...work-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java b/...work-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/LoggingMdcTest.java
@@ -0,0 +1,65 @@
+package uk.gov.justice.framework.tools.replay;
+
+import static org.hamcrest.CoreMatchers.is;
+import static org.hamcrest.CoreMatchers.nullValue;
+import static org.junit.Assert.assertThat;
+
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.mockito.InjectMocks;
+import org.mockito.runners.MockitoJUnitRunner;
+import org.slf4j.MDC;
+
+
+@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/...-tools-replay/src/test/java/uk/gov/justice/framework/tools/replay/ProgressLoggerTest.java b/...-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/...s-replay/src/test/java/uk/gov/justice/framework/tools/replay/StreamStatusFactoryTest.java b/...s-replay/src/test/java/uk/gov/justice/framework/tools/replay/StreamStatusFactoryTest.java
@@ -14,7 +14,6 @@
 import uk.gov.justice.services.messaging.JsonEnvelope;
 import uk.gov.justice.services.messaging.MetadataBuilder;
 
-import java.util.List;
 import java.util.Optional;
 import java.util.UUID;
 

diff --git a/framework-tools-replay/standalone-ds.xml b/framework-tools-replay/standalone-ds.xml
@@ -64,17 +64,16 @@
     <profile>
         <subsystem xmlns="urn:jboss:domain:logging:3.0">
             <console-handler name="CONSOLE">
-                <level name="INFO"/>
                 <formatter>
-                    <named-formatter name="COLOR-PATTERN"/>
+                    <named-formatter name="PATTERN"/>
                 </formatter>
             </console-handler>
 
             <file-handler name="FILE" autoflush="true">
                 <encoding value="UTF-8"/>
-                <file relative-to="jboss.server.log.dir" path="integration-test-server.log"/>
+                <file relative-to="jboss.server.log.dir" path="replay-wildfly-swarm.log"/>
                 <formatter>
-                    <named-formatter name="COLOR-PATTERN"/>
+                    <named-formatter name="PATTERN"/>
                 </formatter>
                 <append value="true"/>
             </file-handler>
@@ -83,13 +82,13 @@
                 <level name="DEBUG"/>
             </logger>
             <logger category="com.arjuna.ats.jta">
-                <level name="INFO"/>
+                <level name="WARN"/>
             </logger>
             <logger category="org.jboss.as.jpa">
-                <level name="INFO"/>
+                <level name="WARN"/>
             </logger>
             <logger category="org.jboss">
-                <level name="WARN"/>
+                <level name="INFO"/>
             </logger>
             <logger category="sun.rmi">
                 <level name="WARN"/>
@@ -101,17 +100,14 @@
                 <level name="WARN"/>
             </logger>
             <root-logger>
-                <level name="DEBUG"/>
+                <level name="INFO"/>
                 <handlers>
                     <handler name="CONSOLE"/>
                     <handler name="FILE"/>
                 </handlers>
             </root-logger>
             <formatter name="PATTERN">
-                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
-            </formatter>
-            <formatter name="COLOR-PATTERN">
-                <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
+                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] %X{streamId} %X{eventData} %s%e%n"/>
             </formatter>
         </subsystem>
         <subsystem xmlns="urn:jboss:domain:bean-validation:1.0"/>