解决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ülcü</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配置。