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();
}
}