解决spring boot logging在两个目录生成日志文件且max-history不生效

解决spring boot logging在两个目录生成日志文件且max-history不生效

背景

• 使用spring boot 2.1.6-RELEASE
• 使用默认的spring-boot-starter-logging (logback 1.2.3)作为日志记录组件
• classpath配置了logback.xml文件，内容如下：

  <?xml version="1.0" encoding="UTF-8"?>
  <configuration scan="true" scanPeriod="60 seconds" debug="false">
      <!-- 定义log文件的目录 -->
      <property name="logHome" value="/var/log/classpath/"/>
      <property name="maxHistory" value="7"/>
      <property name="maxFileSize" value="10MB"/>
      <property name="totalSizeCap" value="200MB"/>
      <property name="minIndexNum" value="1"/>
      <property name="maxIndexNum" value="10"/>
  
      <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
          <encoder>
              <pattern>[%d{yyyy-MM-dd HH:mm:ss}] [%thread] [%p] [%class:%line] %msg%n</pattern>
              <charset>UTF-8</charset>
          </encoder>
      </appender>
   	
   	<appender name="INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
          <file>${logHome}/info.log</file>
          <append>true</append>
          <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
              <fileNamePattern>${logHome}/info.%i.log.zip</fileNamePattern>
              <minIndex>${minIndexNum}</minIndex>
              <maxIndex>${maxIndexNum}</maxIndex>
          </rollingPolicy>
          <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
              <maxFileSize>${maxFileSize}</maxFileSize>
          </triggeringPolicy>
          <encoder>
              <pattern>[%d{yyyy-MM-dd HH:mm:ss}] [%thread] [%p] [%class:%line] %msg%n</pattern>
              <charset>UTF-8</charset>
          </encoder>
      </appender>
  	
  	<root level="INFO">
          <appender-ref ref="STDOUT"/>
          <appender-ref ref="INFO"/>
      </root>
  </configuration>
  

• 启动时指定了外部的logback.xml，cmdline为：java -Xms256m -Xmx512m -jar myapp.jar --logging.config=/usr/local/config/logback.xml，配置内容如下，两个配置文件仅有一处logHome不同：

  <?xml version="1.0" encoding="UTF-8"?>
  <configuration scan="true" scanPeriod="60 seconds" debug="false">
      <!-- 定义log文件的目录 -->
      <property name="logHome" value="/var/log/cmdline/"/>
      <property name="maxHistory" value="7"/>
      <property name="maxFileSize" value="10MB"/>
      <property name="totalSizeCap" value="200MB"/>
      <property name="minIndexNum" value="1"/>
      <property name="maxIndexNum" value="10"/>
  
      <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
          <encoder>
              <pattern>[%d{yyyy-MM-dd HH:mm:ss}] [%thread] [%p] [%class:%line] %msg%n</pattern>
              <charset>UTF-8</charset>
          </encoder>
      </appender>
   	
   	<appender name="INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
          <file>${logHome}/info.log</file>
          <append>true</append>
          <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
              <fileNamePattern>${logHome}/info.%i.log.zip</fileNamePattern>
              <minIndex>${minIndexNum}</minIndex>
              <maxIndex>${maxIndexNum}</maxIndex>
          </rollingPolicy>
          <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
              <maxFileSize>${maxFileSize}</maxFileSize>
          </triggeringPolicy>
          <encoder>
              <pattern>[%d{yyyy-MM-dd HH:mm:ss}] [%thread] [%p] [%class:%line] %msg%n</pattern>
              <charset>UTF-8</charset>
          </encoder>
      </appender>
  	
  	<root level="INFO">
          <appender-ref ref="STDOUT"/>
          <appender-ref ref="INFO"/>
      </root>
  </configuration>
  

现象

使用cmdline启动并且指定logging.config时，会同时在/var/log/classpath/和/var/log/cmdline/生成一个info.log文件，但classpath的info.log始终为空，只会在cmdline下的info.log写入日志。

排查

猜测可能是springboot或logback在项目启动时先读取了classpath下的logback.xml初始化了日志文件，等spring context加载到某一个过程发布一个事件，某一个Listener又根据外部配置再初始化了一次日志文件，后续都会使用这个配置文件。

1. 删除classpath和cmdline文件夹，在启动类的main方法第一行打上断点，启动项目；
2. 到达main方法第一行时，两个文件夹均未生成；
3. step into，刚进入方法第一行，classpath文件夹生成了，并且文件夹下有一个空的info.log；
4. 继续step into进入org.springframework.boot.SpringApplication#run(java.lang.String...)方法后，cmdline文件夹还未生成；
5. 执行org.springframework.boot.SpringApplication#prepareEnvironment方法后发布了一个ApplicationEnvironmentPreparedEvent事件；
6. org.springframework.boot.context.logging.LoggingApplicationListener监听器响应该事件，执行org.springframework.boot.context.logging.LoggingApplicationListener#initialize方法初始化了cmdline文件夹

至此整个过程基本明了：

1. 应该有static属性或static块读取了classpath里的logback.xml，并初始化了日志文件；
2. spring boot在环境准备完毕后才会初始化日志文件。

最后发现是logback的org.slf4j.impl.StaticLoggerBinder有一个static块SINGLETON.init();：

