search

systemd / systemd

The systemd System and Service Manager
https://systemd.io
GNU General Public License v2.0
13.32k stars 3.81k forks source link

mDNS resolve timeout #30212

Open liusen373 opened 12 months ago

liusen373 commented 12 months ago

systemd version the issue has been seen with

254

Used distribution

Fedora 39

Linux kernel version used

6.5.11-300.fc39.x86_64

CPU architectures issue was seen on

x86_64

Component

nss-resolve

Expected behaviour you didn't see

No response

Unexpected behaviour you saw

systemd-resolved is my default domain name resolver.

When using programs like curl, ping, etc. to resolve .local domains, it always times out; however, if I use dig to query the domain directly, everything works fine.

Also, if I resolve the domain with dig first, let systemd-resolved cache the query results, and then use curl next, everything works fine.

fedora@xps13 ~> LANG=C curl http://pi.local:8080  -Iv
* processing: http://pi.local:8080
* Could not resolve host: pi.local
* Closing connection
curl: (6) Could not resolve host: pi.local

systemd-resolved log:

11月 27 17:05:45 xps13 systemd-resolved[1111586]: Looking up RR for pi.local IN A.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Looking up RR for pi.local IN AAAA.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Firing regular transaction 17202 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Delaying mdns transaction 17202 for 0us.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN AAAA
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Firing regular transaction 34589 for <pi.local IN AAAA> scope mdns on wlp58s0/INET6 (validate=yes).
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Delaying mdns transaction 34589 for 0us.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: varlink-27: Changing state processing-method → pending-method
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Initial jitter phase for transaction 17202 elapsed.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Retrying transaction 17202.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Firing regular transaction 17202 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET of size 26.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Initial jitter phase for transaction 34589 elapsed.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Retrying transaction 34589.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN AAAA
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Firing regular transaction 34589 for <pi.local IN AAAA> scope mdns on wlp58s0/INET6 (validate=yes).
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET6 of size 26.
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=192.168.1.4, destination=224.0.0.251
11月 27 17:05:45 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=fe80::1da:5fee:83ce:d389, destination=ff02::fb
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Timeout reached on transaction 17202.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Retrying transaction 17202.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Firing regular transaction 17202 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET of size 26.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Timeout reached on transaction 34589.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Retrying transaction 34589.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN AAAA
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Firing regular transaction 34589 for <pi.local IN AAAA> scope mdns on wlp58s0/INET6 (validate=yes).
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET6 of size 26.
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=192.168.1.4, destination=224.0.0.251
11月 27 17:05:46 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=fe80::1da:5fee:83ce:d389, destination=ff02::fb
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Timeout reached on transaction 17202.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Retrying transaction 17202.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Firing regular transaction 17202 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET of size 26.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Timeout reached on transaction 34589.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Retrying transaction 34589.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN AAAA
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Firing regular transaction 34589 for <pi.local IN AAAA> scope mdns on wlp58s0/INET6 (validate=yes).
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET6 of size 26.
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=192.168.1.4, destination=224.0.0.251
11月 27 17:05:48 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=fe80::1da:5fee:83ce:d389, destination=ff02::fb
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Timeout reached on transaction 17202.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Retrying transaction 17202.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Regular transaction 17202 for <pi.local IN A> on scope mdns on wlp58s0/INET now complete with <attempts-max-reached> from none (unsigned; non-confidential).
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Timeout reached on transaction 34589.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Retrying transaction 34589.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Regular transaction 34589 for <pi.local IN AAAA> on scope mdns on wlp58s0/INET6 now complete with <attempts-max-reached> from none (unsigned; non-confidential).
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Freeing transaction 17202.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Sending message: {"error":"io.systemd.Resolve.MaxAttemptsReached","parameters":{}}
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Changing state pending-method → idle-server
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Freeing transaction 34589.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Got POLLHUP from socket.
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Changing state idle-server → pending-disconnect
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Changing state pending-disconnect → processing-disconnect
11月 27 17:05:52 xps13 systemd-resolved[1111586]: varlink-27: Changing state processing-disconnect → disconnected
11月 27 17:05:52 xps13 systemd-resolved[1111586]: Connection failure for DNS TCP stream: Connection reset by peer
11月 27 17:05:54 xps13 systemd-resolved[1111586]: Failed to invoke SSL_shutdown, ignoring: error:0A000197:SSL routines::shutdown while in init
11月 27 17:05:54 xps13 systemd-resolved[1111586]: Connection failure for DNS TCP stream: Connection timed out
fedora@xps13 ~ [6]> LANG=C dig @127.0.0.53 pi.local

