log4j2:占位符引起的内存泄漏bug

log4j2使用

之前用的logback，然后（抽了）换成log4j2,主要log4j2支持异步日志（基于disruptor），据说性能很高，但是用了后发现不少问题，记录下最近发现的一个严重bug

调用现象

访问接口的时间重复打印了两次日志，第一次是fegin返回日志，第二次是springmvc返回日志，但是发现耗时十几秒；

排查手段

1.开始时手段比较粗暴，直接观察日志打印时间前后时间差，发现耗时确实比较长，然后fegin直接进行了降级，于是把fegin返回日志禁掉，发现还是耗时将近10s。
2.然后监控线程和堆内存大小，这里用arthas监控的，发现新生代内存飙涨达到1g多(实际粘贴出来只有200k)，线程cpu使用率达到100%，gc日志也频繁输出swt，如图(经过调整过还是百分之60%)：

。
3.用jcmd pid JRF 记录器记录下一次请求的堆栈情况，然后导出服务器，用JProfiler(支持ssh在线attach)导入记录的备份文件：如图：

从这几张图已经明确log4j2的logger.info导致的，将日志输出改成debug或者去掉就没这问题，而StrSubstitutor.substitute已经接近递归调用了，该方法耗时将近6s.

耗时原因

输出的gc日志也没有内存溢出(堆溢出、栈溢出、堆外溢出)的错误，百思不得其接写法有哪里不对，只是最简单logger.info,
1.通过查到StrSubstitutor该类的是跟appache-text中的同名类差不多解决占位符问题的，在想也是loggger.info第一个参数有{}这种占位符也不影响吧，然后观察到输出的返回参数里带有${1},然后把带有${1}的字段去掉，结果耗时只有100ms，
然后再看源码果然有：

构造方法用的默认

默认替换${}中间的变量名

并且出现循环调用自己

源码里的该方法比较长，没有仔细琢磨下，但是本地debug了下，发现会将整个输出的字符串进行循环替换；，然后找到替换占位符的方法，

看到里面的替换占位符的方法：StrLookup，有如下实现类，

就点进各类去看了，有替换自定义的属性的，传入变量的，发现暂时不需要这些，然后跳到上级调用类MessagePatternConverter.format

发现该方法又一次进行循环判断，也同时看到有条件才可以进入，nolookup为true就不变遍历
然后看到常量配置类里这个默认是false,果断将log4j2.component.properties的log4j2.formatMsgNoLookups设置true(也可以在log4j2的logger初始化前设置System.setProperty).
2.该漏洞明显是字符串过长而导致递归调用的，每次递归和循环都是新建一个StringBuilder，还有递归曾经有两百多层，所有还可以将线程栈初始容量设置大点-X:xss,还有新生代设置大点，大对象进行gc限制也设置大点。当然这种办法可能耗时会减少，但是治标不治本，而且对硬件有要求。

问题回顾

1.定位问题用了观测线上堆栈与cpu情况、线下查看dump详情、和源码阅读三种方式。
2.该bug通过百度、google都没找到相似问题，github的log4j2项目的bug列表也没，目前升级到2.13.3问题依旧还在，小编英文不太好，所以就不提了，有github账号的朋友可以去提下（lo4j2的github地址）。