Sparodic Hang from nscd.

[kevincox]

I am still diagnosing this but I have noticed it rarely when opening a new terminal. The terminal hangs for a while before the shell loads. This seems to happen most often when I don't have a working internet connection but due to the sporadic nature I haven't been able to confirm this.

I have managed to track down the source to nscd. This is a snippet from strace -r zsh -i -c exit:

     0.000089 getppid()                 = 7445
     0.000048 getpid()                  = 7447
     0.000047 getuid()                  = 1000
     0.000064 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000082 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000230 sendto(11, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000246 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
     5.004649 close(11)                 = 0
     0.000249 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000113 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000149 sendto(11, "\2\0\0\0\1\0\0\0\5\0\0\0001000\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
     0.000121 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLERR|POLLHUP}])
     1.373307 read(11, 0x7ffd8b2dc4d0, 36) = -1 ECONNRESET (Connection reset by peer)
     0.000456 close(11)                 = 0
     0.000302 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0444, st_size=256, ...}, 0) = 0
     0.000323 newfstatat(AT_FDCWD, "/", {st_mode=S_IFDIR|0755, st_size=4096, ...}, 0) = 0
     0.000068 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 11
     0.000143 fstat(11, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000124 read(11, "passwd:    files systemd\ngroup: "..., 4096) = 256
     0.000131 read(11, "", 4096)        = 0
     0.000074 fstat(11, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000058 close(11)                 = 0
     0.000106 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 11
     0.000078 fstat(11, {st_mode=S_IFREG|0644, st_size=11018, ...}) = 0
     0.000051 lseek(11, 0, SEEK_SET)    = 0
     0.000055 read(11, "root:x:0:0:System administrator:"..., 4096) = 4096
     0.000130 close(11)                 = 0

You can see that a request 11 (\v) which seems to correspond to GETFDPW takes 5s before the client gives up waiting.

I appear to be using nsncd which NixOS defaults to. I notice that this command intentionally does not respond:

https://github.com/twosigma/nsncd/blob/81615a8473d8bf3e422a03407e9fcf42712094ed/src/handlers.rs#L720-L727

It claims "Luckily clients fall back to explicit queries if no FDs are sent over." which is technically true, but it seems that this is after some timeout. I haven't read the code very carefully though, so I don't understand the exact behaviour that nsncd is performing.

So quite possibly this is an upstream issue, but the fact that this affects the default NixOS config and may be a configuration issue I have decided to open it here first.

glibc (or whatever is in zsh) then follows up with a GETPWBYUID request. But even this takes 1.4s before ECONNRESET for an unclear reason.

---

For reference here is a "normal" zsh startup.

     0.000069 getppid()                 = 8164
     0.000037 getpid()                  = 8166
     0.000037 getuid()                  = 1000
     0.000052 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000061 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000076 sendto(11, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000067 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLHUP}])
     0.000087 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="", iov_len=7}, {iov_base="", iov_len=8}], msg_iovlen=2, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 0
     0.000064 close(11)                 = 0
     0.000045 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000042 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000049 sendto(11, "\2\0\0\0\1\0\0\0\5\0\0\0001000\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
     0.000050 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLHUP}])
     0.000519 read(11, "\2\0\0\0\1\0\0\0\t\0\0\0\2\0\0\0\350\3\0\0d\0\0\0\n\0\0\0\17\0\0\0"..., 36) = 36
     0.000262 read(11, "kevincox\0x\0Kevin Cox\0/home/kevin"..., 67) = 67
     0.000256 close(11)                 = 0

Interestingly there is a response there, so IDK how this "no response" in the handler works.

[kevincox]

