关于node.js:记一次-Nodejs-http-服务的排障记录

4次阅读

共计 4278 个字符,预计需要花费 11 分钟才能阅读完成。

前言

最近咱们团队接手了一个遗留我的项目,是由 Node.js 语言所编写的 HTTP 服务项目,我的项目大抵逻辑是通过 Node.js 来实现一层代理逻辑,做流量的直达,并增加一些要害的埋点来展现申请记录(_以及一些进阶的用法,篡改申请相干的数据,但与本次排障无关,便不赘述_)。
刚接手的时候咱们失去的状况是,这个我的项目因为内存透露和其余未知的起因,导致我的项目毕竟定时进行重启,否则用户应用时会感触到显著的提早 or 服务间接不可用。
所以咱们在一边进行人肉运维的同时,开始浏览源码,理解我的项目,剖析问题的起因并尝试进行修复。

排查过程

该我的项目是有要害的指标埋点的,包含内存、CPU 等指标,以及用户流量的数据统计,咱们看到了两个比拟重要的指标:

  1. 内存趋势
  2. Active Handle 的数量


就像最后失去的信息一样,有内存透露的问题存在,而不到一个小时的指标断崖式上涨就是因为服务被重启导致的。
同样下边一个 Active Handle 指标也是稳定十分的大,这里能够简略介绍一下 Active Handle 是什么,这个会延长提到一个 Node.js 技术栈常常波及到的一个关键词:Event Loop。

简略介绍 Event Loop

简略解释一下 Event Loop 的工作模式,如果咱们有一个文件,写了这样的代码:

console.log('hello')

那么咱们通过 node XXX 的形式运行该文件,运行结束后过程就会退出了。

而如果咱们写一个这样的文件:

console.log('hello')

setInterval(() => {}, 1e3)

再次通过 node XXX 的形式运行该文件,则终端会始终停留在该过程,并不会退出,因为咱们创立了一个定时器,而定时器能够了解为是一个 Active Handle,而 Event Loop 的运行流程就是会执行所有的同步代码,而后检测是否存在 Active Handle,如果没有检测到则会间接退出,如有存在的 Handle 则会进入咱们相熟的 Event Loop。
咱们能够通过一个非公开的 API 来获取到 Active Handle 的数量:

process._getActiveHandles()

console.log(process._getActiveHandles().length) // 0

如果通过 node XXX 的形式运行这样的代码,那么咱们会失去一个 0,而如果咱们间接通过 node 进入交互命令行,则会发现这个值为 2,这是因为交互式命令行会绑定 stdin 与 stdout,这也是为什么你会停留在交互式命令行环境,而非终端。

相似 process.nextTicknet.listenfs.XXX 多种异步 API 都能够认为是一个 Active Handle,只有有相似的场景存在,过程就能始终在运行。

上边简略阐明了一下 Active Handle 是什么,后边会提到为什么这个指标会帮忙咱们排查到问题。

剖析问题

咱们在看我的项目代码的过程中,发现该项目标外围逻辑是做流量的转发,而实现这一性能的形式是通过两个 Socket 相互绑定来做到的,具体代码:

export function pipeSocket(from: Socket, to: Socket) {
  from.on('data', chunk => {to.write(chunk)
  })
  from.on('close', () => {to.destroy()
  })
}

看似没啥故障,不过联合着咱们前边所看到的 active handle 数量非正常稳定,咱们有理由狐疑和这里无关。
同时咱们在指标异样的时候在服务器上进行问题的排查,发现了一些端倪。
咱们通过执行 netstat -an | awk '/^tcp/ {++y[$NF]} END {for(w in y) print w, y[w]}' 来查看以后连贯辨别类型的数量统计,失去了相似这样的后果:

能够看到其中 ESTABLISHED 类型的数量十分多,这个其实与我最开始的猜想有差别,我本认为会是常见的 CLOSE_WAIT、TIME_WAIT 问题,没想到会是 ESTABLISHED 数量异样。
在 TCP 连贯的状态定义中 ESTABLISHED 代表了一个曾经建设胜利的连贯,能够了解为一个失常的数据传输状态:

然而同时存在这么多的传输中的连贯显然不是一个失常的状态,所以咱们通过执行 netstat -nat|grep ESTABLISHED|awk '{print$5}'|awk -F : '{print$1}'|sort|uniq -c 来进一步查看到底是哪些 IP 所占据的连贯最多,果不其然发现是 127.0.0.1,这是因为该项目标代理逻辑就是通过转发到本地某个特定端口的服务来实现的,理论代理逻辑由该服务来提供。

因 IP 敏感性所以不贴图了。
大抵状况就是查出来了大略几十条数据,而 127.0.0.1 一条数据对应的数量超过了 2W。

接下来咱们针对 127.0.0.1 进行进一步的排查,咱们要找出为什么会有这么多的连贯处于一个传输中的状态,为什么这些连贯没有被敞开。

