Missing correlationId in logs in spring integration application after a HTTP call made in spring configuration file

Question

In one of the spring integration application, I am trying to print correlationId (which I will get in the headers as "x-correlation-id"="postman") in logs using log4j and MDC. Please find the below spring web filter to intercept the incoming request headers to print them in the logs through the entire transaction

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.UUID;

import static org.apache.logging.log4j.util.Strings.isBlank;

@Component
public class CorrelationIDFilter extends OncePerRequestFilter {
  private static final String CORRELATION_ID_HEADER_NAME = "x-correlation-id";
  private static final String CORRELATION_ID_LOG_VAR_NAME = "correlationId";

  @Override
  protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, FilterChain filterChain) throws ServletException, IOException {
    try {
      final String correlationId = getCorrelationIdFromHeader(httpServletRequest);
      MDC.put(CORRELATION_ID_LOG_VAR_NAME, correlationId);
      filterChain.doFilter(httpServletRequest, httpServletResponse);
    } finally {
      MDC.remove(CORRELATION_ID_LOG_VAR_NAME);
    }
  }

  private String getCorrelationIdFromHeader(final HttpServletRequest httpServletRequest) {
    String correlationId = httpServletRequest.getHeader(CORRELATION_ID_HEADER_NAME);
    if (isBlank(correlationId)) {
      correlationId = generateUniqueCorrelationId();
    }
    logger.info("correlationId :: " + correlationId);
    return correlationId;
  }

  private String generateUniqueCorrelationId() {
    return UUID.randomUUID().toString();
  }

  @Override
  public void destroy() {
    MDC.remove(CORRELATION_ID_LOG_VAR_NAME);
  }
}

spring-integration.xml

<int:annotation-config/>
<context:component-scan base-package="com.springintegration" />

<!-- Gateway -->
<int-http:inbound-gateway id="lpaGateway" request-channel="inboundGatewayRequests" supported-methods="POST" path="/api/v1/mdc" request-payload-type="java.lang.String" reply-timeout="300000" reply-channel="outboundGatewayResponses" error-channel="httpErrorChannel">
  <int-http:request-mapping consumes="application/xml" produces="application/xml" />
</int-http:inbound-gateway>

<int:transformer input-channel="inboundGatewayRequests" ref="springIntegrationMdcTransformer" method="buildRequestPayload" output-channel="httpPostRequests" />

<beans:bean id="headerMapper" class="org.springframework.integration.http.support.DefaultHttpHeaderMapper">
  <beans:property name="outboundHeaderNames" value="HTTP_REQUEST_HEADERS, Content-Type, Authorization" />
</beans:bean>

<!-- HTTP POST -->
<int:chain input-channel="httpPostRequests" output-channel="httpPostRsponses">
  <int:header-enricher>
    <int:header name="Content-Type" value="application/xml" />
    <int:header name="Authorization" expression="payload.getoAuthBean().getAccessToken()" />
  </int:header-enricher>
  <int:transformer expression="payload.getLpaRequest()" />
  <int-http:outbound-gateway id="lpaPostGateway" url="${post_endpoint}" http-method="POST" extract-request-payload="true" expected-response-type="java.lang.String" header-mapper="headerMapper">
  </int-http:outbound-gateway>
</int:chain>

<int:transformer input-channel="httpPostRsponses" ref="springIntegrationMdcTransformer" method="examinePostResponse" output-channel="getDelayer" />

<!-- Wait till polling frequency (in milliseconds) is met before invoking HTTP GET -->
<int:delayer id="delayer" input-channel="getDelayer" default-delay="0" expression="payload.getPollingFrequency()" output-channel="httpGetRequests" />

<!-- HTTP GET -->
<int:chain input-channel="httpGetRequests" output-channel="httpGetResponses">
  <int:header-enricher>
    <int:header name="Content-Type" value="application/xml" />
    <int:header name="Authorization" expression="payload.getoAuthBean().getAccessToken()" />
  </int:header-enricher>
  <int-http:outbound-gateway id="httpGetGateway" url-expression='"${get_endpoint}".concat("/").concat(payload.getReferenceID())' http-method="GET" expected-response-type="java.lang.String" header-mapper="headerMapper">
  </int-http:outbound-gateway>
</int:chain>

<!-- Examine LPA HTTP GET response -->
<int:transformer input-channel="httpGetResponses" ref="springIntegrationMdcTransformer" method="examineGetResponse" output-channel="outboundGatewayResponses" />

log4j2.xml