/**
 * Logback: the reliable, generic, fast and flexible logging framework.
 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
 *
 * This program and the accompanying materials are dual-licensed under
 * either the terms of the Eclipse Public License v1.0 as published by
 * the Eclipse Foundation
 *
 *   or (per the licensee's choosing)
 *
 * under the terms of the GNU Lesser General Public License version 2.1
 * as published by the Free Software Foundation.
 */
package org.slf4j.impl;

import ch.qos.logback.core.status.StatusUtil;
import org.slf4j.ILoggerFactory;
import org.slf4j.LoggerFactory;
import org.slf4j.helpers.Util;
import org.slf4j.spi.LoggerFactoryBinder;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.util.ContextInitializer;
import ch.qos.logback.classic.util.ContextSelectorStaticBinder;
import ch.qos.logback.core.CoreConstants;
import ch.qos.logback.core.joran.spi.JoranException;
import ch.qos.logback.core.util.StatusPrinter;

/**
 * 
 * The binding of {@link LoggerFactory} class with an actual instance of
 * {@link ILoggerFactory} is performed using information returned by this class.
 * 
 * @author Ceki G&uuml;lc&uuml;</a>
 */
public class StaticLoggerBinder implements LoggerFactoryBinder {

    /**
     * Declare the version of the SLF4J API this implementation is compiled
     * against. The value of this field is usually modified with each release.
     */
    // to avoid constant folding by the compiler, this field must *not* be final
    public static String REQUESTED_API_VERSION = "1.7.16"; // !final

    final static String NULL_CS_URL = CoreConstants.CODES_URL + "#null_CS";

    /**
     * The unique instance of this class.
     */
    private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

    private static Object KEY = new Object();

	/**
	 * 这个方法跟下去可以发现加载了classpath根目录的logback.xml，并初始化了日志文件
	 */
    static {
        SINGLETON.init();
    }

    private boolean initialized = false;
    private LoggerContext defaultLoggerContext = new LoggerContext();
    private final ContextSelectorStaticBinder contextSelectorBinder = ContextSelectorStaticBinder.getSingleton();

    private StaticLoggerBinder() {
        defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);
    }

    public static StaticLoggerBinder getSingleton() {
        return SINGLETON;
    }

    /**
     * Package access for testing purposes.
     */
    static void reset() {
        SINGLETON = new StaticLoggerBinder();
        SINGLETON.init();
    }

    /**
     * Package access for testing purposes.
     */
    void init() {
        try {
            try {
                new ContextInitializer(defaultLoggerContext).autoConfig();
            } catch (JoranException je) {
                Util.report("Failed to auto configure default logger context", je);
            }
            // logback-292
            if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
                StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
            }
            contextSelectorBinder.init(defaultLoggerContext, KEY);
            initialized = true;
        } catch (Exception t) { // see LOGBACK-1159
            Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
        }
    }

    public ILoggerFactory getLoggerFactory() {
        if (!initialized) {
            return defaultLoggerContext;
        }

        if (contextSelectorBinder.getContextSelector() == null) {
            throw new IllegalStateException("contextSelector cannot be null. See also " + NULL_CS_URL);
        }
        return contextSelectorBinder.getContextSelector().getLoggerContext();
    }

    public String getLoggerFactoryClassStr() {
        return contextSelectorBinder.getClass().getName();
    }

}

解决方案

1. 将logback.xml从classpath根目录移动到非根目录，然后在application.properties加入参数：logging.config=classpath:/logback/logback.xml
2. 既然spring boot可以在applicaiton.properties配置，为何还要单独使用logback.xml配置呢，于是尝试使用application.properties配置

新的问题

对于第2中解决方案，详见：Logging

按照文档中的解释，本以为设置了如下3个参数就完事了，期望实现日志文件达到10M时归档压缩，最多保留10个归档文件：

logging.file=/var/log/myapp/info.log
logging.file.max-size=10mb
logging.file.max-history=10

但实际并不与期望相符，google找到如下解释：Clarify description of “logging.file.max-history” #17566

Spring Boot is using Logback’s SizeAndTimeBasedRollingPolicy, which means log files are rotated when the time limit has been reached - also, the log files are split to make sure that files don’t exceed the maximum size.
In our case, Spring Boot is using the following pattern %d{yyyy-MM-dd}.%i.gz, which infers daily periods.
This means that, for the following configuration, we might get 14 files if the application logs 20MB every 24hours (2x 10MB files per day):

logging.file.max-history=7
logging.file.max-size=10MB

This holds true, unless developers override the default logback configuration provided by Spring Boot.
I think you’re right and we should update the configuration description to reflect that.

简言之，就是spring boot默认使用的rolling策略是SizeAndTimeBasedRollingPolicy，在这个策略中，logging.file.max-history并不是代表最大文件数，而是最多保留多少天的文件

修改logging.file.max-size=10kb logging.file.max-history=1，并配合修改系统时间，发现果真如此。

总结

1. logback的org.slf4j.impl.StaticLoggerBinder里有一个static块，会在项目启动的时候读取classpath根目录下的logback.xml，并初始化日志文件；
2. spring boot的logging配置有很多局限性，在后续的版本增加了许多logback的参数，比如total-cap-size等等，但还是不能支持logback所有参数和配置方式，这可能和springboot的初衷有关：简化配置，而不是支持所有配置，如果需要使用logback的复杂特性，建议使用外部xml配置。