所以咱们通过执行 ss -aoen | grep '127.0.0.1' | grep 'ESTAB' | tail -n 10 来抽样失去前十个相干的 Socket 统计信息,在这里咱们发现了一些端倪,在统计信息的最初一列详细信息中,咱们发现好多 Socket 并没有超时设置。

这个就比拟令人纳闷,因为咱们零碎其实是设置了 keep alive 的,如果对端数据曾经不再传输,那么连贯应该只会保留 2 小时(咱们零碎设置的为 7200),按理说两个小时也不会产生如此数量的连贯。
通过上边的 ss 命令失去的后果也帮咱们更确定了一点,有 socket 没有失常开释,始终处于 ESTABLISHED 的状态,为了统计精确的数据,咱们别离输出下边两条命令,依照是否蕴含 timer 来辨别统计:

ss -aoen | grep '127.0.0.1' | grep 'ESTAB' | grep -v 'timer:' | wc -l # 28636
ss -aoen | grep '127.0.0.1' | grep 'ESTAB' | grep 'timer:' | wc -l    # 115

数量差距十分可怕,咱们再通过采样找到其中的几个 ss 端口号,通过 lsof -p < 过程 ID> | grep < 端口号 > 的形式筛选查看该文件描述符的信息。
再拿到 FD 列的具体值,并通过 ll /proc/< 端口号 >/fd/<FD> 的形式查看到创立日期,发现半天前的都有,这必定就超过了 keepalive 的检测时间。

根据上述信息,差不多是确定了问题出在哪。

修复问题

定位问题后咱们开始着手修复,因为指标曾经比拟明确,找到那些没有设置 keepalive 的中央,并增加 keepalive
这就又回到了前边比拟要害的那个函数上:

export function pipeSocket(from: Socket, to: Socket) {
  from.on('data', chunk => {to.write(chunk)
  })
  from.on('close', () => {to.destroy()
  })
}

如之前所提到的 Active Handle,Socket 也是其中一种,因为波及到一个连贯的建设,所以咱们通过前边的摸索后第一工夫聚焦到了这个函数上。
通过查看 net 模块的文档,咱们发现默认 Socket 是不会增加 keepalive 的:https://nodejs.org/api/net.ht…
所以简略的解决办法就是咱们在函数外部增加 Socket 的 setKeepAlive 操作。
趁着咱们曾经在看 net 模块文档了,所以咱们认真钻研了一下 Socket,发现不仅默认没有 keepalive,甚至说连 timeout 默认也是没有的。

顺带的咱们也追加了 timeout 的解决,这是因为该我的项目用做代理服务,全局所有的申请都会过一遍服务,难免会有用户 偶然、非主观、一不小心 拜访到一些非法资源,这会导致该申请始终处于一个 pending 的状态,所以咱们要增加 timeout 来避免这种状况的产生。

接下来再来说函数外部事件的解决,发现现有逻辑只解决了 close,但实际上 Socket 有着很多的事件,包含 errorendtimeout 等。
而即使咱们设置了 timeout,实际上 Socket 也不会主动敞开的,只是会触发 timeout 事件,真正的敞开须要咱们手动执行。
而且目前在 close 事件中采纳的是 destroy,而更举荐的做法则是应用 endend 会发送 FIN 到对端,而 destroy 则会间接销毁以后连贯,在事件触发上呢 end 会触发 endclose,而 destroy 只会触发 close

所以通过咱们上述的改变后,函数变成了这个样子:

export function pipeSocket(from: Socket, to: Socket) {from.setTimeout(60 * 1e3)
  from.setKeepAlive(true, 60 * 1e3)
  from.on('data', chunk => {to.write(chunk)
  })
  from.on('close', () => {to.end()
  })
  from.on('error', () => {to.end()
  })
  from.on('end', () => {to.end()
  })
  from.on('timeout', () => {from.destroy()
  })
}

验证问题

将上述代码批改并提交后,试跑了一段时间,再次通过命令查看 TCP 连贯数量:

ss -aoen | grep '127.0.0.1' | grep 'ESTAB' | grep -v 'timer:' | wc -l # 191
ss -aoen | grep '127.0.0.1' | grep 'ESTAB' | grep 'timer:' | wc -l    # 261

再次通过 netstat -an | awk '/^tcp/ {++y[$NF]} END {for(w in y) print w, y[w]}' 验证 TCP 各个状态下的连贯数量:

TIME_WAIT 虽说看着很多,然而与之前的 ESTABLISHED 不同,它并非始终存在,因为申请多,所以会始终敞开、创立 循环,所以每次输出命令时都会看到很多 TIME_WAIT 状态的,这是 TCP 连贯敞开的失常状态。

内存指标与咱们关注的 Active Handle 指标均处于一个失常的状态:


总结

总结一下本次排障所遇到的问题,次要是 Socket 的应用姿态问题,没有及时开释资源。

  1. Socket 没有设置超时工夫
  2. Socket 没有设置 KeepAlive
  3. Socket 状态监听不欠缺
  4. Socket Destroy 是一个非优雅的敞开形式

将上述几项解决后,所遇到的用户无法访问、访问速度迟缓、被迫定时重启等问题都解决了。

正文完
 0