; <<>> DiG 9.18.19 <<>> @127.0.0.53 pi.local
; (1 server found)
;; global options: +cmd
;; Got answer:
;; WARNING: .local is reserved for Multicast DNS
;; You are currently testing what happens when an mDNS query is leaked to DNS
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 31258
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 65494
;; QUESTION SECTION:
;pi.local.          IN  A

;; ANSWER SECTION:
pi.local.       120 IN  A   192.168.1.2

;; Query time: 304 msec
;; SERVER: 127.0.0.53#53(127.0.0.53) (UDP)
;; WHEN: Mon Nov 27 17:08:22 CST 2023
;; MSG SIZE  rcvd: 53

11月 27 17:08:21 xps13 systemd-resolved[1111586]: Received dns UDP packet of size 49, ifindex=0, ttl=64, fragsize=0, sender=127.0.0.1, destination=127.0.0.53
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Got DNS stub UDP query packet for id 6778
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Looking up RR for pi.local IN A.
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Firing regular transaction 3960 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Delaying mdns transaction 3960 for 0us.
11月 27 17:08:21 xps13 systemd-resolved[1111586]: Processing query...
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Initial jitter phase for transaction 3960 elapsed.
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Retrying transaction 3960.
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Cache miss for pi.local IN A
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Firing regular transaction 3960 for <pi.local IN A> scope mdns on wlp58s0/INET (validate=yes).
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Sending query packet with id 0 on interface 3/AF_INET of size 26.
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 26, ifindex=3, ttl=255, fragsize=0, sender=192.168.1.4, destination=224.0.0.251
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Received mdns UDP packet of size 36, ifindex=3, ttl=255, fragsize=0, sender=192.168.1.2, destination=224.0.0.251
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Got mDNS reply packet
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Checking for conflicts...
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Processing incoming packet of size 36 on transaction 3960 (rcode=SUCCESS).
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Regular transaction 3960 for <pi.local IN A> on scope mdns on wlp58s0/INET now complete with <success> from network (unsigned; non-confidential).
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Sending response packet with id 6778 on interface 1/AF_INET of size 53.
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Freeing transaction 3960.
11月 27 17:08:22 xps13 systemd-resolved[1111586]: Added positive unauthenticated non-confidential cache entry for pi.local IN A 120s on wlp58s0/INET/192.168.1.2

Steps to reproduce the problem

No response

Additional program output to the terminal or log subsystem illustrating the issue

fedora@xps13 ~> resolvectl status
Global
         Protocols: LLMNR=resolve +mDNS +DNSOverTLS DNSSEC=no/unsupported
  resolv.conf mode: stub
Current DNS Server: 223.5.5.5#dns.alidns.com
       DNS Servers: 223.5.5.5#dns.alidns.com

Link 3 (wlp58s0)
    Current Scopes: DNS LLMNR/IPv4 LLMNR/IPv6 mDNS/IPv4 mDNS/IPv6
         Protocols: +DefaultRoute LLMNR=resolve +mDNS +DNSOverTLS DNSSEC=no/unsupported
Current DNS Server: 2400:3200::1
       DNS Servers: 192.168.1.1 2400:3200::1 2400:3200:baba::1
        DNS Domain: Home

fedora@xps13 ~> cat /etc/nsswitch.conf
hosts:      files myhostname mymachines resolve [!UNAVAIL=return] dns
rpigott commented 11 months ago

resolved stub should probably outright refuse dns queries to the .local domain anyway, making the "successful" responses the real error.

Anwyay, in your log the sender's source address is identified as 192.168.1.4, but the later successful response is apparently 192.168.1.2, so something fishy is going on. Based on the messages present, the failed replies were rejected here: https://github.com/systemd/systemd/blob/d4506301f945006c1619f7455b35653517b57a74/src/resolve/resolved-mdns.c#L362-L363

Are those addresses local? Share the ip configuration of your host. This condition should probably hit a debug log.

liusen373 commented 11 months ago

resolved stub should probably outright refuse dns queries to the .local domain anyway, making the "successful" responses the real error.

Anwyay, in your log the sender's source address is identified as 192.168.1.4, but the later successful response is apparently 192.168.1.2, so something fishy is going on. Based on the messages present, the failed replies were rejected here:

https://github.com/systemd/systemd/blob/d4506301f945006c1619f7455b35653517b57a74/src/resolve/resolved-mdns.c#L362-L363

Are those addresses local? Share the ip configuration of your host. This condition should probably hit a debug log.

192.168.1.4 xps13.local, my laptop 192.168.1.2 pi.local, another machine on the lan

poettering commented 9 months ago

So in the first case there simply is noone asking our request. In the second case 192.168.1.2 is answering.

No idea why noone answers in the first case...

The messages from 192.168.1.4 are a red herring, it's just the query messages we sent out ourselves...