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

╰+哭是因爲堅強的太久メ 2023-06-28 09:51 4阅读 0赞

# 解决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">
            
            <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">
            
            <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][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配置。

[Logging]: https://docs.spring.io/spring-boot/docs/2.1.6.BUILD-SNAPSHOT/reference/html/boot-features-logging.html
[Clarify description of _logging.file.max-history_ _17566]: https://github.com/spring-projects/spring-boot/issues/17566