解决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又根据外部配置再初始化了一次日志文件,后续都会使用这个配置文件。
- 删除classpath和cmdline文件夹,在启动类的main方法第一行打上断点,启动项目;
- 到达main方法第一行时,两个文件夹均未生成;
- step into,刚进入方法第一行,classpath文件夹生成了,并且文件夹下有一个空的info.log;
- 继续step into进入
org.springframework.boot.SpringApplication#run(java.lang.String...)
方法后,cmdline文件夹还未生成; - 执行
org.springframework.boot.SpringApplication#prepareEnvironment
方法后发布了一个ApplicationEnvironmentPreparedEvent
事件; -
org.springframework.boot.context.logging.LoggingApplicationListener
监听器响应该事件,执行org.springframework.boot.context.logging.LoggingApplicationListener#initialize
方法初始化了cmdline文件夹
至此整个过程基本明了:
- 应该有static属性或static块读取了classpath里的logback.xml,并初始化了日志文件;
- 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();
}
}
解决方案
- 将logback.xml从classpath根目录移动到非根目录,然后在application.properties加入参数:
logging.config=classpath:/logback/logback.xml
- 既然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
,并配合修改系统时间,发现果真如此。
总结
- logback的
org.slf4j.impl.StaticLoggerBinder
里有一个static块,会在项目启动的时候读取classpath根目录下的logback.xml
,并初始化日志文件; - spring boot的logging配置有很多局限性,在后续的版本增加了许多logback的参数,比如total-cap-size等等,但还是不能支持logback所有参数和配置方式,这可能和springboot的初衷有关:简化配置,而不是支持所有配置,如果需要使用logback的复杂特性,建议使用外部xml配置。