TOC

Node Socket 编程 EMFILE 错误的一种情况

本月,听了同事做的一次技术分享,觉得很有意思的问题,我在这里隐去业务细节,只保留技术部分,做个总结归纳,最后用一个业务无关的脚本来模拟一下这个过程。

同事的分享就好比是先逐步实验发现一个现象,然后研究出他背后的原理是什么。我在这里作为事后的归纳总结,就直接冲着背后的原理说了。

重点: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:

其实答案很勉强,其实是四次挥手都结束了,连接已经断开,不过是服务器端没有释放连接而已。

第二步:排除法

是什么导致连接没有释放呢?

  1. 调用其他服务时的 BUG
  2. 连接超时
  3. 并发量太大
  4. 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();
        // ...
    }
}

我们遇到的问题就和这段逻辑有关。

梳理一下逻辑,概括一下:

  1. 在 SMTP 协议的 DATA 命令和数据都传输完成之后,执行 data_done
    注意:这里 pause 了,data 时间不会触发了,也就是说对于应用来说,客户端来的所有数据都不可见了
  2. 服务器在 SMTP 协议的 DATA 命令之后,执行一些必须放在此处的业务逻辑
  3. 最终,服务器决定返回一个错误信息,比如 “552 5.2.2 user quota exceeded”
  4. 然后调用 disconnect 方法,意图中断连接
  5. 然后会调用 disconnect_respond (socket.end 方法发出 FIN 包)
  6. 如果超时就会触发上面那个绑定在 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 的连接没有正常关闭。

总结

  1. 问题出现的原因:pause 之后 end,导致客户端发过来的数据滞留缓冲区,从而导致连接没有释放
    据说老版本之所以没有这个问题是因为 nodejs 早期版本 end 之后会自动清理缓存(存疑)
  2. 要解决这个问题,有两种方案:
  3. 超时之后消费掉数据,然后连接自动释放
  4. 超时之后判断连接关闭,然后手动 destroy

留下的疑问

  1. 以下几个缓冲区之间是一种什么样子的关联:
    1. NodeJS 的缓冲区(socket.bufferSize / writable.writableLength)
    2. Socket 接口(python: sock.setsockopt(SOL_SOCKET, SO_SNDBUF, 32 * 1024), SO_RECVBUF 同样)
    3. Linux 协议栈缓冲区(可以用 ioctl 修改,或改 /proc 下的指定文件)
    4. 网卡 DMA 缓冲

参考资料与拓展阅读