原起
在排查一个问题时,发现本应该每天定时执行的日志,在某些日期居然没有,中间的 11.26 、11.28、11.30 的日志呢?
查看同样代码的 打的 A 日志文件,日志均匀,每天都有
B 文件的日志为什么某些天丢失了? (这些日志文件本来是做数据对账的,比较重要)
分析
-
第一时间反应会不会是踩了 SLS 中间件 日志搜集上传的坑?
开始登录机器去查看 A 和 B 当天的日志文件,发现 当天打印 A 日志的机器,确实没有打印 B 日志,奇怪了 。
-
logback 日志打印丢失了? 查看 B 日志的日志配置 和 机器日志清单
tail -200 查看最后 200 行 out_user.log 后发现,日志停留在了 11月25号,已经停止更新 5 天了。
定位
已经怀疑到了是日志滚动问题,查了问题日志文件的 logback 配置:
而本项目中正常打印日志的的logback 配置如下:
这样对比来看,一下就猜测性的定位了问题 , 有人将 SizeAndTimeBasedRollingPolicy的 fileNamePattern 拷贝到了 FixedWindowRollingPolicy
而FixedWindowRollingPolicy 的 滚动策略配置了 %d{yyyy-MM-dd} 样式的在滚动代码执行时估计异常了
验证:将模板修改为 ${OUT_USER_FILE}.%i.log 后发现问题解决。
深究
为了搞清楚错误的原因,简单分析源码后,在关键位置打上断点
ch.qos.logback.core.rolling.helper.FileNamePattern 第 66 行,看 parse 方法第 65 行的结果:
如图所示,logback 中自制的分词器将 biz-%d{yyyy-MM-dd_HH}.%i.txt 解析成了 tokenList。
接下来代码执行到第 67 行,看一下 Node 的结果:
%d{yyyy-MM-dd_HH} 和 %i 被解析成了关键字,其他则保持字面值。
关键字 d 和 i 对应不同的转换器:
static final Map<String, String> CONVERTER_MAP = new HashMap<String, String>();
static {
// i 对应 IntegerTokenConverter
CONVERTER_MAP.put(IntegerTokenConverter.CONVERTER_KEY, IntegerTokenConverter.class.getName());
// d 对应 DateTokenConverter
CONVERTER_MAP.put(DateTokenConverter.CONVERTER_KEY, DateTokenConverter.class.getName());
}
又因为 FixedWindowRollingPolicy 产生的参数值只有 Integer 型的,所以遇到 %d{yyyy-MM-dd_HH} 就会出错了
总结
很多时候,我们在编写日志配置时,往往都死直接COPY 或者 照猫画虎 , 一不小心就会配置错误,然后 logback-core 并不会在这里做异常配置启动检测,或者做 try catch 处理这个小错误 。
而日志丢失问题可大可小,如果正好赶上问题排查的关键日志丢失,可能让排查问题的过程非常痛苦,另外如果赶上业务操作日志等重要举证内容,技术同学的说服力大大降低;
挡路牌指示语:
FixedWindowRollingPolicy 策略的 fileNamePattern 不能包含 %d{yyyy-MM-dd}
补坑:
该问题在 logback 官方确定为 bug , Issues 链接: https://jira.qos.ch/browse/LOGBACK-1293
想要完全规避该问题,需要将 logback-core 的版本升级到 1.4.6 以上 ;