net: v20.3.1 dangling file descriptors when resolving "localhost".

[rednexela1941]

Version

v20.3.1

Platform

Linux stream 6.3.9-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 21 Jun 2023 20:46:20 +0000 x86_64 GNU/Linux

Subsystem

net

What steps will reproduce the bug?

Pick some unused port (so that connect will fail) and repeatedly attempt to connect using "localhost" hostname:

setInterval(() => {
  const stream = net.createConnection(
    1234 /* GARBAGE PORT */,
    'localhost'
  );
  stream.on('error', () => void 0 /* ECONNREFUSED */);
}, 1000);

The number of open file descriptors will continue to climb with each attempt. Switching from 'localhost' -> '127.0.0.1' and all opened fd's are closed after connection failure.

From strace, we see the socket(...) syscalls for AF_INET6 (::1) and AF_INET (127.0.0,1), but only the AF_INET6 related descriptor is closed after connection failure.

$ strace -f node localhost.js  2>&1 | perl -nE 'if (/STREAM/ || /close/ || /connect/) { print $_; }'
...
~~~~~~ AF_INET6 ~~~~~~~
[pid 192620] socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 18
[pid 192620] connect(18, {sa_family=AF_INET6, sin6_port=htons(1883), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
~~~~ IPV4 socket opened, but not closed (see 26, 27, 28, ... with no corresponding close) ~~~~
[pid 192620] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 26
[pid 192620] connect(26, {sa_family=AF_INET, sin_port=htons(1883), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
~~~~~ AF_INET6 fd closed ~~~~~~~
[pid 192620] close(18)                  = 0
[pid 192627] close(18)                  = 0
[pid 192627] socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 18
[pid 192627] connect(18, {sa_family=AF_UNIX, sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42) = -1 ENOENT (No such file or directory)
[pid 192627] close(18)                  = 0
[pid 192627] close(18)                  = 0
[pid 192627] connect(18, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
[pid 192627] close(18)                  = 0
[pid 192627] connect(18, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = 0
[pid 192627] close(18)                  = 0
[pid 192620] socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 18
[pid 192620] connect(18, {sa_family=AF_INET6, sin6_port=htons(1883), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 27
[pid 192620] connect(27, {sa_family=AF_INET, sin_port=htons(1883), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] close(18)                  = 0
[pid 192628] close(18)                  = 0
[pid 192629] close(18)                  = 0
[pid 192629] socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 18
[pid 192629] connect(18, {sa_family=AF_UNIX, sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42) = -1 ENOENT (No such file or directory)
[pid 192629] close(18)                  = 0
[pid 192629] close(18)                  = 0
[pid 192629] connect(18, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
[pid 192629] close(18)                  = 0
[pid 192629] connect(18, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = 0
[pid 192629] close(18)                  = 0
[pid 192620] socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 18
[pid 192620] connect(18, {sa_family=AF_INET6, sin6_port=htons(1883), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 28
[pid 192620] connect(28, {sa_family=AF_INET, sin_port=htons(1883), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] close(18)                  = 0
[pid 192630] close(18)                  = 0
[pid 192630] socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 18
[pid 192630] connect(18, {sa_family=AF_UNIX, sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42) = -1 ENOENT (No such file or directory)
[pid 192630] close(18)                  = 0
[pid 192630] close(18)                  = 0
[pid 192630] connect(18, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
[pid 192630] close(18)                  = 0
[pid 192630] connect(18, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = 0
[pid 192630] close(18)                  = 0
[pid 192620] socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 18
[pid 192620] connect(18, {sa_family=AF_INET6, sin6_port=htons(1883), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 29
[pid 192620] connect(29, {sa_family=AF_INET, sin_port=htons(1883), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
[pid 192620] close(18)                  = 0
[pid 192627] close(18)                  = 0
[pid 192627] socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 18
[pid 192627] connect(18, {sa_family=AF_UNIX, sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42) = -1 ENOENT (No such file or directory)
[pid 192627] close(18)                  = 0
[pid 192627] close(18)                  = 0
[pid 192627] connect(18, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
[pid 192627] close(18)                  = 0
[pid 192627] connect(18, {sa_family=AF_INET6, sin6_port=htons(0), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = 0
[pid 192627] close(18)                  = 0
[pid 192620] socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 18
[pid 192620] connect(18, {sa_family=AF_INET6, sin6_port=htons(1883), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
...

lsof -p will show a similar result, with climbing file descriptors.

How often does it reproduce? Is there a required condition?

See above.

What is the expected behavior? Why is that the expected behavior?

I'd expected unused sockfd's to be closed.

What do you see instead?

See above. For example that logs the lsof count, you should be able to use:

#!/usr/bin/env node
const net = require('net');
const { exec } = require('child_process');

function log_fd_count() {
  exec(`/usr/bin/lsof -p ${process.pid}`, (err, stdout, stderr) => {
    if (err) {
      console.error(err, stdout, stderr);
      return;
    }
    const lines = stdout.trim().split('\n');
    console.log('lsof count:', lines.length > 1 ? lines.length - 1 : 0);
  });
}

setInterval(() => {
  const stream = net.createConnection(1234 /* unbound port */, 'localhost');
  stream.on('error', () => void 0);
}, 1000);
setInterval(() => {
  log_fd_count();
}, 1000);

$ node repro.js
lsof count: 47
lsof count: 49
lsof count: 50
lsof count: 51
lsof count: 52
lsof count: 53
lsof count: 54
lsof count: 55
lsof count: 56
...

Additional information

Issue is resolved on more recent main branch 5da84a6 but I didn't see any commits that explicitly address this (I would be curious to see this if I missed it).

My naive guess would be that:

afterConnect seems to destroy/close failed out fd's.

node/lib/net.js

Lines 1569 to 1584 in 9869bdc

	} else {
	let details;
	if (req.localAddress && req.localPort) {
	details = req.localAddress + ':' + req.localPort;
	}
	const ex = exceptionWithHostPort(status,
	'connect',
	req.address,
	req.port,
	details);
	if (details) {
	ex.localAddress = req.localAddress;
	ex.localPort = req.localPort;
	}
	self.destroy(ex);
	}

but afterConnectMultiple doesn't:

node/lib/net.js

Lines 1602 to 1622 in 9869bdc

	if (status !== 0) {
	let details;
	if (req.localAddress && req.localPort) {
	details = req.localAddress + ':' + req.localPort;
	}
	const ex = exceptionWithHostPort(status,
	'connect',
	req.address,
	req.port,
	details);
	if (details) {
	ex.localAddress = req.localAddress;
	ex.localPort = req.localPort;
	}
	ArrayPrototypePush(context.errors, ex);
	// Try the next address
	internalConnectMultiple(context, status === UV_ECANCELED);
	return;
	}

But I'm sure its not so simple. I'll poke around but if any net.js experts around here would be generous enough to offer an explanation I'd be grateful.

Cheers!

[mscdex]

Did you try 20.4.0?

[rednexela1941]

Did you try 20.4.0?

Not yet, but it does seem to be fixed on more recent versions of main.

[rednexela1941]

Did you try 20.4.0?

@mscdex It seems to be resolved in 20.4.0.