刚从国庆假期回来(本来开开心心),人刚到工位,突然运营团队反馈某个功能非常卡顿,经测试初步判断看到接口变慢,一次查询要等 5~13 秒,但服务整体仍可使用。起初以为是慢 SQL,最后查到了被 SQL 注入。
用 Arthas 顺着调用链往下追,耗时集中在数据库查询,查看 InnoDB 状态时,发现一个异常指标:(trx_rseg_history_len) History list length 约 1.046 亿 (MVCC 回滚日志长度 )
继续检查
information_schema.innodb_trx 和连接列表,发现有查询已经持续十余天,状态是 User sleep。SQL 条件里出现了:至于为什么
SLEEP(5) 能持续这么久:五秒是一次函数求值的等待时间,不是整条 SQL 的执行上限。放在查询语句多个表连接查询放大次数(处理行数),然后影响多个别的事务更改的时候创建undo log未被清理。(本来还想夸一下是那个鬼才写的代码往 SQL 丢 SLEEP )
拿异常 SQL 的字段和关联结构搜索代码,找到下面这段 MyBatis 条件:
再往上追,发现接口传入的 ID 最终进入了
ids。因为 ${ids} 是原样拼接,参数里的 1 AND SLEEP(5) 就成了 SQL 表达式。核对异常连接后,结束旧事务,并停止异常写入,随后持续观察:
约 1.046 亿 → 5539 万 → 89.9 万 → 221
总结
前人挖坑,后人填坑。(接下来要用 Codex 来全局扫描所有老项目)