on tech

震惊！你的健康检查，正在杀死你！

TLDR （经验教训）

  1. 阿里云的负载服务，在健康检查失败的情况下，直接把所有请求返回 502，请求不再 forward 到后端服务器
  2. nodejs 的mysql这个库，链接池在用完的情况下，继续取链接，（default）不会报错，更不会超时，大家一起等到天荒地老
  3. 除了你自己写的代码，所有其他库也好、服务也好，都是依赖。依赖是黑盒子（我不信开源的库你就会熟读每一行代码），黑盒子出了问题，是最头痛的

流水账

中午新版本发布，代码主要 diff 在新作了个活动，逻辑有一丢丢复杂，发布之后到晚上都正常，在日常流量下。

下午的时候，有用户在核心用户群里反馈请求错误，验证了一下所有人的登录包都没响应了，欣喜若狂，以为流量炸裂了（理智分析了 1s，好像不太可能，是想钱想疯了没错）。

果然，第一时间打开阿里云的监控，cpu 带宽都是 10%不到的状况（稍微背景下：乞丐级虚拟机，单机，前面有个负载服务，为啥单机还要负载？因为 1.有理想 2.价钱并没有贵多少，like 一个月一顿 KFC？）

第二时间 ssh 上服务器，祭出大杀器——重启试试（我流量小但我日志打得多啊，不用留全尸，就是这么自信呵呵），重启了一下，果真万事大吉。 转念一想，不对啊，有进程管理的东西在（pm2），如果真是服务器进程崩了自动就重启了啊，也就是进程没死，只是变成僵尸了？后悔刚才应该 curl 一下的。

第三时间开始查日志（无关吐槽，postmortem 这个词看起来很专业，尸检看起来就很阴森），先看 accesslog，发现有一段时间的空白，一条日志都没有。这个好理解，因为我为了记每个请求的 duration，是在请求返回的前一刻才打的日志（duration = endtime - starttime），所以可以断定为请求都在服务器里堆积着，处在并没有从网卡写回去的状态。 进一步证明了，服务器在故障时，处于一个装了一肚子请求的僵尸状态，神奇。
再看 info 级别的 log，这个 log 记得啰嗦很多，从请求来到请求走中间还有些逻辑都写了日志。用 accesslog 开始空白的时间搜索，很容易就找到了案发现场，往前查看详细日志，看到了一大堆没返回（有来无回）的登录包，然后突然也就没日志了，再后来就是重启了。 嗯？不对！就算可能是死锁或者是类似的问题，也没说过 nodejs 有请求太多（况且请求真不多）就阻塞不再相应的问题，反之 nodejs 的买点不就是异步无阻塞，高 IO 行家吗？一个请求都不在进 nodejs（log 不到）不合常理。

头痛，一下午就过去了。

晚上，再一次故障，所有请求 502。第一时间 ssh 上服务器以后，curl了一下 localhost 的某个接口，200，说明僵尸还活着，还能吃请求。突然想到，这个服务器前面不是还有一个负载的服务吗，还给我勤勤恳恳地发了服务不健康的短信来着。
健康检查可能是坏人，它谎报了健康状况(其实并没有)！一边查看日志，一边提了工单问阿里云的售后（吐槽一下，大多时候没啥卵用）。顺便，健康检查大致的代码如下：

function healthCheck() {
	checkRedis();
	// some 'SELECT 1;' sql, sadly timeout here
	checkDb();
	checkGrpc();
}

最终发现，负载服务一旦开启了健康查查，且健康检查的结果是不健康的时候，所有请求不再 forward 到后端的服务，而是直接在负载这层就 return 502 了。而当检查检查恢复到健康的时候，它才会继续 forward 请求。
这顺便也就解答了我长期以来的一个疑问，有时候，一旦重启服务器的速度比较慢，前端链接恢复正常的速度就会慢得更多，原来是在等健康检查 200，就“无端”浪费了好几个健康检查的 interval。

至此，问题解决
了吗？并没有。

只是晓得了 502 和后端服务器收不到请求的原因，但造成后端服务器假死的真正原因并没有找到，健康检查挂了的原因也不明确。

一天过去了。

第二天，从日志里把几次事故时间点往上大概 1000 条日志抓了出来，去除一些干扰信息，重新合并到一个文件里，然后开了 N 个窗口，开始交叉对比。
惊奇的发现，开始出现假死的时候，所有数据库的 query 都没有执行（健康检查也就挂在了检查数据库链接的那一行）。数据库死锁？不对啊，重启服务器解决不了这个啊。上 rds 看了下（对，数据库也买的 PaaS），确实没有死锁的记录。
又一想，数据库服务器没死锁，但客户端可以啊。是不是问题出在 mysql 客户端的链接池？但这个东西能“死锁”吗？还真能！赶快写个简单的代码复现一下：

const pool = mysql.createPool({ ...otherConfig, connectionLimit: 2 });
pool.getConnection(cbNotRelease);
pool.getConnection(cbNotRelease);
// died here
pool.getConnection(cbNotRelease);

之后顺着日志看了下，事发之前都在请求新上的活动的接口，很快就定位到了真正的 bug：

const tx = await db.beginTransaction();
// bug1: should use tx not db
await db.query("select blah");
// bug2: forget to commit
// tx.commit

自己封装的beginTransaction()在commit()或者rollback()的时候自动去 release connection，忘了 commit 就不会 release，而 tx 中的 query 其实并没有用到这个 connection，还是在正常执行。 所以两个 bug 叠加在一起就导致了好像业务能正常运行，但是请求这个接口到达一定次数之后（connectionLimit 次），所有数据库请求都在客户端被锁死。 所以，mysql.js 这个库的acquireTimeout根本不是我想象的那个意思（获取 connection 超时后报错），不过也不能这样设计，原因见下。

至此，问题解决
了吗？bugfix 了，但是能不能在 design 上杜绝这种情况？

考虑了两种实现，使用了后一种：

  1. 直接在 beginTransaction 的时候起一个 timer，超时自动 release，client 端是不会死锁了，但是锁却留给了数据库（相当于在 mysql 里只BEGIN，然后就不管不顾起其他链接了），只是把问题转移给了数据库，还更不容察觉
  2. 自行记录所有在用的 conn 计数，超过 connectionLimit 就报错，让程序挂掉，顺便释放所有数据库链接（这一手 let it crash 相当潇洒）

至此，问题解决。

经验教育（续）

强行首尾呼应一下

  1. 日志还是要多打
  2. 做好每一个依赖出错的准备（至少是心里准备）