一个好几天都没有想明白的问题，日志乱序了

本文链接：https://blog.csdn.net/Lambert_Wang/article/details/113553244

本文记录了一次在生产环境中观察到的日志时序异常现象，即在同一线程中，接口调用入口日志出现在了两个内部方法日志之间。通过对Logback配置的详细检查，排除了日志框架配置不当的可能性。

摘要生成于 C知道，由 DeepSeek-R1 满血版支持，前往体验 >

今天发现一个非常奇怪的现象，这里记录下。

上面这张图是同一个实例的同一个线程打印的三行日志，按照时间从近到远排序。

17:30:09.687和17:30:09.672是同一个方法中的两行日志，但是17:30:09.676这条日志是接口调用的入口日志。

按照正常逻辑来讲，Netty在工作线程没有执行完成之前，不应该会再分配请求给该线程，这也不符合JAVA线程的底层逻辑。

所以中间17:30:09.676这条日志就很奇怪了。

为了确认是否有可能是日志打印出现乱序，对生产环境的日志配置文件排查了下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
    <property name="LOG_LEVEL" value="INFO"/>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="com.xiaohongshu.infra.utils.log.jsonlog.JSONEncodingPatternLayoutEncoder">
            <pattern>
                {
                "app":"insight",
                "prdline": "risk-insight",
                "remoteAddr": "%X{remoteAddr}",
                "timestamp": "%d{yyyy-MM-dd HH:mm:ss.SSS}",
                "logger": "%logger",
                "thread": "%thread",
                "level": "%level",
                "traceId": "%X{traceId}",
                "msg": "%msg",
                "stack_trace": "%exception %nopex"
                }%n
            </pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <neverBlock>true</neverBlock>
        <discardingThreshold>0</discardingThreshold>
        <queueSize>1024</queueSize>
        <appender-ref ref="STDOUT"/>
    </appender>

    <root level="${LOG_LEVEL}">
        <appender-ref ref="ASYNC"/>
    </root>
</configuration>

AsyncAppender内部使用了一个BlockingQueue用于缓存所有日志事件，再使用一个Work线程对象异步处理日志事件。

BlockingQueue是FIFO的，单个Work线程也不存在导致日志乱序的问题。

ConsoleAppender是OutputStreamAppender的具体实现，看起来也太可能导致日志乱序。

因此，应该不是logback框架导致日志时序错乱的问题。

问题先放这儿吧，等什么时候想明白了再来填这个坑。