feature: add X-Correlation-Id to tracing filter (#129)

* feature: add X-Correlation-Id to tracing filter

* feature: add X-Correlation-Id to tracing filter

* feature: config logback.xml to put exception at the end

* feature: config logback.xml to put exception at the end

* feature: config logback.xml to put exception at the end

---------

Co-authored-by: Duncan Crawford <duncan.crawford@hmcts.net>

Author: coling01

src/main/java/uk/gov/hmcts/cp/filters/tracing/TracingFilter.java

@@ -1,52 +1,49 @@
 package uk.gov.hmcts.cp.filters.tracing;
 
+import jakarta.annotation.Nonnull;
 import jakarta.servlet.FilterChain;
 import jakarta.servlet.ServletException;
 import jakarta.servlet.http.HttpServletRequest;
 import jakarta.servlet.http.HttpServletResponse;
 import lombok.extern.slf4j.Slf4j;
-import org.owasp.encoder.Encode;
 import org.slf4j.MDC;
-import org.springframework.beans.factory.annotation.Value;
+import org.springframework.core.Ordered;
+import org.springframework.core.annotation.Order;
 import org.springframework.stereotype.Component;
 import org.springframework.web.filter.OncePerRequestFilter;
 
 import java.io.IOException;
+import java.util.UUID;
 
 @Component
+@Order(Ordered.HIGHEST_PRECEDENCE)
 @Slf4j
 public class TracingFilter extends OncePerRequestFilter {
 
-    public static final String TRACE_ID = "traceId";
-    public static final String SPAN_ID = "spanId";
-    public static final String APPLICATION_NAME = "applicationName";
+    public static final String CORRELATION_ID_KEY = "X-Correlation-Id";
 
-    private final String applicationName;
-
-    public TracingFilter(@Value("${spring.application.name}") final String applicationName) {
-        this.applicationName = applicationName;
+    @Override
+    protected boolean shouldNotFilter(@Nonnull final HttpServletRequest request) {
+        return false;
     }
 
     @Override
-    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response, final FilterChain filterChain) throws ServletException, IOException {
+    protected void doFilterInternal(@Nonnull final HttpServletRequest request,
+                                    @Nonnull final HttpServletResponse response,
+                                    @Nonnull final FilterChain filterChain) throws ServletException, IOException {
         try {
-            populateMDC(request, response, filterChain);
+            final String correlationId = getCorrelationId(request);
+            MDC.put(CORRELATION_ID_KEY, getCorrelationId(request));
+            response.setHeader(CORRELATION_ID_KEY, correlationId);
+            filterChain.doFilter(request, response);
         } finally {
-            MDC.clear();
+            MDC.remove(CORRELATION_ID_KEY);
         }
     }
 
-    public void populateMDC(final HttpServletRequest request, final HttpServletResponse response, final FilterChain filterChain) throws IOException, ServletException {
-        log.info("TracingFilter for uri:{}", Encode.forJava(request.getRequestURI()));
-        MDC.put(APPLICATION_NAME, applicationName);
-        if (request.getHeader(TRACE_ID) != null) {
-            MDC.put(TRACE_ID, request.getHeader(TRACE_ID));
-            response.setHeader(TRACE_ID, request.getHeader(TRACE_ID));
-        }
-        if (request.getHeader(SPAN_ID) != null) {
-            MDC.put(SPAN_ID, request.getHeader(SPAN_ID));
-            response.setHeader(SPAN_ID, request.getHeader(SPAN_ID));
-        }
-        filterChain.doFilter(request, response);
+    private String getCorrelationId(final HttpServletRequest request) {
+        return request.getHeader(CORRELATION_ID_KEY) == null
+                ? UUID.randomUUID().toString()
+                : request.getHeader(CORRELATION_ID_KEY);
     }
 }

src/main/resources/logback.xml

@@ -2,21 +2,23 @@
     <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
         <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
             <providers>
+                <mdc/>
                 <timestamp>
                     <fieldName>timestamp</fieldName>
                     <pattern>yyyy-MM-dd' 'HH:mm:ss.SSS</pattern>
                 </timestamp>
                 <!-- Lets keep the message to the left so its easier to find without scrolling -->
-                <pattern>
-                    <pattern>{"message": "%message%n%xException{full}"}</pattern>
-                </pattern>
-                <mdc/>
+                <message/>
                 <loggerName/>
                 <threadName/>
                 <logLevel/>
+                <pattern>
+                    <pattern>{"exception": "%xException{full}"}</pattern>
+                </pattern>
             </providers>
         </encoder>
     </appender>
+
     <root level="INFO">
         <appender-ref ref="JSON"/>
     </root>

src/test/java/uk/gov/hmcts/cp/filters/tracing/TracingFilterTest.java

@@ -4,43 +4,63 @@
 import jakarta.servlet.ServletException;
 import jakarta.servlet.http.HttpServletRequest;
 import jakarta.servlet.http.HttpServletResponse;
+import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.ExtendWith;
 import org.mockito.Mock;
 import org.mockito.junit.jupiter.MockitoExtension;
 import org.slf4j.MDC;
 
 import java.io.IOException;
+import java.util.UUID;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.mockito.ArgumentMatchers.anyString;
+import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
-import static uk.gov.hmcts.cp.filters.tracing.TracingFilter.APPLICATION_NAME;
-import static uk.gov.hmcts.cp.filters.tracing.TracingFilter.SPAN_ID;
-import static uk.gov.hmcts.cp.filters.tracing.TracingFilter.TRACE_ID;
 
 @ExtendWith(MockitoExtension.class)
 class TracingFilterTest {
+
     @Mock
     private HttpServletRequest request;
     @Mock
     private HttpServletResponse response;
     @Mock
     private FilterChain filterChain;
 
-    private final TracingFilter tracingFilter = new TracingFilter("myAppName");
+    private final TracingFilter filter = new TracingFilter();
+
+    @AfterEach
+    void tearDown() {
+        MDC.clear();
+    }
+
+    @Test
+    void shouldAlwaysFilter_all_paths() {
+        assertThat(filter.shouldNotFilter(request)).isFalse();
+    }
+
+    @Test
+    void doFilterInternal_puts_correlationId_in_MDC_and_response_when_header_present() throws ServletException, IOException {
+        final String correlationId = UUID.randomUUID().toString();
+        when(request.getHeader(TracingFilter.CORRELATION_ID_KEY)).thenReturn(correlationId);
+
+        filter.doFilterInternal(request, response, filterChain);
+
+        verify(response).setHeader(TracingFilter.CORRELATION_ID_KEY, correlationId);
+        verify(filterChain).doFilter(request, response);
+        assertThat(MDC.get(TracingFilter.CORRELATION_ID_KEY)).isNull();
+    }
 
     @Test
-    void filter_should_use_incoming_traceId() throws ServletException, IOException {
-        when(request.getHeader(TRACE_ID)).thenReturn("incoming-traceId");
-        when(request.getHeader(SPAN_ID)).thenReturn("incoming-spanId");
+    void doFilterInternal_generates_correlationId_when_header_absent() throws ServletException, IOException {
+        when(request.getHeader(TracingFilter.CORRELATION_ID_KEY)).thenReturn(null);
 
-        tracingFilter.populateMDC(request, response, filterChain);
+        filter.doFilterInternal(request, response, filterChain);
 
-        assertThat(MDC.get(APPLICATION_NAME)).isEqualTo("myAppName");
-        verify(response).setHeader(TRACE_ID, "incoming-traceId");
-        assertThat(MDC.get(TRACE_ID)).isEqualTo("incoming-traceId");
-        verify(response).setHeader(SPAN_ID, "incoming-spanId");
-        assertThat(MDC.get(SPAN_ID)).isEqualTo("incoming-spanId");
+        verify(response).setHeader(eq(TracingFilter.CORRELATION_ID_KEY), anyString());
+        verify(filterChain).doFilter(request, response);
     }
-}
+}

src/test/java/uk/gov/hmcts/cp/integration/SpringLoggingIntegrationTest.java

@@ -1,53 +1,62 @@
 package uk.gov.hmcts.cp.integration;
 
-import ch.qos.logback.classic.AsyncAppender;
 import com.fasterxml.jackson.core.type.TypeReference;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import lombok.extern.slf4j.Slf4j;
-import org.assertj.core.api.AssertionsForClassTypes;
 import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.Test;
-import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
 
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
 import java.io.PrintStream;
+import java.nio.charset.StandardCharsets;
 import java.util.Map;
+import java.util.UUID;
 
 import static org.assertj.core.api.Assertions.assertThat;
+import static uk.gov.hmcts.cp.filters.tracing.TracingFilter.CORRELATION_ID_KEY;
 
 @Slf4j
 class SpringLoggingIntegrationTest extends IntegrationTestBase {
-    private PrintStream originalStdOut = System.out;
+
+    private final PrintStream originalStdOut = System.out;
 
     @AfterEach
     void afterEach() {
         System.setOut(originalStdOut);
     }
 
+    UUID correlationId = UUID.randomUUID();
+
     @Test
-    void springboot_test_should_log_correct_fields_including_exception() throws IOException {
-        MDC.put("any-mdc-field", "1234-1234");
-        ByteArrayOutputStream capturedStdOut = captureStdOut();
-        log.info("spring boot test message", new RuntimeException("MyException"));
-
-        String logMessage = capturedStdOut.toString();
-        AssertionsForClassTypes.assertThat(logMessage).isNotEmpty();
-        Map<String, Object> capturedFields = new ObjectMapper().readValue(logMessage, new TypeReference<>() {
-        });
-        assertThat(capturedFields.get("any-mdc-field")).isEqualTo("1234-1234");
+    void springboot_test_should_log_correct_fields() throws IOException {
+        MDC.put(CORRELATION_ID_KEY, correlationId.toString());
+        final ByteArrayOutputStream capturedStdOut = captureStdOut();
+        log.info("spring boot test message", new RuntimeException("TestException"));
+
+        final String logMessage = capturedStdOut.toString(StandardCharsets.UTF_8);
+        assertThat(logMessage).isNotEmpty();
+
+        final Map<String, Object> capturedFields =
+                new ObjectMapper().readValue(logMessage, new TypeReference<>() {
+                });
+
+        assertThat(capturedFields.get(CORRELATION_ID_KEY)).isEqualTo(correlationId.toString());
         assertThat(capturedFields.get("timestamp")).isNotNull();
-        assertThat(capturedFields.get("logger_name")).isEqualTo("uk.gov.hmcts.cp.integration.SpringLoggingIntegrationTest");
+        assertThat(capturedFields.get("message").toString()).contains("spring boot test message");
+        assertThat(capturedFields.get("exception").toString())
+                .contains("java.lang.RuntimeException: TestException")
+                .contains("cp.integration.SpringLoggingIntegrationTest");
+        assertThat(capturedFields.get("logger_name"))
+                .isEqualTo("uk.gov.hmcts.cp.integration.SpringLoggingIntegrationTest");
         assertThat(capturedFields.get("thread_name")).isEqualTo("Test worker");
         assertThat(capturedFields.get("level")).isEqualTo("INFO");
-        assertThat(capturedFields.get("message").toString()).contains("spring boot test message\njava.lang.RuntimeException: MyException");
-        assertThat(capturedFields.get("message").toString()).contains("at uk.gov.hmcts.cp.integration.SpringLoggingIntegrationTest");
     }
 
     private ByteArrayOutputStream captureStdOut() {
         final ByteArrayOutputStream capturedStdOut = new ByteArrayOutputStream();
-        System.setOut(new PrintStream(capturedStdOut));
+        System.setOut(new PrintStream(capturedStdOut, true, StandardCharsets.UTF_8));
         return capturedStdOut;
     }
 }