Timeout Responding to `GETFDPW`

[kevincox]

It appears that in some cases, seemingly when some NSS module takes too long—which has been noticed to occur when the network state of the machine is changing—nsncd will fail to respond to GETFDPW requests resulting in a 5s hang until glibc times out and makes a GETPWBYUID request which succeeds fairly quickly.

Example log from ZSH startup:

     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

nsncd logs:

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 was original discussed on the nixpkgs bug tracker: NixOS/nixpkgs#402693

[Urie96]

> time sudo strace -r -o /tmp/ping.strace ping -c 1 wled-812520.local
PING wled-812520.local (192.168.2.121) 56(84) bytes of data.
64 bytes from 192.168.2.121: icmp_seq=1 ttl=255 time=3.52 ms

--- wled-812520.local ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 3.522/3.522/3.522/0.000 ms

________________________________________________________
Executed in   13.53 secs      fish           external
   usr time    0.06 millis    0.06 millis    0.00 millis
   sys time    7.74 millis    1.07 millis    6.66 millis

[01:21:51] urie@home-router /home/urie  
> grep -C 10 Timeout /tmp/ping.strace 
     0.000043 futex(0x7f84e140068c, FUTEX_WAKE_PRIVATE, 2147483647) = 0
     0.000041 openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 5
     0.000054 fstat(5, {st_mode=S_IFREG|0644, st_size=920, ...}) = 0
     0.000044 read(5, "# This is /run/systemd/resolve/s"..., 4096) = 920
     0.000054 read(5, "", 4096)         = 0
     0.000041 fstat(5, {st_mode=S_IFREG|0644, st_size=920, ...}) = 0
     0.000044 close(5)                  = 0
     0.000044 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5
     0.000052 connect(5, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
     0.000065 sendto(5, "\2\0\0\0\6\0\0\0\4\0\0\0\300\250\2y", 16, MSG_NOSIGNAL, NULL, 0) = 16
     0.000077 poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
     5.004646 close(5)                  = 0
     0.000111 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0444, st_size=256, ...}, 0) = 0
     0.000419 newfstatat(AT_FDCWD, "/", {st_mode=S_IFDIR|0755, st_size=158, ...}, 0) = 0
     0.000234 openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 5
     0.000137 fstat(5, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000082 read(5, "passwd:    files systemd\ngroup: "..., 4096) = 256
     0.000109 read(5, "", 4096)         = 0
     0.000052 fstat(5, {st_mode=S_IFREG|0444, st_size=256, ...}) = 0
     0.000040 close(5)                  = 0
     0.000043 openat(AT_FDCWD, "/nix/store/vbrdc5wgzn0w1zdp10xd2favkjn5fk7y-glibc-2.40-66/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)

I can always reproduce it.