求助：Tomcat 9.0.71中Spring Boot自定义过滤器日志时间顺序颠倒

AI 小北

2026-6-21

日志时间顺序异常的可能原因分析

针对你遇到的同一请求下过滤器启动日志时间晚于结束日志的问题，结合Tomcat 9.0.71和Spring Boot的环境，常见原因如下：

异步日志框架的无序写入
如果应用使用了Logback/Log4j2等日志框架的异步Appender配置，日志事件会先进入缓冲区，再由后台线程批量写入文件。若请求处理过程中，结束日志的事件被后台线程优先处理写入，而启动日志的事件因缓冲区排队或线程调度延迟后写入，就会出现文件中日志顺序与代码执行顺序颠倒的情况。可以检查日志配置文件中是否开启了异步Appender，比如Logback的<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">。
系统时钟异常变动
请求处理过程中系统时钟被手动调整或NTP服务同步回拨，会导致日志时间戳不符合实际执行顺序。例如：过滤器先执行启动日志打印，但此时系统时钟被临时调快；执行完chain.doFilter(request, response)后，时钟被回拨到更早时间，再打印结束日志，最终就会出现启动日志时间晚于结束日志的情况。可以检查服务器时钟历史记录，确认是否存在时间跳变。

过滤器代码逻辑错误
排查自定义过滤器的代码结构，是否存在日志打印顺序颠倒的情况。比如错误地将结束日志放在chain.doFilter(request, response)之前执行，而启动日志放在finally块或方法末尾。正确的过滤器逻辑应该是：

@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
    // 启动日志（先执行）
    log.info("[{}] 过滤器启动", traceId);
    try {
        chain.doFilter(request, response);
    } finally {
        // 结束日志（后执行）
        log.info("[{}] 过滤器结束", traceId);
    }
}

若代码中日志位置写反，会直接导致时间顺序异常。

操作系统文件缓存延迟
catalina.out的写入依赖操作系统的文件缓存机制，当日志内容被写入缓存后，并非实时同步到磁盘。如果启动日志的缓存未及时刷盘，而结束日志的缓存因某种触发（如缓存满、线程结束）先被刷入磁盘，就会在文件中看到结束日志先出现的情况。可以尝试配置日志框架的即时刷盘参数（如Logback的immediateFlush="true"）来验证。
TraceId传递与线程上下文问题
虽然你确认日志属于同一traceId，但需排查traceId是否在异步线程中被重复使用，或者线程上下文（如MDC）在过滤器执行过程中被错误覆盖。比如某个异步任务复用了之前的traceId，导致两条日志看似属于同一请求，但实际是不同线程的操作，时间顺序自然混乱。可以结合线程ID（日志中添加%thread参数）来确认两条日志是否来自同一线程。

内容的提问来源于stack exchange，提问作者Owais Shahzad