本月,听了同事做的一次技术分享,觉得很有意思的问题,我在这里隐去业务细节,只保留技术部分,做个总结归纳,最后用一个业务无关的脚本来模拟一下这个过程。
同事的分享就好比是先逐步实验发现一个现象,然后研究出他背后的原理是什么。我在这里作为事后的归纳总结,就直接冲着背后的原理说了。
重点:NodeJS 网络服务对半连接的处理需要谨慎一些。
虽然本文所说的问题在其他场景下出现的可能性不大,但是还是可以看看,至少小心一点为好。
涉及的服务是用 Node 写的,最近做了一次升级,从超级老的 0.10 升级到较新的 Dubnium LTS (10.22) 😛。
然后发现问题了:
问题的外在表现就是服务夯住,乃至不可用,大量请求超时。
内在的,就是发现日志中有很多网络服务中常见的 EMFILE: too many open files
异常。
重点是,出现问题的节点都做过升级。
排查过程
第一步:锁定网络连接问题
一般遇到文件数超出限制,要么是文件打开没有关,要么是 socket 连接数超出最大限制。
ulimit -n
1000000
通过 lsof -p <pid>
可以发现是大量的网络连接,而且显示的和正常服务的不一样。
正常的服务应该是类似这样:
nodejs 4160164 catroll 21u IPv4 101071010 0t0 TCP localhost:8000->localhost:37192 (ESTABLISHED)
nodejs 4160164 catroll 22u IPv4 101071017 0t0 TCP localhost:8000->localhost:37194 (ESTABLISHED)
nodejs 4160164 catroll 23u IPv4 101071055 0t0 TCP localhost:8000->localhost:37198 (ESTABLISHED)
nodejs 4160164 catroll 24u IPv4 101067765 0t0 TCP localhost:8000->localhost:37200 (ESTABLISHED)
但是这次是这样:
nodejs 4165129 catroll 21u sock 0,9 0t0 101130600 protocol: TCP
nodejs 4165129 catroll 22u sock 0,9 0t0 101130618 protocol: TCP
nodejs 4165129 catroll 23u sock 0,9 0t0 101130633 protocol: TCP
Google 一下:lsof protocol tcp:
- SO, lsof shows protocol: TCP
- SO, In lsof output what are those 'sock' lines?
- Youtube, Unix & Linux: lsof shows protocol: TCP (2 Solutions!!)
答案都类似:没有显示连接详情的原因要么是进程在另一个 network namespace 中(容器技术),要么是连接还没有绑定到端口 (bind / listen / connect)
其实答案很勉强,其实是四次挥手都结束了,连接已经断开,不过是服务器端没有释放连接而已。
第二步:排除法
是什么导致连接没有释放呢?
- 调用其他服务时的 BUG
- 连接超时
- 并发量太大
- TLS 错误
... 跳过
第三部:strace -p
意外发现,lsof 看到的那些没有释放的连接,都有一个相同的特征:
write(24, "S: client end", 13) = 13
shutdown(24, SHUT_WR) = 0
read(24, "im the king of the world", 65536) = 24
上面是实验输出。
总之就是每次都是服务器给了同一个消息之后,断开连接(进入半连接状态),然后收到客户端发过来的一个消息。
再从这个消息发送位置入手去看就接近真相了。
问题原因
class Connection {
static setupClient (self) {
// https://github.com/haraka/Haraka/blob/v2.8.19/connection.js#L191~L196
self.client.on('timeout', () => {
if (self.state >= states.DISCONNECTING) return;
self.respond(421, 'timeout', function () {
self.fail(`${rhost} connection timed out`);
});
});
}
// https://github.com/haraka/Haraka/blob/v2.8.19/connection.js#L599~L633
disconnect () {
if (this.state >= states.DISCONNECTING) return;
const self = this;
self.state = states.DISCONNECTING;
self.current_data = null; // don't process any more data we have already received
this.reset_transaction(() => {
plugins.run_hooks('disconnect', self);
});
}
disconnect_respond () {
const logdetail = {
'ip': this.remote.ip,
'rdns': ((this.remote.host) ? this.remote.host : ''),
'helo': ((this.hello.host) ? this.hello.host : ''),
'relay': (this.relaying ? 'Y' : 'N'),
'early': (this.early_talker ? 'Y' : 'N'),
'esmtp': (this.esmtp ? 'Y' : 'N'),
'tls': (this.tls.enabled ? 'Y' : 'N'),
'pipe': (this.pipelining ? 'Y' : 'N'),
'errors': this.errors,
'txns': this.tran_count,
'rcpts': `${this.rcpt_count.accept}/${this.rcpt_count.tempfail}/${this.rcpt_count.reject}`,
'msgs': `${this.msg_count.accept}/${this.msg_count.tempfail}/${this.msg_count.reject}`,
'bytes': this.totalbytes,
'lr': ((this.last_reject) ? this.last_reject : ''),
'time': (Date.now() - this.start_time)/1000,
};
this.results.add({name: 'disconnect'}, {
duration: (Date.now() - this.start_time)/1000,
});
this.lognotice('disconnect', logdetail);
this.state = states.DISCONNECTED;
this.client.end();
}
// https://github.com/haraka/Haraka/blob/v2.8.19/connection.js#L689~695
pause () {
const self = this;
if (self.state >= states.DISCONNECTING) return;
self.client.pause();
if (self.state !== states.PAUSE_DATA) self.prev_state = self.state;
self.state = states.PAUSE_DATA;
}
// https://github.com/haraka/Haraka/blob/v2.8.19/connection.js#L1610
data_done () {
const self = this;
this.pause();
// ...
}
}
我们遇到的问题就和这段逻辑有关。
梳理一下逻辑,概括一下:
- 在 SMTP 协议的
DATA
命令和数据都传输完成之后,执行data_done
。
注意:这里 pause 了,data
时间不会触发了,也就是说对于应用来说,客户端来的所有数据都不可见了 - 服务器在 SMTP 协议的
DATA
命令之后,执行一些必须放在此处的业务逻辑 - 最终,服务器决定返回一个错误信息,比如 “552 5.2.2 user quota exceeded”
- 然后调用 disconnect 方法,意图中断连接
- 然后会调用 disconnect_respond (socket.end 方法发出 FIN 包)
- 如果超时就会触发上面那个绑定在 timeout 事件上的匿名函数
重点来了:FIN 包发出之后,服务器端的连接处于半关闭状态,这个时候客户端可能还在往服务器发送数据。比如 Python 的 smtplib 收到非 250 消息之后发出了一个 SMTP 的 RSET
命令:
# https://github.com/python/cpython/blob/v3.9.2/Lib/smtplib.py#L886~L892
(code, resp) = self.data(msg)
if code != 250:
if code == 421:
self.close()
else:
self._rset()
raise SMTPDataError(code, resp)
这个时候,服务器不知道用户发过来的数据(比如上面例子中的 RSET\r\n
),这个数据会一直留在缓冲区中。
猜想是由于缓冲区有数据没有处理完成导致 socket 没有正常关闭,验证一下,果然如此。
tcpserver.js
Download
const net = require('net')
const server = net.createServer({ 'allowHalfOpen': true }, function(client) {
let isClosed = false
client.setTimeout(3000)
// client.on('timeout', function() {
// console.log('timeout')
// if (isClosed) {
// // 方案 1
// // 会重新触发 data 事件
// // 避免导致别的问题,data 方法可能需要处理,如下面注释的那行
// client.resume()
// // 方案 2
// client.destroy()
// }
// })
client.on('data', function(data) {
// if (isClosed) { return }
let lines = data.toString().split('\n')
console.log(lines)
client.write('im the king of the world')
if (lines.indexOf('end') != -1) {
client.pause()
client.end()
isClosed = true
}
})
client.write('welcome')
});
server.listen(8000, 'localhost', function() { console.log('runing') })
tcpclient.js
Download
const net = require('net')
const client = net.createConnection({
'host': 'localhost',
'port': 8000,
'allowHalfOpen': true,
})
client.on('data', function(data) { console.log(data.toString()) })
client.on('end', function() { // get FIN
client.write('fine, u are boss')
client.end() // FIN
})
setTimeout(() => {
client.write('end') // tell server to close this connection
}, 500)
每一次运行就有有一个 PROTOCOL: TCP 的连接没有正常关闭。
总结
- 问题出现的原因:pause 之后 end,导致客户端发过来的数据滞留缓冲区,从而导致连接没有释放
据说老版本之所以没有这个问题是因为 nodejs 早期版本 end 之后会自动清理缓存(存疑) - 要解决这个问题,有两种方案:
- 超时之后消费掉数据,然后连接自动释放
- 超时之后判断连接关闭,然后手动 destroy
留下的疑问
- 以下几个缓冲区之间是一种什么样子的关联:
- NodeJS 的缓冲区(socket.bufferSize / writable.writableLength)
- Socket 接口(python:
sock.setsockopt(SOL_SOCKET, SO_SNDBUF, 32 * 1024)
, SO_RECVBUF 同样) - Linux 协议栈缓冲区(可以用 ioctl 修改,或改 /proc 下的指定文件)
- 网卡 DMA 缓冲
Update @ 2021-10-23
在 GitHub 上提交了一个 Issue: The socket cann't be release when disconnect after DATA command #2992
写这篇博客时就写好了,一直忘记提交,刚清理文件才想起来。
要是这大半年里面,新版本已经解决了这个问题,那就有点尴尬了。
参考资料与拓展阅读
- http://nodejs.cn/api/net.html#net_socket_end_data_encoding_callback
- http://nodejs.cn/api/net/socket_end_data_encoding_callback.html
- http://nodejs.cn/api/net/socket_pause.html
- http://nodejs.cn/api/stream/event_end.html
- http://nodejs.cn/api/net/event_timeout.html
- http://nodejs.cn/api/net/socket_timeout.html
- SMTP Error Code 552
- https://www.ibm.com/support/knowledgecenter/en/SSLTBW_2.3.0/com.ibm.zos.v2r3.hala001/setopt.htm#setopt__srcb04
- https://docs.microsoft.com/zh-cn/windows/win32/api/winsock/nf-winsock-setsockopt
- https://stackoverflow.com/questions/4257410/what-are-so-sndbuf-and-so-rcvbuf