TOC

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

作者： catroll
日期： 2021-01-31
标签： NodeJS 网络编程 Socket

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

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

重点：NodeJS 网络服务对半连接的处理需要谨慎一些。
虽然本文所说的问题在其他场景下出现的可能性不大，但是还是可以看看，至少小心一点为好。

涉及的服务是用 Node 写的，最近做了一次升级，从超级老的 0.10 升级到较新的 Dubnium LTS (10.22) 😛。

然后发现问题了：
问题的外在表现就是服务夯住，乃至不可用，大量请求超时。
内在的，就是发现日志中有很多网络服务中常见的 EMFILE: too many open files 异常。

重点是，出现问题的节点都做过升级。

排查过程

第一步：锁定网络连接问题

一般遇到文件数超出限制，要么是文件打开没有关，要么是 socket 连接数超出最大限制。

ulimit -n
1000000

通过 lsof -p <pid> 可以发现是大量的网络连接，而且显示的和正常服务的不一样。

正常的服务应该是类似这样：

nodejs 4160164 markjour 21u IPv4 101071010 0t0 TCP localhost:8000->localhost:37192 (ESTABLISHED)
nodejs 4160164 markjour 22u IPv4 101071017 0t0 TCP localhost:8000->localhost:37194 (ESTABLISHED)
nodejs 4160164 markjour 23u IPv4 101071055 0t0 TCP localhost:8000->localhost:37198 (ESTABLISHED)
nodejs 4160164 markjour 24u IPv4 101067765 0t0 TCP localhost:8000->localhost:37200 (ESTABLISHED)

但是这次是这样：

nodejs 4165129 markjour 21u sock 0,9 0t0 101130600 protocol: TCP
nodejs 4165129 markjour 22u sock 0,9 0t0 101130618 protocol: TCP
nodejs 4165129 markjour 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 之后会自动清理缓存（存疑）
要解决这个问题，有两种方案：
1. 超时之后消费掉数据，然后连接自动释放
2. 超时之后判断连接关闭，然后手动 destroy

留下的疑问

以下几个缓冲区之间是一种什么样子的关联：
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 缓冲

Update @ 2021-10-23
在 GitHub 上提交了一个 Issue: The socket cann't be release when disconnect after DATA command #2992
写这篇博客时就写好了，一直忘记提交，刚清理文件才想起来。
要是这大半年里面，新版本已经解决了这个问题，那就有点尴尬了。

参考资料与拓展阅读

发布于码厩技术博客的所有文章，除注明转载外，均为作者原创，欢迎转载，但必须注明出处。
尊重他人劳动，共创开源社区！转载请注明以下信息：
转载来源：码厩技术博客 [https://www.markjour.com]
原文标题：Node Socket 编程 EMFILE 错误的一种情况
原文地址：/article/20210131-nodejs-emfile-too-many-open-files.html

一	二	三	四	五	六	日