先说结论
本次日志回收失败主要是由于logback(1.1.7)低版本bug导致无法按照totalSize正常回收。尝试升级至高版本(1.2.0及以上)即可。
问题记录
有一次线上突然报错,说是k8s对应的ecs的磁盘压力过大,而导致了pod的重启。
很快分析磁盘的内容是日志占满了。但是哪有不配置日志回收策略的生产项目呢?这个时候就在想为啥日志不回收,为啥?
状况分析
版本
logback 1.1.7
回收策略配置代码部分
解决日志的分布式问题,使用统一的包对日志进行了封装。采用了java代码的方式配置了Logger,Appender以及RollingPolicy,其中日志回收部分代码配置如下
ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy rollingPolicy = new
ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy();
// 设置针对那一个appender的回收方式
rollingPolicy.setParent(fileAppender);
// 拼接出来文件名
String fp = LOG_PATH + getProject() + "/" + getProject() +
fileRemark + "-" + "%d{yyyy-MM-dd}.%i.log";
rollingPolicy.setFileNamePattern(fp);
// 这个是关键,设置最大的保存期限,这个maxHistory是一个动态的概念。需要和 fp中的 %d{yyyy-MM-dd}对应,此时表示保留的最大天数。%d{yyyy-MM-dd-HH} 则代表小时
rollingPolicy.setMaxHistory(LOG_MAXHISTORY);
// 设置单个文件的长度
rollingPolicy.setMaxFileSize(500mb);
// 设置保存的文件的最大长度
rollingPolicy.setTotalSizeCap(10gb);
rollingPolicy.start();
回收策略:初步认识
1、配置了maxHistory参数
这个参数不是单纯的保留多少天的意思,也不是保留多少个文件的意思。他是跟随者文件的格式变化的,如使用 %d{yyyy-MM-dd-HH} 就是保留多少天的意思。当然一般也都是使用的这个
2、配置了maxFileSize参数
这个参数代表着单个文件最大的长度。实时也按照500mb切分成了小文件
3、配置了totalSizeCap
这个参数代表着最大的文件大小。
我们配置了10gb,但是这个参数没有生效。当时其pod内的日志已经达到了接近200g。
分析过程
其回收一般分为两个部分
1、按时间回收。比如说使用%d{yyyy-MM-dd} 格式时,会在每天零点进行回收
2、每次日志滚动生成新的文件时也会调用回收方法判断是否可以回收
调试回收代码
ch.qos.logback.core.rolling.helper.TimeBasedArchiveRemover.ArhiveRemoverRunnable#run
其内分为两部分,如下。clean方法是按照时间(maxHistory)进行回收。capTotalSize是按照文件大小回收。
// 此方法是按照时间回收
TimeBasedArchiveRemover.this.clean(this.now);
if (TimeBasedArchiveRemover.this.totalSizeCap != 0L &&
TimeBasedArchiveRemover.this.totalSizeCap > 0L) {
// 此方法是按照大小回收
TimeBasedArchiveRemover.this.capTotalSize(this.now);
}
按照时间回收代码分析
这个根据maxpoint和上次回收的点计算出偏移量,然后按照日期进行删除。按照对日志的回收观测,确实是可以按照时间点进行回收的。
public void clean(Date now) {
// 获取当前时间
long nowInMillis = now.getTime();
// 根据当前时间,以及记录的上一次回收的时间,判断过去了几个周期
// 比如本次时间是 2024-07-02 20:00:00 上次是2024-07-01 20:00:00,此时配置的是{yyyy-MM-dd} 就代表着有一个时间周期没回收数据了
int periodsElapsed = this.computeElapsedPeriodsSinceLastClean(nowInMillis);
this.lastHeartBeat = nowInMillis;
if (periodsElapsed > 1) {
this.addInfo("Multiple periods, i.e. " + periodsElapsed + " periods, seem to have elapsed. This is expected at application start.");
}
// 判断有几个周期没回收,比如说1个周期,则如果maxPoint配置的是4,可能是距离当天的前面的第五个周期的没回收。因此计算出偏移量,和当前时间,然后按照日期回收。
for(int i = 0; i < periodsElapsed; ++i) {
int offset = this.getPeriodOffsetForDeletionTarget() - i;
Date dateOfPeriodToClean = this.rc.getEndOfNextNthPeriod(now, offset);
this.cleanPeriod(dateOfPeriodToClean);
}
}
按照大小回收代码
因为不在maxHistory这个周期范围内会被上边的代码回收,如果在周期范围内,且总长度超过配置的长度则会用到这个方法进行回收。
其中totalSize是使用int表示的。代表的最大范围是4294967296,也就是4Gb,当超过4Gb的话就会抛出异常,从而导致回收异常。
基于此性质的情况下可以看出来回收的时候所有日志长度之和不能超过4Gb这个限制,一旦超过则无法正常回收。
而且文件有一个细节,就是偏移量在2以内的也不会回收。如果想正常回收,那么必须在一个周期的日志不能超过4gb,当然文件大小以及新生成的文件会有一定偏差,此值在3gb以内比较安全。
void capTotalSize(Date now) {
// 最大的败笔就是在这,使用int来表示了totalSize的长度
int totalSize = 0;
int totalRemoved = 0;
// 在周期范围内的回收
for(int offset = 0; offset < this.maxHistory; ++offset) {
// 这个就是获取每个周期的时间,用当前时间和格式获取偏移周期的时间
Date date = this.rc.getEndOfNextNthPeriod(now, -offset);
// 获取偏移周期的所有文件
File[] matchingFileArray = this.getFilesInPeriod(date);
this.descendingSortByLastModified(matchingFileArray);
File[] arr$ = matchingFileArray;
int len$ = matchingFileArray.length;
// 遍历偏移周期的文件,然后逐个加上所有的文件大小,判断总长度
for(int i$ = 0; i$ < len$; ++i$) {
File f = arr$[i$];
long size = f.length();
if ((long)totalSize + size > this.totalSizeCap) {
// 此处也有个回收的小策略。当前周期和上个周期不会回收,只会回收1个周期以上的文件
if (offset >= 2) {
this.addInfo("Deleting [" + f + "]" + " of size " + new FileSize(size));
totalRemoved = (int)((long)totalRemoved + size);
f.delete();
} else {
this.addWarn("Skipping [" + f + "]" + " of size " + new FileSize(size) + " as it is one of the two newest log achives.");
}
}
totalSize = (int)((long)totalSize + size);
}
}
官方问题处理
解决方案
1、升级logback版本至1.2.3
2、通过maxHistory进行回收,由于我们的日志都会输出到阿里云,因此可以设置为1,这些比较短的值