Struts拦截器计算请求响应时间写入MDC后Log4j日志不显示求助

核心问题根源 #

你当前的拦截器逻辑存在两个关键问题：

1. MDC赋值时机滞后：在invocation.invoke()完成后才将processingTime放入MDC，但Action的业务逻辑、日志输出都在invoke()执行过程中完成，此时MDC中还没有耗时数据，JSON日志自然捕获不到。
2. 不必要的MDC上下文恢复：你在finally块中先恢复了invoke前的MDC上下文，这会覆盖Action执行过程中添加的其他MDC字段，既不符合业务逻辑，也会导致耗时字段的添加被干扰。

方案一：适配请求收尾日志（推荐） #

如果你的JSON日志是在请求生命周期末尾统一输出（比如全局过滤器、Struts2收尾逻辑中），只需调整拦截器逻辑即可：

import java.util.Map;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.MDC;
import com.opensymphony.xwork2.ActionInvocation;
import com.opensymphony.xwork2.interceptor.Interceptor;

public class RequestTimerInterceptor extends BaseInterceptor implements Interceptor {
    private static final long serialVersionUID = 1L;
    private static final ThreadLocal<Long> REQUEST_DURATION = new ThreadLocal<>();
    private static final String DURATION_KEY = "processingTime";

    @Override
    public String intercept(ActionInvocation invocation) throws Exception {
        long startTime = System.currentTimeMillis();
        String result;
        try {
            result = invocation.invoke();
        } finally {
            long processingTime = System.currentTimeMillis() - startTime;
            // 直接将耗时放入MDC，无需恢复原上下文（避免覆盖Action中新增的MDC字段）
            MDC.put(DURATION_KEY, Long.toString(processingTime));
            REQUEST_DURATION.set(processingTime);
            
            // 可选：若使用线程池，建议在请求完全结束后移除MDC字段，避免污染后续请求
            // 可在全局过滤器的finally块中执行 MDC.remove(DURATION_KEY);
        }
        return result;
    }
}

方案二：让Action内部日志也能获取耗时 #

如果希望Action执行过程中输出的日志也能带上最终请求耗时，由于耗时只有在请求结束时才能计算，需结合ThreadLocal+自定义Log4j转换器实现：

1. 修改拦截器，仅存储起始时间到ThreadLocal

import com.opensymphony.xwork2.ActionInvocation;
import com.opensymphony.xwork2.interceptor.Interceptor;

public class RequestTimerInterceptor extends BaseInterceptor implements Interceptor {
    private static final long serialVersionUID = 1L;
    private static final ThreadLocal<Long> START_TIME = new ThreadLocal<>();

    @Override
    public String intercept(ActionInvocation invocation) throws Exception {
        START_TIME.set(System.currentTimeMillis());
        String result;
        try {
            result = invocation.invoke();
        } finally {
            // 必须清理ThreadLocal，避免线程池复用导致内存泄漏
            START_TIME.remove();
        }
        return result;
    }

    // 提供静态方法给自定义转换器获取实时耗时
    public static long getProcessingTime() {
        Long startTime = START_TIME.get();
        return startTime != null ? System.currentTimeMillis() - startTime : -1;
    }
}

2. 自定义Log4j PatternConverter

import org.apache.log4j.pattern.LoggingEvent;
import org.apache.log4j.pattern.PatternConverter;

public class ProcessingTimeConverter extends PatternConverter {
    @Override
    protected String convert(LoggingEvent event) {
        long processingTime = RequestTimerInterceptor.getProcessingTime();
        return processingTime >= 0 ? String.valueOf(processingTime) : "N/A";
    }
}

3. 配置Log4j启用自定义转换器

在Log4j的properties配置文件中注册转换器并使用：

# 注册自定义转换器
log4j.pattern.converter.processingTime=com.yourpackage.ProcessingTimeConverter

# 在JSON布局中引用转换器
log4j.appender.json.layout.ConversionPattern={"timestamp": "%d", "processingTime": "%processingTime", "message": "%m"}

额外注意事项 #

• 确保拦截器在Struts2拦截器栈中的顺序：必须放在所有业务拦截器之前，保证起始时间能被正确记录。
• 异步日志场景：如果使用Log4j异步Appender，需开启MDC复制功能，避免线程切换导致MDC数据丢失。
• ThreadLocal清理：务必在finally块中移除ThreadLocal中的数据，防止线程池复用引发的内存泄漏或数据污染。

内容的提问来源于stack exchange，提问作者Setareh Mokhtari