在spring配置文件中进行HTTP调用后，spring集成应用程序的日志中缺少correlationId

Question

在一个spring集成应用程序中，我试图使用log4j和MDC在日志中打印correlationId(我将在标题中获得"x- correlationId "="postman")。请找到下面的弹簧web过滤器，以拦截传入的请求头，并在整个事务的日志中打印它们

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>

一个变压器类

@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();
}

这就是我看到日志的方式。我看到在spring配置文件的第二次HTTP调用之后，我从日志语句中丢失了correlationId。我添加了日志语句，以便在每个通道执行后打印MDC contextMap。请帮助我了解为什么会发生这种情况，以及建议的解决方案。

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) – {}

Answer 1

MDC为线程绑定。你绝对不能在其他线程中看到它的状态。仔细查看日志:

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

http-nio-8080-exec-3和task-scheduler-1。因此，您确实使用了不同的、未连接的线程。因此，您可以在http-nio-8080-exec-3中看到MDC内容，这是CorrelationIDFilter的一部分，但您不会在httpGetRequests通道子流中看到它，因为这个在预定延迟后已经在不同的线程中启动。

或者不使用delayer，或者考虑实现线程状态转移功能。参见ThreadStatePropagationChannelInterceptor及其安全传播实现:https://docs.spring.io/spring-integration/docs/current/reference/html/security.html#security-context-propagation。

另一种方法是将您的关联id存储到消息头中，并在打印日志时从那里取出。