Improve logging

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

Hide file tree

Showing 10 changed files with 89 additions and 46 deletions.
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
@@ -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,15 +76,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
@@ -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/...-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/framework-tools-replay/standalone-ds.xml b/framework-tools-replay/standalone-ds.xml
@@ -64,32 +64,31 @@
     <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>
 
             <logger category="uk.gov.justice">
-                <level name="DEBUG"/>
+                <level name="TRACE"/>
             </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"/>

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
@@ -64,23 +64,22 @@
     <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="replay-wildfly-swarm.log"/>
                 <formatter>
-                    <named-formatter name="COLOR-PATTERN"/>
+                    <named-formatter name="PATTERN"/>
                 </formatter>
                 <append value="true"/>
             </file-handler>
 
             <logger category="uk.gov.justice">
-                <level name="DEBUG"/>
+                <level name="TRACE"/>
             </logger>
             <logger category="com.arjuna.ats.jta">
                 <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"/>

diff --git a/...ner/src/main/java/uk/gov/justice/framework/tools/listener/FrameworkToolsTestListener.java b/...ner/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) {