记一次日志切割问题

logback日志切分问题

logback切分日志是在有打印事件时才触发，也就是说如果你设置的按小时切割，如果晚上1:00至3:00 服务没有请求，没有日志打印，那么logback不会生成这段期间内的切分日志，对接运维收集日志时出现了问题，所以我们重写了Appender

public class MyRollingFileAppender<E> extends RollingFileAppender<E> {
    private static List<MyRollingFileAppender> appenders = new CopyOnWriteArrayList();

    private void checkRollover() {
        TriggeringPolicy var1 = this.triggeringPolicy;
        synchronized(this.triggeringPolicy) {
            if (this.triggeringPolicy.isTriggeringEvent(this.currentlyActiveFile, (Object)null)) {
                this.rollover();
            } else {
                // 到点日志切分文件不存在时触发，这里是按时间切的
                if (this.triggeringPolicy instanceof TimeBasedRollingPolicy && !this.currentlyActiveFile.exists()) {
                    TimeBasedFileNamingAndTriggeringPolicy policy = ((TimeBasedRollingPolicy)this.triggeringPolicy).getTimeBasedFileNamingAndTriggeringPolicy();
                    if (policy instanceof TimeBasedFileNamingAndTriggeringPolicyBase) {
                        TimeBasedFileNamingAndTriggeringPolicyBase tp = (TimeBasedFileNamingAndTriggeringPolicyBase)policy;
                        tp.elapsedPeriodsFileName = tp.tbrp.fileNamePatternWithoutCompSuffix.convert(tp.dateInCurrentPeriod);
                        this.rollover();
                    }
                }

            }
        }
    }

    public MyRollingFileAppender() {
        appenders.add(this);
    }

    static {
        // 确保每小时都执行切割
        ManagedExecutors.getScheduleExecutor().scheduleWithFixedDelay(new TimerTask() {
            public void run() {
                String name = Thread.currentThread().getName();

                try {
                    Thread.currentThread().setName("MyLogbackTimer");
                    Iterator var2 = MyRollingFileAppender.appenders.iterator();

                    while(var2.hasNext()) {
                        MyRollingFileAppender appender = (MyRollingFileAppender)var2.next();
                        appender.checkRollover();
                    }
                } finally {
                    Thread.currentThread().setName(name);
                }

            }
        }, 1L, 1L, TimeUnit.MINUTES);
    }
}

这样运维那边收集日志就不会报错，ssm框架完美运行，之后改用springboot时，日志打印、切割全乱套了，后来发现问题是因为，项目启动时，logback相关jar包会初始化appender节点相关类（初始化入口：org.slf4j.impl.StaticLoggerBinder#init）；之后springboot定义的ApplicationListener（LoggingApplicationListener）会将Loggerl类中管理的appender集合清空，以便再次实例化appender节点相关类。

// org.springframework.boot.logging.logback.LogbackLoggingSystem#stopAndReset
@Override
public void reset() {
    resetCount++;
    super.reset();
    initEvaluatorMap();
    initCollisionMaps();
	// 清空第一次实例化的appender
    root.recursiveReset();
    resetTurboFilterList();
    cancelScheduledTasks();
    fireOnReset();
    resetListenersExceptResetResistant();
    resetStatusListeners();
}

但是我们自定义的MyRollingFileAppender类中维护的appenders集合，实际上经过logback jar和springboot两次初始化后，每个appender实例都保存了两份，导致打印、切割出现了问题

public MyRollingFileAppender() {
  // springboot实例化两次，导致appenders集合中存在两个相同的appender的bean
    appenders.add(this);
}

解决方式就是将logback.xml改名为logback-spring.xml，springboot完美运行

• logback在第一次加载时会找logback.xml文件，找不到则不会实例化xml中配置的appender类。
• 在springboot加载第二次时，如果找不到logback.xml，会去找logback-spring.xml文件，进行初始化。初始化入口：org.springframework.boot.context.logging.LoggingApplicationListener#onApplicationEnvironmentPreparedEvent

springboot生态中各种starter依赖，入口基本都在METE-INF目录下spring-factories文件中配置

// org.springframework.boot.logging.AbstractLoggingSystem#getSpringConfigLocations
protected String[] getSpringConfigLocations() {
   String[] locations = getStandardConfigLocations();
   for (int i = 0; i < locations.length; i++) {
      String extension = StringUtils.getFilenameExtension(locations[i]);
      locations[i] = locations[i].substring(0,
            locations[i].length() - extension.length() - 1) + "-spring."
            + extension;
   }
   return locations;
}

再来追一下logback的切分逻辑

当有日志输出时，logback才会触发切分流程

1.logback切分入口：ch.qos.logback.core.rolling.RollingFileAppender#subAppend

synchronized (triggeringPolicy) {
    // 判断是否触发切分事件
    if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
        rollover();
    }
}

2.triggeringPolicy为logback.xml中rollingPolicy节点定义的类，最终调用了DefaultTimeBasedFileNamingAndTriggeringPolicy的isTriggeringEvent方法

public boolean isTriggeringEvent(File activeFile, final E event) {
    long time = getCurrentTime();
    if (time >= nextCheck) {
        // 获取上次触发切分事件的时间点
        Date dateOfElapsedPeriod = dateInCurrentPeriod;
        addInfo("Elapsed period: " + dateOfElapsedPeriod);
		// 设置切分后文件名
        elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convert(dateOfElapsedPeriod);
        // 设置dateInCurrentPeriod为当前时间
        setDateInCurrentPeriod(time);
		// 设置nextCheck值，为下次切分日志的时间
        computeNextCheck();
        return true;
    } else {
        return false;
    }
}

3.当触发了日志切分，调用ch.qos.logback.core.rolling.RollingFileAppender#rollover

public void rollover() {
    lock.lock();
    try {
        // 关闭当前文件输出流。如default.log
        this.closeOutputStream();
		// 不压缩，将文件重命名，elapsedPeriodsFileName字段值（如${catalina.base}/logs/default.log.2019-05-21-16）
        attemptRollover();
		// 获取当前输出文件default.log，打开输出流
        attemptOpenFile();
    } finally {
        lock.unlock();
    }
}