mdns resolution only works on the second try

[kirelagin]

Ok, so I have been living with this issue for a very long time now, I think I am finally fed up enough to start looking into it.

My setup:

• OpenWrt ap running umdns (this does not really matter) and publishing its mdns name as lechat.local
• My laptop with NixOS and services.avahi.nssmdns = true;

Here is what I see on my laptop:

› ping lechat.local
ping: lechat.local: System error
› ping lechat.local  
PING lechat.local ($ap) 56(84) bytes of data.
64 bytes from $ap ($ap): icmp_seq=1 ttl=64 time=10.9 ms
<...>

So, the symptom is: every time it tries to resolve an mdns name, it fails with “System error”, then if I retry immediately, it works. It will keep working as long as I retry within a certain period of time (no idea, a minute? maybe a couple of minutes?).

---

Here is what I’ve got so far.

I am pretty sure that the dns-sd is setup correctly outside of my laptop name resolution, i.e. Avahi sees everything:

› avahi-browse -at
+ wlp0s20f3 IPv6 lechat                                        _ssh._tcp            local
+ wlp0s20f3 IPv4 lechat                                        _ssh._tcp            local
<...>

and, in general, in tcpdump I see the ap correctly responding to mdns resolution requests with its name.

Generated nsswitch.conf:

<...>
hosts:     files mdns_minimal [NOTFOUND=return] mymachines dns mdns myhostname`
<...>

The weird thing is that I don’t see any mdns requests at all whenever I run either of the ping commands. However, I do see a regular dns request which takes some time and, I think, “System error” is printed once it fails:

root@lechat:~# tcpdump -i br-wan -n -vv '(host $laptop or host $ap) and (port 53 or port 5353)'
tcpdump: listening on br-wan, link-type EN10MB (Ethernet), capture size 262144 bytes
11:01:24.157270 IP (tos 0x0, ttl 64, id 51108, offset 0, flags [DF], proto UDP (17), length 82)
    $laptop.53843 > 1.1.1.1.53: [udp sum ok] 45562+ [1au] PTR? $ap.in-addr.arpa. ar: . OPT UDPsize=1200 (54)
11:01:24.170454 IP (tos 0x20, ttl 59, id 41245, offset 0, flags [DF], proto UDP (17), length 82)
    1.1.1.1.53 > $laptop.53843: [udp sum ok] 45562 NXDomain q: PTR? $ap.in-addr.arpa. 0/0/1 ar: . OPT UDPsize=1232 (54)
11:01:24.286164 IP (tos 0x0, ttl 255, id 20680, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [udp sum ok] 0 PTR (QM)? $ap.in-addr.arpa. (43)
11:01:25.302306 IP (tos 0x0, ttl 255, id 20784, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [udp sum ok] 0 PTR (QM)? $ap.in-addr.arpa. (43)
11:01:27.288300 IP (tos 0x0, ttl 255, id 22381, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [udp sum ok] 0 PTR (QM)? $ap.in-addr.arpa. (43)
11:01:29.169397 IP (tos 0x0, ttl 64, id 53011, offset 0, flags [DF], proto UDP (17), length 69)
    $laptop.40954 > 1.1.1.1.53: [udp sum ok] 40974+ [1au] A? lechat.local. ar: . OPT UDPsize=1200 (41)
11:01:29.169457 IP (tos 0x0, ttl 64, id 53012, offset 0, flags [DF], proto UDP (17), length 69)
    $laptop.40954 > 1.1.1.1.53: [udp sum ok] 59199+ [1au] AAAA? lechat.local. ar: . OPT UDPsize=1200 (41)
11:01:29.183826 IP (tos 0x20, ttl 59, id 37590, offset 0, flags [DF], proto UDP (17), length 144)
    1.1.1.1.53 > $laptop.40954: [udp sum ok] 40974 NXDomain* q: A? lechat.local. 0/1/1 ns: . SOA a.root-servers.net. nstld.verisign-grs.com. 2021111701 1800 900 604800 86400 ar: . OPT UDPsize=1232 (116)
11:01:29.183870 IP (tos 0x20, ttl 59, id 37591, offset 0, flags [DF], proto UDP (17), length 144)
    1.1.1.1.53 > $laptop.40954: [udp sum ok] 59199 NXDomain* q: AAAA? lechat.local. 0/1/1 ns: . SOA a.root-servers.net. nstld.verisign-grs.com. 2021111701 1800 900 604800 86400 ar: . OPT UDPsize=1232 (116)

To sum up, currently:

• My best theory is that mdns_minimal just returns nothing straight away and the resolution proceeds to dns.
• On the first try it waits for dns to return nothing and then fails with “System error”.
• On the second try the error is cached, it proceeds to mdns and is somehow able to resolve the name.
• I have no idea how it manages resolves the name, since I don’t see any mdns requests in the network.

[kirelagin]

uggggggh ok, now that I have taken a closer look at the tcpdump output... The very first request that happens is a PTR request to the upstream dns server(?) with the ip address of the ap(???). So, it knows the address already?

[kirelagin]

I replaced ping with a simple program that does getaddrinfo. Here is what I am getting:

› ./resolve google.com
AF_INET6: 2607:f8b0:4006:80f::200e
AF_INET: 142.250.80.46

› ./resolve lechat.local
ERROR: getaddrinfo => -11 (System error)
  errno = 16 (Device or resource busy)

› ./resolve lechat.local
AF_INET: $ap
AF_INET6: $ap_v6

tcpdump (form the laptop):

# First query:
12:06:00.755634 IP (tos 0x0, ttl 64, id 15092, offset 0, flags [DF], proto UDP (17), length 82)
    $laptop.33557 > 1.1.1.1.53: [bad udp cksum 0xc313 -> 0x2f05!] 1735+ [1au] PTR? $ap.in-addr.arpa. ar: . OPT UDPsize=1200 (54)
12:06:00.773512 IP (tos 0x20, ttl 59, id 57242, offset 0, flags [DF], proto UDP (17), length 82)
    1.1.1.1.53 > $laptop.33557: [udp sum ok] 1735 NXDomain q: PTR? $ap.in-addr.arpa. 0/0/1 ar: . OPT UDPsize=1232 (54)
12:06:00.875717 IP6 (flowlabel 0x2ed18, hlim 255, next-header UDP (17) payload length: 51) 2601:182:d040:de0:fe21:5827:d517:e76f.5353 > ff02::fb.5353: [bad udp cksum 0x18b7 -> 0x3f86!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:00.875840 IP (tos 0x0, ttl 255, id 40807, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [bad udp cksum 0xa202 -> 0xb63a!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:01.877142 IP6 (flowlabel 0x2ed18, hlim 255, next-header UDP (17) payload length: 51) 2601:182:d040:de0:fe21:5827:d517:e76f.5353 > ff02::fb.5353: [bad udp cksum 0x18b7 -> 0x3f86!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:01.877239 IP (tos 0x0, ttl 255, id 41186, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [bad udp cksum 0xa202 -> 0xb63a!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:03.879151 IP6 (flowlabel 0x2ed18, hlim 255, next-header UDP (17) payload length: 51) 2601:182:d040:de0:fe21:5827:d517:e76f.5353 > ff02::fb.5353: [bad udp cksum 0x18b7 -> 0x3f86!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:03.879233 IP (tos 0x0, ttl 255, id 41232, offset 0, flags [DF], proto UDP (17), length 71)
    $laptop.5353 > 224.0.0.251.5353: [bad udp cksum 0xa202 -> 0xb63a!] 0 PTR (QM)? $ap.in-addr.arpa. (43)
12:06:05.761132 IP (tos 0x0, ttl 64, id 16387, offset 0, flags [DF], proto UDP (17), length 69)
    $laptop.53190 > 1.1.1.1.53: [bad udp cksum 0xc306 -> 0xde15!] 12454+ [1au] A? lechat.local. ar: . OPT UDPsize=1200 (41)
12:06:05.761156 IP (tos 0x0, ttl 64, id 16388, offset 0, flags [DF], proto UDP (17), length 69)
    $laptop.53190 > 1.1.1.1.53: [bad udp cksum 0xc306 -> 0x82f6!] 35754+ [1au] AAAA? lechat.local. ar: . OPT UDPsize=1200 (41)
12:06:05.777055 IP (tos 0x20, ttl 59, id 24495, offset 0, flags [DF], proto UDP (17), length 144)
    1.1.1.1.53 > $laptop.53190: [udp sum ok] 12454 NXDomain* q: A? lechat.local. 0/1/1 ns: . SOA a.root-servers.net. nstld.verisign-grs.com. 2021111701 1800 900 604800 86400 ar: . OPT UDPsize=1232 (116)
12:06:05.784493 IP (tos 0x20, ttl 59, id 24498, offset 0, flags [DF], proto UDP (17), length 144)
    1.1.1.1.53 > $laptop.53190: [udp sum ok] 35754 NXDomain* q: AAAA? lechat.local. 0/1/1 ns: . SOA a.root-servers.net. nstld.verisign-grs.com. 2021111701 1800 900 604800 86400 ar: . OPT UDPsize=1232 (116)

# Second query:
(nothing)

So, pretty much the same as with ping.

[kirelagin]

Restarting nscd seems to flush that cache involved. So, resolve (fail), resolve (success), restart nscd, resolve (fail).

[kirelagin]

snippets from strace:

A request no nscd:

socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(3, "\2\0\0\0\r\0\0\0\6\0\0\0hosts\0", 18, MSG_NOSIGNAL, NULL, 0) = 18
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN|POLLHUP}])
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="hosts\0", iov_len=6}, {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=[4]}], msg_controllen=20, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 14
<...>
close(3)                                = 0

Another request (times out):

socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(3, "\2\0\0\0\16\0\0\0\r\0\0\0lechat.local\0", 25, MSG_NOSIGNAL, NULL, 0) = 25
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
close(3)                                = 0

Reading nsswitch.conf and some other files for some reason:

openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=233, ...}) = 0
read(3, "passwd:    files systemd\ngroup: "..., 4096) = 233
read(3, "", 4096)                       = 0
close(3)                                = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=78, ...}) = 0
openat(AT_FDCWD, "/etc/host.conf", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=9, ...}) = 0
read(3, "multi on\n", 4096)             = 9
read(3, "", 4096)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=78, ...}) = 0
read(3, "# Generated by resolvconf\nnamese"..., 4096) = 78
read(3, "", 4096)                       = 0
uname({sysname="Linux", nodename="kirXps", ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=78, ...}) = 0
close(3)                                = 0

NSS stuff starts:

openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_files.so.2", O_RDONLY|O_CLOEXEC) = 3
<...>
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=62, ...}) = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "127.0.0.1 localhost\n::1 localhos"..., 4096) = 62
read(3, "", 4096)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_mdns_minimal.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_mymachines.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 3
<...>
close(3)                                = 0
openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libresolv.so.2", O_RDONLY|O_CLOEXEC) = 3
<...>
close(3)                                = 0

DNS query:

socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 3
setsockopt(3, SOL_IP, IP_RECVERR, [1], 4) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("1.1.1.1")}, 16) = 0
poll([{fd=3, events=POLLOUT}], 1, 0)    = 1 ([{fd=3, revents=POLLOUT}])
sendmmsg(3, [{msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\351i\1\0\0\1\0\0\0\0\0\1\6lechat\5local\0\0\1\0\1\0\0"..., iov_len=41}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=41}, {msg_hdr={msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="Un\1\0\0\1\0\0\0\0\0\1\6lechat\5local\0\0\34\0\1\0\0"..., iov_len=41}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, msg_len=41}], 2, MSG_NOSIGNAL) = 2
poll([{fd=3, events=POLLIN}], 1, 5000)  = 1 ([{fd=3, revents=POLLIN}])
<...>

More NSS modules:

openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_mdns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/nix/store/jsp3h3wpzc842j0rz61m5ly71ak6qgdn-glibc-2.32-54/lib/libnss_myhostname.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)

And finally a failure.

So, IIUC, all these NSS failures are expected on NixOS, as all those modules are not installed to standard locations where NSS can find them. The modules are supposed to be loaded by nscd, and the real problem here is that it times out.

[kirelagin]

And here are snippets form the second resolution attemp:

socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = 0
sendto(3, "\2\0\0\0\r\0\0\0\6\0\0\0hosts\0", 18, MSG_NOSIGNAL, NULL, 0) = 18
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=3, revents=POLLIN|POLLHUP}])
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="hosts\0", iov_len=6}, {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=[4]}], msg_controllen=20, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 14
<...>
close(3)                                = 0

openat(AT_FDCWD, "/etc/gai.conf", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC, NETLINK_ROUTE) = 3
bind(3, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 0
getsockname(3, {sa_family=AF_NETLINK, nl_pid=1776650, nl_groups=00000000}, [12]) = 0
sendto(3, [{nlmsg_len=20, nlmsg_type=RTM_GETADDR, nlmsg_flags=NLM_F_REQUEST|NLM_F_DUMP, nlmsg_seq=1637169407, nlmsg_pid=0}, {ifa_family=AF_UNSPEC, ...}], 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20
recvmsg(3, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[[{nlmsg_len=76, nlmsg_type=RTM_NEWADDR, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, {ifa_family=AF_INET, ifa_prefixlen=8, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [[{nla_len=8, nla_type=IFA_ADDRESS}, inet_addr("127.0.0.1")], [{nla_len=8, nla_type=IFA_LOCAL}, inet_addr("127.0.0.1")], [{nla_len=7, nla_type=IFA_LABEL}, "lo"], [{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT], [{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=944, tstamp=944}]]], [{nlmsg_len=92, nlmsg_type=RTM_NEWADDR, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, {ifa_family=AF_INET, ifa_prefixlen=24, ifa_flags=0, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("wlp0s20f3")}, [[{nla_len=8, nla_type=IFA_ADDRESS}, inet_addr("$laptop")], [{nla_len=8, nla_type=IFA_LOCAL}, inet_addr("$laptop")], [{nla_len=8, nla_type=IFA_BROADCAST}, inet_addr("$laptop_mask")], [{nla_len=14, nla_type=IFA_LABEL}, "wlp0s20f3"], [{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_NOPREFIXROUTE], [{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=70304, ifa_valid=70304, cstamp=71639019, tstamp=71639026}]]]], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 168
recvmsg(3, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[[{nlmsg_len=72, nlmsg_type=RTM_NEWADDR, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, {ifa_family=AF_INET6, ifa_prefixlen=128, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_HOST, ifa_index=if_nametoindex("lo")}, [[{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "::1")], [{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=944, tstamp=944}], [{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT]]], [{nlmsg_len=72, nlmsg_type=RTM_NEWADDR, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=0, ifa_scope=RT_SCOPE_UNIVERSE, ifa_index=if_nametoindex("wlp0s20f3")}, [[{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "2601:182:d040:de0:fe21:5827:d517:e76f")], [{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=344855, ifa_valid=344855, cstamp=71639517, tstamp=73247080}], [{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_NOPREFIXROUTE]]], [{nlmsg_len=72, nlmsg_type=RTM_NEWADDR, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, {ifa_family=AF_INET6, ifa_prefixlen=64, ifa_flags=IFA_F_PERMANENT, ifa_scope=RT_SCOPE_LINK, ifa_index=if_nametoindex("wlp0s20f3")}, [[{nla_len=20, nla_type=IFA_ADDRESS}, inet_pton(AF_INET6, "fe80::9488:ed23:174a:a23b")], [{nla_len=20, nla_type=IFA_CACHEINFO}, {ifa_prefered=4294967295, ifa_valid=4294967295, cstamp=71638918, tstamp=73247080}], [{nla_len=8, nla_type=IFA_FLAGS}, IFA_F_PERMANENT|IFA_F_NOPREFIXROUTE]]]], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 216
recvmsg(3, {msg_name={sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, msg_namelen=12, msg_iov=[{iov_base=[{nlmsg_len=20, nlmsg_type=NLMSG_DONE, nlmsg_flags=NLM_F_MULTI, nlmsg_seq=1637169407, nlmsg_pid=1776650}, 0], iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 20
close(3)                                = 0

And success.

So, it looks like, on the second try, it likes nscd’s response to the first request much more, and proceeds with a completely different code path.

[kirelagin]

Debug logs from nscd:

Resolving google.com:

13:01:51: handle_request: request received (Version = 2) from PID 1784734
13:01:51: 	GETFDHST
13:01:51: provide access to FD 11, for hosts
13:01:51: handle_request: request received (Version = 2) from PID 1784734
13:01:51: 	GETAI (google.com)
13:01:51: Haven't found "google.com" in hosts cache!
13:01:51: add new entry "google.com" of type GETAI for hosts to cache (first)

Resolving google.com (again):

13:01:52: handle_request: request received (Version = 2) from PID 1784742
13:01:52: 	GETFDHST
13:01:52: provide access to FD 11, for hosts

Resolving lechat.local (first try):

13:03:37: handle_request: request received (Version = 2) from PID 1784880
13:03:37: 	GETFDHST
13:03:37: provide access to FD 11, for hosts
13:03:37: handle_request: request received (Version = 2) from PID 1784880
13:03:37: 	GETAI (lechat.local)
13:03:37: Haven't found "lechat.local" in hosts cache!
13:03:42: add new entry "lechat.local" of type GETAI for hosts to cache (first)

Resolving lechat.local (second try):

13:03:43: handle_request: request received (Version = 2) from PID 1784888
13:03:43: 	GETFDHST
13:03:43: provide access to FD 11, for hosts

So, the logs are exactly the same... However the resolution process is definitely different.

[kirelagin]

Here is a fun fact: glibc makes no distinction between nscd being unavilable/unusable and a timeout. Another fun fact is that there is absolutely no documentation on nscd, oh well.

So what happens in strace, is this:

• glibc uses GETFDHST to request a file descriptor for nscd’s in-memory cache.
• On the first query, this cache does not contain the name, so it makes a GETAI request, which, I think(?), is supposed to perform an actual dns (mdns) query and return the actual results.
• In the case of a simple DNS query, nscd quickly returns a result (either the address or an error) and we are done.
• In the case of an mDNS query, nscd does... something for a long time? We hit a timeout, glibc thinks that nscd is unavailable and falls back to its standard NSS stuff.
• I suspect the mDNS query keeps being executed nevertheless and so the name ends up in the cache, hence immediately retried query succeeds.

[kirelagin]

Here is a weird thing: if I try to resolve a name for a device that does not exist in the network, I do see an ordinary mdns name resolution query as the first thing. (Then it returns nothing, the nscd socket read times out, and the same thing happens: NSS, error).

So, it looks like the mdns module somehow knows that this device exists, so it does not try to resolve its name with an A query. Instead, as one can see in the tcpdump, it verifies(?) the address by making reverse PTR query (which, apparently, umdns on my router ignores).

[kirelagin]

The latest news is that I replaced umdns with avahi on the router and it all... seems to work somehow? Although there are still no mdns queries whatsoever :/.

[kirelagin]

Alright, I think the issue is indeed the of the PTR record. And the reason I did not see any queries is that a lot of stuff gets cached in Avahi. So, I shouldn’t have focused on nscd so much, but rater on Avahi.

› avahi-resolve -a $ap

returns immediately when Avahi is running on the router, since it publishes its PTR record, which gets cached by Avahi on the laptop. With umdns no PTR record is published, so this command times out.

My guess is that, for some reason, when glibc asks nscd to resolve a name, nscd goes ahead and also looks for a PTR record, which times out in Avahi. This is a bit weird, since I never asked for the reverse mapping and now I end up with an unresolved name, which could have been resolved easily.

I don’t think the mDNS RFC requires responding to PTR records, so I would say it is a bug either in nscd or in the mdns nss module?

[kirelagin]

omg, here is another completely crazy fact:

If, when calling getaddrinfo, I hint ai_family = AF_INET instead of AF_UNSPEC, everything starts to work. Why? Because there is a special case in glibc for when ai_family = AF_INET and AI_CANONNAME unset – instead of sending GETAI to nscd, it sends GETHOSTBYNAME, which succeeds, even without a PTR record.

[kirelagin]

Yes, ok, the GETAI request is handled by the addhstaiX function in nscd, and this function will call getcanonname_r to get the canonical name whether it was requested or not (i.e. regardless of AI_CANONNAME in the original call to getaddrinfo).

I suspect, if I report a bug against glibc, their response will be that nscd is just a cache. glibc does the right thing by giving up on waiting for it and going ahead and resolving the stuff itself – and the fact that on NixOS the NSS configuration does not match for ordinary binaries and nscd is no their problem :(.

[flokli]

@kirelagin it's even crazier. nscd can't really "not cache" (see #135888 (comment)), and client code uses GETFDHST to get an FD to peek in the cache structures.

If there recently was a forward lookup, chances are this finds the reverse lookup. And that's why GETAI isn't called in these cases.

[flokli]

Let's close this, this shouldn't be an issue with nsncd anymore, to which nixpkgs master just switched by default. Please reopen if this is still an issue, or you need to stick with glinc-nscd for some reason.