当前位置: 首页 > 后端技术 > Node.js

记得一个Node.jshttp服务的排查记录

时间:2023-04-04 01:04:32 Node.js

前言最近,我们团队接手了一个遗留项目,这是一个用Node.js语言编写的HTTP服务项目。项目的大体逻辑是通过Node.jsLogic实现一层proxy,做流量中转,增加一些关键埋点展示请求记录(还有一些高级用法,篡改请求相关数据,但是它有与此故障排除无关,因此我不会详细介绍)。我们刚接手的时候遇到的情况是,由于内存泄漏等不明原因,项目必须定时重启,否则用户在使用时会出现明显的延迟或者服务直接不可用。于是开始阅读源码,了解项目,分析问题原因并尝试修复,同时进行人肉运维。在调查过程中,该项目嵌入了关键指标,包括内存、CPU等指标,以及用户流量统计。我们看到了两个重要的指标:内存趋势中的活跃句柄数与最初获取的信息一致,存在内存泄漏问题,不到一个小时指标就因为服务重启而断崖式下跌。同样,下方的ActiveHandle指标也波动较大。下面简单介绍一下什么是ActiveHandle。这就引申出Node.js技术栈中经常涉及到的一个关键词:EventLoop。简单介绍一下EventLoop,简单说明一下EventLoop的工作模式。如果我们有一个文件并写了这样的代码:console.log('hello'),那么我们通过节点XXX运行这个文件,进程就会退出。而如果我们这样写一个文件:console.log('hello')setInterval(()=>{},1e3)通过节点XXX再次运行这个文件,终端会停留在进程中,不会退出,因为我们创建了一个定时器,定时器可以理解为一个ActiveHandle,而EventLoop的运行过程就是执行所有的同步代码,然后检测是否有ActiveHandle,如果检测不到则直接退出,如果有Handle,就会进入我们熟悉的EventLoop。我们可以通过一个非公开的API获取ActiveHandles的数量:process._getActiveHandles()console.log(process._getActiveHandles().length)//0如果我们通过节点XXX运行这样的代码,那么我们将得到一个0,而如果我们直接通过node进入交互式命令行,我们会发现这个值为2,这是因为交互式命令行会绑定stdin和stdout,这就是为什么你会停留在交互式命令行环境中,而不是一个终端。process.nextTick、net.listen和fs.XXX等各种异步API都可以视为ActiveHandle。只要有类似的场景,进程就可以一直运行。上面简单说明了什么是ActiveHandle,为什么这个指标会帮助我们排查问题,后面会提到。问题分析在查看项目代码的过程中,我们发现项目的核心逻辑是转发流量,而实现这个功能的方式是将两个Socket相互绑定。具体代码:exportfunctionpipeSocket(from:Socket,to:Socket){from.on('data',chunk=>{to.write(chunk)})from.on('close',()=>{to.destroy()})}看起来没什么问题,但是结合我们前面看到的活跃句柄数量的异常波动,我们有理由怀疑它有什么关系。同时,我们在各项指标异常的时候检查了服务器上的问题,发现了一些蛛丝马迹。我们执行netstat-an|awk'/^tcp/{++y[$NF]}END{for(winy)printw,y[w]}'查看当前连接类型数的统计,得到了一个结果类似这样:可以看到有很多ESTABLISHED类型。这其实和我最初的猜测不一样。本以为会是常见的CLOSE_WAIT和TIME_WAIT问题,没想到是ESTABLISHED的个数异常。在TCP连接的状态定义中,ESTABLISHED代表一个连接已经建立成功,可以理解为正常的数据传输状态:但是同时有那么多连接在传输显然不是正常状态,所以我们执行netstat-nat|grepESTABLISHED|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|对前十个相关的Socket统计信息进行采样。grep'127.0.0.1'|grep'ESTAB'|tail-n10,这里我们发现了一些端倪,在统计的最后一栏的详细信息中,我们发现很多Sockets并没有超时设置。这更令人困惑,因为我们的系统实际上设置为保持活动状态。如果对端数据不再传输,连接应该只保持2小时(我们的系统设置为7200)。不会有那么多的连接。通过上面ss命令得到的结果,也帮助我们更加确定。有些socket没有正常释放,一直处于ESTABLISHED状态。为了统计准确的数据,我们分别输入以下两条命令,根据是否包含定时器来区分统计信息:ss-aoen|grep'127.0.0.1'|grep'ESTAB'|grep-v'定时器:'|wc-l#28636ss-aoen|grep'127.0.0.1'|grep'ESTAB'|grep'定时器:'|wc-l#115数量上的差距是可怕的。然后我们通过采样找到几个ss端口号,使用lsof-p|grep过滤查看文件描述符信息。然后获取FD列的具体值,通过ll/proc//fd/查看创建日期,发现有半天前,肯定超过了keepalive检测时间。根据以上信息,差不多可以确定问题出在哪里了。修复问题定位问题后,开始修复,因为目标比较明确,找到那些没有设置keepalive的地方,加上keepalive。这就回到了上面那个比较关键的函数:exportfunctionpipeSocket(from:Socket,to:Socket){from.on('data',chunk=>{to.write(chunk)})from.on('close',()=>{to.destroy()})}前面说到ActiveHandle,Socket也是其中之一,因为涉及到连接的建立,所以我们通过前面的探索和第一时间的重点这个功能。通过查看net模块的文档,发现默认的Socket是没有添加keepalive的:https://nodejs.org/api/net.ht...所以简单的解决方法就是在里面添加Socket的setKeepAlive操作功能。一边看net模块文档,一边仔细研究Socket,发现不仅默认没有keepalive,连timeout都默认没有。对了,我们也加入了超时处理,因为这个项目是做代理服务的,所有的全局请求都会经过这个服务一次,难免有些用户会偶尔的、非主观的、不小心访问到一些非法的资源,这会导致请求一直处于pending状态,所以我们需要加一个timeout来防止这种情况发生。接下来说说函数内部事件的处理,发现现有逻辑只处理close,但实际上Socket有很多事件,包括error、end、timeout等。而且就算我们设置了timeout,Socket不会自动关闭,而是会触发timeout事件,实际关闭需要手动执行。而且close事件目前使用的是destroy,比较推荐的方法是使用end。end会发送FIN给对端,destroy会直接销毁当前连接。在事件触发中,end会触发end和close。并且销毁只会触发关闭。所以经过我们上面的改动之后,函数就变成了这样:,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'定时器:'|wc-l#191ss-aoen|grep'127.0.0.1'|grep'ESTAB'|grep'定时器:'|wc-l#261再次通过netstat-an|awk'/^tcp/{++y[$NF]}END{for(winy)printw,y[w]}'验证TCP各个状态下的连接数:TIME_WAIT看起来很多,但不像之前的ESTABLISHED,并不是一直存在的,因为请求多了,它会一直关闭,造成循环,所以每次输入命令都会看到很多TIME_WAIT状态,这是TCP连接的正常状态关闭。我们关心的memoryindicator和ActiveHandleindicator都处于正常状态:总结一下这次排查遇到的问题,主要是Socket的使用姿势,没有及时释放资源。Socket没有设置超时时间Socket没有设置KeepAliveSocket状态监控不完善SocketDestroy是一种非优雅的关闭方式经过以上几项处理后,用户遇到的无法访问,访问速度慢,和被强制定时重启都解决了。