Spring Boot项目中logger.info仅输出6条日志的原因排查求助

先梳理下你的场景：项目基于Spring Boot框架，配置了logback滚动文件输出，但运行日志循环代码后，出现每条日志重复输出两次，且循环100次却只输出到i=5的情况。下面一步步分析原因和解决办法。

一、你的配置与代码情况 #

1. logback-spring.xml 配置 #

<appender name="defaultLogFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${system.log.path}/${appName}-default.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${system.log.path}/${appName}-default.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>10MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
        <maxHistory>10</maxHistory>
    </rollingPolicy>
    <append>true</append>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>%date [%thread] %-5level %logger{36} Method:%M Line:%L - %msg%n</pattern>
        <charset>UTF-8</charset>
    </encoder>
</appender>

2. 日志输出代码 #

for (int i = 0; i < 100; i++){
    logger.info("asdfasdfsadf i = {}", i);
    try {
        TimeUnit.SECONDS.sleep(2);
    } catch (Exception e) {
        System.out.println("dddddd");
    }
}

3. 实际输出结果（重复且仅到i=5） #

2018-05-16 09:18:16,164 [main] INFO c.x.********.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 0
2018-05-16 09:18:16.164 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 0
2018-05-16 09:18:18,169 [main] INFO c.x.*******.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 1
2018-05-16 09:18:18.169 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 1
2018-05-16 09:18:20,172 [main] INFO c.x.*******.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 2
2018-05-16 09:18:20.172 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 2
2018-05-16 09:18:22,176 [main] INFO c.x.*******.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 3
2018-05-16 09:18:22.176 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 3
2018-05-16 09:18:24,181 [main] INFO c.x.*******.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 4
2018-05-16 09:18:24.181 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 4
2018-05-16 09:18:26,184 [main] INFO c.x.*******.RecommendationTest Method:test Line:58 - asdfasdfsadf i = 5
2018-05-16 09:18:26.184 INFO 1399 --- [ main] com.*******.RecommendationTest : asdfasdfsadf i = 5

二、问题原因分析 #

1. 重复输出的核心原因 #

你看到的两行重复日志，来自两个不同的Logback Appender：

• 第一行是你自定义的defaultLogFile Appender输出（带有Method、Line号的格式）
• 第二行是Spring Boot默认绑定的ConsoleAppender输出（格式是Spring Boot自带的%date{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{36} : %msg%n）

本质是你的Logger同时被两个Appender处理了——要么是你给Root Logger同时添加了自定义Appender和ConsoleAppender，要么是自定义Logger继承了Root Logger的Appender配置，导致同一条日志被输出两次。

2. 仅输出6条日志的原因 #

循环100次却只输出到i=5，大概率是程序被提前终止了：

• 如果这是JUnit测试代码，JUnit默认会在测试方法执行后终止JVM，而循环100次需要200秒，可能你手动终止了测试，或者测试框架设置了超时时间（比如默认超时时间较短）
• 也可能存在未被正确捕获的异常导致程序崩溃，但你的catch块只打印了dddddd，无法确认是否有异常；不过从时间戳来看，每条日志间隔2秒，更倾向于程序被主动终止。

三、解决建议 #

针对重复输出问题 #

• 关闭Logger的继承性：在自定义Logger配置中添加additivity="false"，避免继承Root Logger的Appender：

  <logger name="com.*******.RecommendationTest" level="info" additivity="false">
      <appender-ref ref="defaultLogFile"/>
  </logger>
  

• 关闭Spring Boot默认控制台日志：在application.properties中添加配置：

  # 清空控制台日志格式，相当于关闭ConsoleAppender
  logging.pattern.console=
  

• 调整Root Logger配置：如果不需要ConsoleAppender，直接修改Root Logger的Appender引用，只保留你的自定义defaultLogFile。

针对仅输出6条日志问题 #

• 改用Main方法运行：如果是JUnit测试，把代码放到Main方法中运行，避免测试框架提前终止程序
• 调整JUnit超时时间：如果必须用JUnit，添加超时注解延长执行时间：

  @Test(timeout = 300000) // 设置5分钟超时
  public void test() {
      // 你的循环日志代码
  }
  

• 完善异常捕获：把catch块的打印改成日志输出，排查是否有异常：

  catch (Exception e) {
      logger.error("睡眠过程中出现异常", e);
  }
  

• 开启日志实时刷新：在自定义Appender中添加<immediateFlush>true</immediateFlush>，确保日志实时写入文件，避免缓冲导致的日志丢失：

  <appender name="defaultLogFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <!-- 其他配置 -->
      <immediateFlush>true</immediateFlush>
  </appender>
  

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