<Configuration status="WARN">
  <Properties>
    <Property name="CONVERSION_PATTERN">%sn %d{yyyy/MM/dd HH:mm:ss,SSS} %r [%-6p] [%t] [%X{correlationId}] %c{3} %C{3}.%M(%F:%L) – %m%n</Property>
  </Properties>
  <Loggers>
    <Root level="info}">
      <AppenderRef ref="SERVICE_ALL_FILE_APPENDER" />
    </Root>
    <Logger name="SERVICE_LOGGER" level="info" additivity="false">
      <AppenderRef ref="SERVICE_FILE_APPENDER" />
    </Logger>
  </Loggers>
  <Appenders>
    <Console name="CONSOLE_APPENDER" target="SYSTEM_OUT">
      <PatternLayout pattern="${CONVERSION_PATTERN}" />
    </Console>
    <RollingFile name="SERVICE_FILE_APPENDER" fileName="/logs/service_log.log" filePattern="/logs/service_log-%d{yyyy-MM-dd}-%i.log">
      <PatternLayout pattern="${CONVERSION_PATTERN}" />
    </RollingFile>
  </Appenders>
</Configuration>

A transformer class

@Component("springIntegrationMdcTransformer")
public class SpringIntegrationMDCTransformer {

  private static final Logger logger = getLogger("SERVICE_LOGGER");

  public Message < Object > buildRequestPayload(Message < String > inputRequest) {
    logger.info("buildRequestPayload");
    logger.info(MDC.getCopyOfContextMap());
    return withPayload((Object) inputRequest.getPayload())
      .copyHeadersIfAbsent(inputRequest.getHeaders())
      .build();
  }

  public Message < Object > examinePostResponse(Message < Object > channelMessage) {
    logger.info("examinePostResponse");
    logger.info(MDC.getCopyOfContextMap());
    return withPayload(channelMessage.getPayload())
      .copyHeadersIfAbsent(channelMessage.getHeaders())
      .build();
  }

  public Message < Object > examineGetResponse(Message < Object > channelMessage) {
    logger.info("examineGetResponse");
    logger.info(MDC.getCopyOfContextMap());
    return withPayload(channelMessage.getPayload())
      .copyHeadersIfAbsent(channelMessage.getHeaders())
      .build();
  }

This is how I am seeing the logs. I see after second HTTP call from the spring configuration file, I am missing correlationId from the log statements. I have added log statement to print MDC contextMap after each channel execution. Please help me understand why this is happening and the recommended solution for this.

915 2021/10/24 03:05:29,794 242390 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER springintegrationmdc.transformer.buildRequestPayload(SpringIntegrationMDCTransformer.java:18) – buildRequestPayload
917 2021/10/24 03:05:30,627 243223 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER core.service.SpringIntegrationMDCTransformer.checkCache(SpringIntegrationMDCTransformer.java:19) – {correlationId=postman}
916 2021/10/24 03:05:29,802 242398 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER core.service.SpringIntegrationMDCTransformer.checkCache(SpringIntegrationMDCTransformer.java:26) – examinePostResponse
917 2021/10/24 03:05:30,627 243223 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER core.service.SpringIntegrationMDCTransformer.checkCache(SpringIntegrationMDCTransformer.java:27) – {correlationId=postman}
992 2021/10/24 03:05:58,911 271507 [INFO  ] [task-scheduler-1] [] SERVICE_LOGGER core.transformer.LPATransformer.examineLPAGetResponse(SpringIntegrationMDCTransformer.java:34) – examineGetResponse
993 2021/10/24 03:05:59,954 272550 [INFO  ] [task-scheduler-1] [] SERVICE_LOGGER core.transformer.LPATransformer.examineLPAGetResponse(SpringIntegrationMDCTransformer.java:35) – {}

score 0 · Answer 1 · answered Oct 25 '21 at 13:14

The MDC is thread-bound. You definitely cannot see its state in the other thread. See your logs carefully:

916 2021/10/24 03:05:29,802 242398 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER core.service.SpringIntegrationMDCTransformer.checkCache(SpringIntegrationMDCTransformer.java:26) – examinePostResponse
917 2021/10/24 03:05:30,627 243223 [INFO  ] [http-nio-8080-exec-3] [postman] SERVICE_LOGGER core.service.SpringIntegrationMDCTransformer.checkCache(SpringIntegrationMDCTransformer.java:27) – {correlationId=postman}
992 2021/10/24 03:05:58,911 271507 [INFO  ] [task-scheduler-1] [] SERVICE_LOGGER core.transformer.LPATransformer.examineLPAGetResponse(SpringIntegrationMDCTransformer.java:34) – examineGetResponse

The http-nio-8080-exec-3 and task-scheduler-1. So, you indeed use different, not connected threads. Therefore you see MDC content in the http-nio-8080-exec-3 which is a part of your CorrelationIDFilter, but you don't see it in the httpGetRequests channel sub-flow since this one starts already in a different thread after scheduled delay.

Or don't use delayer, or think about implementing thread state transferring feature. See ThreadStatePropagationChannelInterceptor and its security propagation implementation: https://docs.spring.io/spring-integration/docs/current/reference/html/security.html#security-context-propagation.

Another way is to store your correlation id into message headers and take it from there when you print logs.

Missing correlationId in logs in spring integration application after a HTTP call made in spring configuration file

1 Answers1