继承OncePerRequestFilter的Filter导致日志出现null行的原因排查

新增了一个继承自OncePerRequestFilter的Filter类后，每次调用API时，正常日志语句之间会出现大量null行。以下是日志示例及Logback配置：

日志示例 #

{"@timestamp":"2022-09-15T18:21:19.295+05:30","@version":"1","message":"Started Application in 20.694 seconds (JVM running for 21.915)","logger_name":"logger-name","thread_name":"main","level":"INFO","level_value":20000,"app":"app-name"}
null
null
null
null
null
null
null
null
null
null
null
{"@timestamp":"2022-09-15T18:21:31.655+05:30","@version":"1","message":"Received request from app swagger-ui","logger_name":"logger-name","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"clientIp":"0:0:0:0:0:0:0:1","serviceName":"client-name","transactionId":"CBC76C0E4A8B4C4798599AEC3C91DD3B","app":"app-name"}

Logback 配置 #

<configuration>

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <customFields>{"app":"app-name"}</customFields>
    </encoder>
</appender>

<appender name="appLogAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <providers>
            <timestamp/>
            <threadName/>
            <provider class="net.logstash.logback.composite.loggingevent.ArgumentsJsonProvider"/>
        </providers>
    </encoder>
</appender>

<logger name="console-logger" level="INFO" additivity="false">
    <appender-ref ref="CONSOLE"/>
</logger>

<logger name="applicationLog" level="INFO" additivity="false">
    <appender-ref ref="appLogAppender"/>
</logger>

<root level="ERROR">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="appLogAppender"/>
</root>
</configuration>

问题原因分析 #

1. appLogAppender编码器配置缺失核心字段：该Appender使用LoggingEventCompositeJsonEncoder，但仅配置了timestamp、threadName和ArgumentsJsonProvider。当Filter触发的日志事件没有传入参数时，ArgumentsJsonProvider会输出null，且没有其他核心字段（如message、logger名称）的Provider兜底，最终整个日志条目就只会输出null。
2. Root日志器的重复输出：Root日志器同时关联了CONSOLE和appLogAppender，如果Filter中使用的日志器匹配了Root规则，就会触发appLogAppender输出无效的null行。
3. Filter日志代码可能存在问题：如果Filter中错误地输出了null内容，或者日志方法调用时传入了null参数，也会直接产生null行，但结合配置来看，编码器配置缺陷是主要原因。

解决方案 #

方案1：修复appLogAppender的编码器配置 #

补充必要的日志字段Provider，确保即使没有日志参数，也能输出完整的JSON内容：

<appender name="appLogAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <providers>
            <timestamp/>
            <threadName/>
            <message/> <!-- 新增日志消息字段 -->
            <loggerName/> <!-- 新增日志器名称字段 -->
            <level/> <!-- 新增日志级别字段 -->
            <arguments/> <!-- 简化ArgumentsJsonProvider的配置标签 -->
            <customFields>{"app":"app-name"}</customFields> <!-- 统一自定义字段 -->
        </providers>
    </encoder>
</appender>

方案2：调整Root日志器的Appender关联 #

如果appLogAppender仅用于applicationLog日志器，可移除Root日志器对它的关联，避免无效输出：

<root level="ERROR">
    <appender-ref ref="CONSOLE"/>
    <!-- 移除appLogAppender，仅保留CONSOLE输出错误日志 -->
</root>

方案3：检查Filter中的日志代码 #

确认Filter使用的日志器是否正确（比如指定console-logger或applicationLog，避免默认使用Root），同时确保日志方法调用时没有传入null内容：

// 错误示例
logger.info(null);
// 正确示例
logger.info("Filter processed request from IP: {}", request.getRemoteAddr());

内容的提问来源于stack exchange，提问作者Deepak Singh