I managed to reproduce this for bash as well. So it likely affects any program using glibc that looks up this info.

     0.000047 uname({sysname="Linux", nodename="kevinyoga", ...}) = 0
     0.000060 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
     0.000063 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000094 sendto(3, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000209 poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
     5.005644 close(3)                  = 0
     0.000230 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
     0.000598 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000176 sendto(3, "\2\0\0\0\1\0\0\0\5\0\0\0001000\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
     0.000123 poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN|POLLERR|POLLHUP}])
     4.993978 read(3, 0x7ffd0ff3a0b0, 36) = -1 ECONNRESET (Connection reset by peer)
     0.000770 close(3)                  = 0
     0.000254 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0444, st_size=256, ...}, 0) = 0
     0.000459 newfstatat(AT_FDCWD, "/", {st_mode=S_IFDIR|0755, st_size=4096, ...}, 0) = 0
     0.000210 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
     0.000096 fstat(3, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000088 read(3, "passwd:    files systemd\ngroup: "..., 4096) = 256
     0.000095 read(3, "", 4096)         = 0
     0.000057 fstat(3, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000093 close(3)                  = 0
     0.000064 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
     0.000082 fstat(3, {st_mode=S_IFREG|0644, st_size=11018, ...}) = 0
     0.000090 lseek(3, 0, SEEK_SET)     = 0
     0.000060 read(3, "root:x:0:0:System administrator:"..., 4096) = 4096
     0.000077 close(3)                  = 0

[kevincox]

cc nsncd maintainers: @flokli @picnoir

[picnoir]

Just to be sure we're looking at the right direction before digging more into that, can you reproduce this timeout with nscd?

services.nscd.enableNsncd = false

[kevincox]

I have tried to reproduce with services.nscd.enableNsncd = false and haven't managed. Due to the sparaodic nature I can't be sure but it seems very likely that it is specific to nsncd.

Here is a trace from zsh on glibc nscd.

     0.000077 getppid()                 = 6504
     0.000037 getpid()                  = 6506
     0.000038 getuid()                  = 1000
     0.000053 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000061 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000091 sendto(11, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000078 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLHUP}])
     0.000317 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="passwd\0", iov_len=7}, {iov_base="\310O\3\0\0\0\0\0", iov_len=8}], msg_iovlen=2, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[12]}], msg_controllen=20, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 15
     0.000247 mmap(NULL, 217032, PROT_READ, MAP_SHARED, 12, 0) = 0x7f3d09c5c000
     0.000139 close(12)                 = 0
     0.000035 close(11)                 = 0

You can see that it returns actual data and sockets rather than just nulls or hanging.

[kevincox]

I switched back to nsncd and this time noticed a log message around the time of the failure:

Starting Name Service Cache Daemon (nsncd)...
Apr 29 19:24:11.253 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket"
Started Name Service Cache Daemon (nsncd).
Apr 29 19:29:25.645 ERRO timed out waiting for an available worker, thread: accept
Apr 29 19:29:25.645 INFO shutting down

This seems to be happen when the network is transitioning in some way. I have been reproducing by switching a WireGuard VPN on and off. It seems to most often happen when the VPN is in the "connecting" state.

[kevincox]

Hmm, it appears that something in regular nscd can also hang on the network despite me not having any sort of network users or similar. However it handles this a lot better, only hanging for 1.4s.

     0.000054 getppid()                 = 20946
     0.000026 getpid()                  = 20948
     0.000025 getuid()                  = 1000
     0.000036 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000238 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000213 sendto(11, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000143 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLHUP}])
     1.369531 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="passwd\0", iov_len=7}, {iov_base="\310O\3\0\0\0\0\0", iov_len=8}], msg_iovlen=2, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[12]}], msg_controllen=20, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 15
     0.000373 mmap(NULL, 217032, PROT_READ, MAP_SHARED, 12, 0) = 0x7f13f787a000
     0.000137 close(12)                 = 0
     0.000049 close(11)                 = 0

[kevincox]

My nsswitch.conf seems pretty boring:

% cat /etc/nsswitch.conf
passwd:    files systemd
group:     files [success=merge] systemd
shadow:    files
sudoers:   files

hosts:     mymachines resolve [!UNAVAIL=return] files myhostname dns
networks:  files

ethers:    files
services:  files
protocols: files
rpc:       files

[flokli]

This looks like nsncd workers can get stuck if requests take too long. Maybe there can be some (short) timeout mechanism there.

Can you open an issue at nsncd upstream?

[kevincox]

Yeah, it seems that there are two mostly independent issues:

1. One of the NSS modules hangs in some network conditions.
2. nsncd workers can get stuck when the modules hang.

I'll file an upstream issue for 2. But it would also be nice to track down 1.

[picnoir]

So, I've been trying to investigate that on my system. I've added some timing informations to nsncd on this branch: https://github.com/picnoir/nsncd/tree/pic/handler-timings

Opening a new zsh shell, nsncd does not seem to hang:

mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG handling request, request: Request { ty: GETFDPW, key: [112, 97, 115, 115, 119, 100, 0] }, request_type: GETFDPW, thread: worker_2
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG received GETFD* request, ignoring, request_type: GETFDPW, thread: worker_2
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG request handled, elapsed: 5.59µs, request_type: GETFDPW, thread: worker_2
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG accepted connection, stream: UnixStream { fd: FileDesc(OwnedFd { fd: 5 }), local: "/var/run/nscd/socket" (pathname), peer: (unnamed) }, thread: worker_3
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG handling request, request: Request { ty: GETPWBYUID, key: [49, 48, 48, 48, 0] }, request_type: GETPWBYUID, thread: worker_3
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG got user, user: Some(User { name: "ninjatrappeur", passwd: "x", uid: Uid(1000), gid: Gid(100), gecos: "ninjatrappeur", dir: "/home/ninjatrappeur", shell: "/run/current-system/sw/bin/zsh" }), request_type: GETPWBYUID, thread: worker_3
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.326 DEBG request handled, elapsed: 125.138µs, request_type: GETPWBYUID, thread: worker_3
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.330 DEBG accepted connection, stream: UnixStream { fd: FileDesc(OwnedFd { fd: 4 }), local: "/var/run/nscd/socket" (pathname), peer: (unnamed) }, thread: worker_4
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.330 DEBG handling request, request: Request { ty: GETPWBYUID, key: [] }, request_type: GETPWBYUID, thread: worker_4
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.330 DEBG got user, user: Some(User { name: "ninjatrappeur", passwd: "x", uid: Uid(1000), gid: Gid(100), gecos: "ninjatrappeur", dir: "/home/ninjatrappeur", shell: "/run/current-system/sw/bin/zsh" }), request_type: GETPWBYUID, thread: worker_4
mai 14 14:41:36 framework nsncd[310397]: May 14 12:41:36.330 DEBG request handled, elapsed: 77.796µs, request_type: GETPWBYUID, thread: worker_4

getfdpw is resolved quite fast (5µs). I tried opening that quite a few time without much variance.

My nssswitch is as boring as yours:

passwd:    files systemd
group:     files [success=merge] systemd
shadow:    files
sudoers:   files

hosts:     mymachines resolve [!UNAVAIL=return] files myhostname dns
networks:  files

ethers:    files
services:  files
protocols: files
rpc:       files

I tried disconnecting my computer from the network. I don't see much variance in the timings aside from the getai/gethostbyname requests who now seem to timeout after ~2ms.

I did not manage to reproduce the 5s hang on the zsh side either despite many attempts. Network available or not. :(

[kevincox]

Yeah, I wish I could figure out how to reproduce this reliability. It isn't as simple as network available or not available. It seems to be in states of transition such as when a VPN was connecting. But couldn't reliably trigger it. I also tried a few firewall rules to simulate it but couldn't get it to work. I had to try dozens of times to get it to reproduce.

[picnoir]

Could you run nsncd in debug mode for a while (using the above branch) on your setup. Maybe we'll get some clues out of it.

[kevincox]

I managed to reproduce with that version.

     0.000034 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000036 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000047 sendto(11, "\2\0\0\0\v\0\0\0\7\0\0\0passwd\0", 19, MSG_NOSIGNAL, NULL, 0) = 19
     0.000043 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
     5.004293 close(11)                 = 0
     0.000050 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
     0.000048 connect(11, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000067 sendto(11, "\2\0\0\0\1\0\0\0\5\0\0\0001000\0", 17, MSG_NOSIGNAL, NULL, 0) = 17
     0.000059 poll([{fd=11, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=11, revents=POLLIN|POLLERR|POLLHUP}])
     3.456846 read(11, 0x7fff633f71e0, 36) = -1 ECONNRESET (Connection reset by peer)
     0.000245 close(11)                 = 0
     0.000262 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0444, st_size=256, ...}, 0) = 0
     0.000164 newfstatat(AT_FDCWD, "/", {st_mode=S_IFDIR|0755, st_size=4096, ...}, 0) = 0
     0.000106 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 11
     0.000147 fstat(11, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000100 read(11, "passwd:    files systemd\ngroup: "..., 4096) = 256
     0.000114 read(11, "", 4096)        = 0
     0.000077 fstat(11, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000081 close(11)                 = 0
     0.000086 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 11
     0.000098 fstat(11, {st_mode=S_IFREG|0644, st_size=11018, ...}) = 0
     0.000081 lseek(11, 0, SEEK_SET)    = 0
     0.000078 read(11, "root:x:0:0:System administrator:"..., 4096) = 4096
     0.000113 close(11)                 = 0

nscd.log

[flokli]

I don't think this is a nixos-specific issue, and it's best to discuss this over in twosigma/nsncd#158.