Node.js 记一次Docker中排查Egg.js项目内存泄漏和异常访问的处理过程，解决Connection timed out和xmldom error
问题简述
在线上环境中，发现服务器内存在缓慢下降，疑似内存泄漏，且CPU占用较高，表现有点异常。并且egg.js部署的web站点响应异常，请求nginx代理后的端口，请求不通，最终会被代理到下一个正常节点。而如果是通过直连的形式，反而可以正常访问。重启站点之后，内存和CPU恢复正常。
处理过程
日志排查
查看nginx的错误日志，发现有大量的 Connection timed out ，出现这种报错的时候，web站点就无法访问，需要重启站点才可以正常访问。
[error] 12#12: *5170 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.1.101
而这种情况，先判断是不是防火墙问题，可能因为设置规则有问题，导致数据包无法正常传输。
由于采用的是docker部署，不同容器相互访问就有可能存在这种情况。
nginx容器和web容器都在本机的话，需要开通容器之间的防火墙。否则就会出现这种报错，无法访问站点。
查看容器IP，docker inspect 容器名，确认已经开放容器之间防火墙。
防火墙是通的，在重启web容器之后，就能正常访问，继续思考为什么。
查看web站点的日志，没有错误输出，也没有异常日志，而且通过直连是可以访问的，可以认为站点本身没问题。
既然站点是正常的，nginx也是正常，那有可能是docker的问题，查一下docker日志。
$ docker logs 容器名 --tail 500
tips: 如果不加
--tail，会从头到尾输出全部，而往往日志会很多，不利于查找，使用–tail，输出最近的500行日志
查看nginx容器日志，没有什么特别的，再看看web容器日志，发现有这些错误信息，开始有点儿进展。
[xmldom error] element parse error: TypeError: source.indexOf is not a function @#[line:0,col:undefined]
但是这些日志，并没有明确告诉是哪里有问题，而且日志在不断地增长。
通过搜索引擎并没有得到有用的信息，尝试用其他地方进行入手。
通过了解docker日志，除了通过 logs 命令，容器还有映射在主机上的日志文件，这个文件路径通过 inspect 命令可以找到
docker inspect 容器名
在输出中找到 LogPath ，这个文件就是存放日志内容，路径一般为 /var/lib/docker/containers/xxx/xxx-json.log，xxx为容器id，查看这个文件内容，从中也不能找到相关信息，错误信息和容器日志一样，只是增加了日期。
$ tail -n 100 /var/lib/docker/containers/xxx/xxx-json.log
{"log":"[xmldom error]\u0009element parse error: TypeError: source.indexOf is not a function \n","stream":"stderr","time":"2020-07-01T00:00:00.000Z"}
{"log":"@#[line:0,col:undefined]\n","stream":"stderr","time":"2020-07-01T00:00:00.000Z"}
进程排查
通过命令 docker stats 可以看到内存和CPU占用都很高，就想到要查一下是什么进程占用这么高，在容器内执行命令查看进程结果：
$ docker exec 容器名 ps -aux
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 88181 1.5 0.8 847296 51996 ? Ssl 23:34 0:00 node /home/egg/node_modules/egg-scripts/lib/start-cluster {"title":"egg-server-egg","baseDir":"/home/egg","framework":"/home/egg"
root 88188 1.3 0.8 893392 48784 ? Sl 23:34 0:00 /usr/local/lib/node-v10.16.0-linux-x64/bin/node /home/egg/node_modules/egg-cluster/lib/agent_worker.js {"framework":"/home/egg/node_modules/egg"
root 88199 2.6 0.7 910332 48668 ? Sl 23:34 0:00 /usr/local/lib/node-v10.16.0-linux-x64/bin/node /home/egg/node_modules/egg-cluster/lib/app_worker.js {"framework":"/home/egg/node_modules/egg"
root 88200 2.6 62.0 8954840 637560 ? Sl 23:34 0:00 /usr/local/lib/node-v10.16.0-linux-x64/bin/node /home/egg/node_modules/egg-cluster/lib/app_worker.js {"framework":"/home/egg/node_modules/egg"
root 88207 2.6 0.7 910324 48760 ? Sl 23:34 0:00 /usr/local/lib/node-v10.16.0-linux-x64/bin/node /home/egg/node_modules/egg-cluster/lib/app_worker.js {"framework":"/home/egg/node_modules/egg"
root 88212 2.7 0.8 910828 49532 ? Sl 23:34 0:01 /usr/local/lib/node-v10.16.0-linux-x64/bin/node /home/egg/node_modules/egg-cluster/lib/app_worker.js {"framework":"/home/egg/node_modules/egg"
可以看到是 egg.js 的一个worker占用特别多，可以判定是web站点问题，把关注点转回后台代码上。
代码排查
这时候就要从错误日志入手了，首先从代码中全局查下 source.indexOf ，代码中没有使用到这样的方法，那只能是来源于 node_modules，在 node_modules 中查一下，有很多用过这个写法，不太好定位是哪里的问题。换 [xmldom error] 试一下，数量变少了，只有 plist 和xmldom 这两个包，而 plist 在项目中有用到，并且在这个包里面存在 source.indexOf 的语法，可以确定是 plist 这个包导致的报错，xmldom是plist的依赖。
接下来看使用过这个方法的代码，一顿排查猛如虎，一看代码都正确的，也无法复现异常。
查看plist源码，代码中只有使用过 parse 方法，在这个方法中调用了 xmldom 这个包，尽管在 plist 里面的 dist 文件夹有出现 [xmldom error]，但不是这个包的报错，来源于 xmldom。查看 parse 源码，调用了 xmldom 的方法。
// plist/lib/parse.js
var DOMParser = require('xmldom').DOMParser;
function parse (xml) {
var doc = new DOMParser().parseFromString(xml);
invariant(
doc.documentElement.nodeName === 'plist',
'malformed document. First element should be <plist>'
);
var plist = parsePlistXML(doc.documentElement);
// the root <plist> node gets interpreted as an Array,
// so pull out the inner data first
if (plist.length == 1) plist = plist[0];
return plist;
}
parseFromString 这个方法是在 xmldom/dom-parser.js 里面，并且这里没有出现 source.indexOf ，继续看下这个 sax 方法。
// xmldom/dom-parser.js
var XMLReader = require('./sax').XMLReader;
DOMParser.prototype.parseFromString = function(source,mimeType){
var options = this.options;
var sax = new XMLReader();
var domBuilder = options.domBuilder || new DOMHandler();//contentHandler and LexicalHandler
// 省略代码······
if(source){
sax.parse(source,defaultNSMap,entityMap);
}else{
sax.errorHandler.error("invalid doc source");
}
return domBuilder.doc;
}
xmldom/sax.js 文件就有出现 source.indexOf ，问题应该就是在这，这里报错之后，被下面的catch给捕获，并没有抛出错误给上层，而是修改位置继续执行，这里是 while(true)，也就是为什么会循环调用。看代码的话原来是有抛出来，在最新版本是被注释了，应该是有其他考虑。
// xmldom/sax.js
function parse(source,defaultNSMapCopy,entityMap,domBuilder,errorHandler){
// 省略代码······
while(true){
try{
var tagStart = source.indexOf('<',start);
if(tagStart<0){
if(!source.substr(start).match(/^\s*$/)){
var doc = domBuilder.doc;
var text = doc.createTextNode(source.substr(start));
doc.appendChild(text);
domBuilder.currentElement = text;
}
return;
}
// 省略代码······
}catch(e){
errorHandler.error('element parse error: '+e)
end = -1;
//throw e;
}
if(end>start){
start = end;
}else{
//TODO: 这里有可能sax回退，有位置错误风险
appendText(Math.max(tagStart,start)+1);
}
}
}
已经找到具体位置，反推回去看这个source如何变为空，在上层调用中，如果 source 为空，是不会调用 sax.js 的方法，那么只能是其他值。经过测试，Array，String类型才有 indexOf 方法，而Boolean，Date，Object类型会报错，错误提示就是 source.indexOf is not a function。
理解源码后，再去看项目中调用的地方，是通过http请求获取数据，该请求正常情况是返回一个字符串，如果不正常，那会返回一个对象，此时传进去就会导致死循环。
解决方案
找到问题后就能对症下药，在使用 plist.parse() 前进行判断类型，不是字符串则抛出异常。
if (typeof res !== 'string'){
// 抛出异常
}
const result = plist.parse(res);
经过分析，是因为源码中没有对传入数据进行参数校验，并且是死循环，一直阻塞进程，逐步消耗内存，占用大量cpu资源。
问题反思
-
为什么站点通过nginx无法访问，而直连可以访问
这是因为处理请求业务是由
egg.js的agent进行分发，随机发送给其中一个worker，而有一个worker进程陷入死循环，如果分配给它，请求并不会执行，会处于等待状态，直到超时，也就显示nginx的超时错误。没有分配给有问题的worker的话，能正常执行请求业务。 -
为什么站点日志没有错误日志输出
这是因为该错误是通过console.error()进行输出的，不会存在egg.js的日志文件里面，能通过docker容器查看日志。 -
为什么内存会缓慢下降
这是因为进程陷入死循环，在不停的执行，没有得到资源释放，在V8的垃圾回收机制中没有被回收。并且分配给这个worker的请求，会因为阻塞而无法得到释放，就会慢慢的消耗内存，只有重启才能恢复正常。
关于V8的垃圾回收机制可以看下这篇文档：Node.js V8引擎的内存管理和垃圾回收机制