今日文章由作者 @林乐扬 投稿分享。
最近接手泛前端团队的服务稳定性治理,遇到一些很有特点的线上问题,这边记录一次『有趣的 bug』排查。
故事的开始是由老板的一个艾特开始的:
当时排查了下没啥思路,就放弃了(以为偶现,过几天它能自己好起来!)。直到某一天我又收到了同样的告警,我回想了下最近好几天都有这个告警。
抬头一看:
心里一惊:别搞出事故啊!就开始了我的排查之路。
根据告警错误栈显示,这是一个 "unhandledRejection":
[ERROR][2020-09-16T23:59:59.582+0800][default:process.<anonymous> at /home/xxx/xxx/xxx/lib/app.js:49:10] _undef||traceid=64594b155f6231298ae0e2b114a1a02||spanid=38197e8a96a6d96a||pid=1431||msg=on unhandledRejection, error: { Error: ERR invalid expire time in set
at JavascriptReplyParser.parseResult (/home/xxx/xxx/xxx/node_modules/redis-parser/lib/javascript.js:90:16)
at JavascriptReplyParser.tryParsing (/home/xxx/xxx/xxx/node_modules/redis-parser/lib/javascript.js:117:21)
at JavascriptReplyParser.run (/home/xxx/xxx/xxx/node_modules/redis-parser/lib/javascript.js:131:22)
at JavascriptReplyParser.execute (/home/xxx/xxx/xxx/node_modules/redis-parser/lib/javascript.js:112:10)
at Socket.<anonymous> (/home/xxx/xxx/xxx/node_modules/redis/index.js:223:27)
at emitOne (events.js:116:13)
at Socket.emit (events.js:211:7)
at addChunk (_stream_readable.js:263:12)
at readableAddChunk (_stream_readable.js:250:11)
at Socket.Readable.push (_stream_readable.js:208:10) command: 'SET', code: 'ERR' }
所以一层一层往上找,是找不到抛错的源头的!猜测了一通无果,于是我去翻告警群的记录,我发现了一个惊人的规律,该告警只要出现,必定是每天凌晨 00:02:
因此排查思路锁定在以下几个:
剧透下,并不是上述两个原因。
经过多番搜索代码,发现了几处设置 redis 值的代码,同时结合 Google,有人指出 Redis 设置的超时时间不能为小于 0。经过本地验证,的确发现超时时间不能为 0:
于是排查方向转为代码中哪里出现了设置超时时间小于 0 的逻辑。可疑代码如下:
setRedisKey(
redisTeamKey,
data,
24 * 3600 - getPastTimeOfToday() / 1000,
)
那么这个值 24*3600 - getPastTimeOfToday() / 1000
可能为 0 或者负数吗?我们来看看完整逻辑:
const getPastTimeOfToday = () => {
const date = new Date()
const year = date.getFullYear()
const month = strPadding(date.getMonth() + 1, '0', 2)
const day = strPadding(date.getDate(), '0', 2)
const todayStartTs = +new Date(`${year}/${month}/${day} 00:00:00`)
return +new Date() - +new Date(todayStartTs)
}
这个值代表当前这个时间点,离今天结束还有多少秒的时间。可是这个值不可能小于 0,我甚至猜测是否执行上述代码第二行时是昨天,而第七行的时候是今天,这样能验证我们的猜测,即这个函数返回的值大于 24*3600
,那 24*3600 - getPastTimeOfToday() / 1000
就小于 0 了。不过这个可能性比较低,于是我转而去服务器复现这个 bug,编写如下代码并执行:
const { setRedisKey } = require('./lib/xxx/xxx/redis')
process.on('unhandledRejection', console.log)
setRedisKey('abc', 'value', 0)
执行结果如下,与告警的错误栈一致:
image-20201009144722346
既然复现了错误,回头继续找 bug,深入到 setRedisKey
代码:
const setRedisKey = (key, value, expireTime = DEFAULT_EXPIRETIME) => {
return redis.set(key, value, 'EX', Math.floor(expireTime))
}
过期时间 expireTime
被 Math.floor 包裹,也就是说当 0 < expireTime < 1
时,Math.floor(expireTime)
的值为 0。那么当服务器时间到无限接近 00:00:00 时,getPastTimeOfToday
将返回 (24*3600-x)*1000
,因为无限接近 00:00:00,因此 x 的值介于 0 - 1 之间(毕竟时间戳的最小单位是毫秒,想象下『当天剩余毫秒数』还有不到 1000 的情况)。
对了,为什么该错误没有被捕获?如果一开始被捕获,也就有完整的错误栈,那么排查过程肯定会顺利很多。业务代码如下(已脱敏):
Promise.resolve().then(() => {
Promise.reject(new Error('出错了!'))
}).catch(console.error)
大家发现了吧,then 中的 Promise 没有返回,那么我返回了就一定会被捕获吗?在这种写法下是会的,大家可以尝试下,但是你写成下面这样,还是会 unhandledRejection
:
new Promise((resolve, reject) => {
if (false) {
resolve('对了!')
}
if (true) {
return Promise.reject(new Error('出错了!'))
}
reject(new Error('兜底逻辑!'))
}).catch(console.warn)
为什么呢?因为需要手动调用 reject 才可抛错,这就需要层层将 resolve 和 reject 传入可能报错的 Promise 才行,珍爱生命远离 Promise,大家还是尽量用 async/await
语法(相同功能下)。
原因既然依旧找到,解决方式也就出来了:
expireTime
值小于等于 0 时,赋值为 1(续一秒,蛤蛤蛤),同时记录 warn 警告日志尝试找了下 typescript 限制 number 为正整数的方式,没有找到,有的话求大神告知?
我叫林乐扬,点击 “阅读原文” 阅读我的更多文章,觉得有收获记得打开原文链接给我点个赞,或者关注我哦~
- END -