Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

No DNS with DNSSEC=yes #8451

Open
paulmenzel opened this issue Mar 14, 2018 · 14 comments
Open

No DNS with DNSSEC=yes #8451

paulmenzel opened this issue Mar 14, 2018 · 14 comments
Labels
dnssec needs-reporter-feedback resolve

Comments

@paulmenzel
Copy link
Contributor

@paulmenzel paulmenzel commented Mar 14, 2018

Submission type

  • Bug report

systemd version the issue has been seen with

238

Used distribution

Linux From Scratch

In case of bug report: Unexpected behaviour you saw

# systemd-resolve www.freedesktop.org
www.freedesktop.org: resolve call failed: DNSSEC validation failed: incompatible-server
# systemd-resolve --status
Global
         DNS Servers: 141.14.16.1
          DNS Domain: molgen.mpg.de

In case of bug report: Steps to reproduce the problem

The error began with the lines below in the log.

systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN AAAA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question herokussl.com IN DS: no-signature
systemd-resolved[227]: DNSSEC validation failed for question herokussl.com IN SOA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN DS: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN SOA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN AAAA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN A: no-signature
systemd-resolved[227]: DNSSEC validation failed for question herokussl.com IN DS: no-signature
systemd-resolved[227]: DNSSEC validation failed for question herokussl.com IN SOA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN DS: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN SOA: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN A: no-signature
systemd-resolved[227]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN AAAA: no-signature
@paulmenzel
Copy link
Contributor Author

@paulmenzel paulmenzel commented Mar 14, 2018

Oh, and the DNS server works, when queried directory, so no idea, what problem systemd-resolved has.

$ dig +dnssec @141.14.16.1 www.freedesktop.org

; <<>> DiG 9.9.6-P1 <<>> +dnssec @141.14.16.1 www.freedesktop.org
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 31688
;; flags: qr rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 3, ADDITIONAL: 4

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;www.freedesktop.org.		IN	A

;; ANSWER SECTION:
www.freedesktop.org.	14400	IN	CNAME	annarchy.freedesktop.org.
annarchy.freedesktop.org. 14400	IN	A	131.252.210.176

;; AUTHORITY SECTION:
freedesktop.org.	68997	IN	NS	ns1.freedesktop.org.
freedesktop.org.	68997	IN	NS	ns3.freedesktop.org.
freedesktop.org.	68997	IN	NS	ns2.freedesktop.org.

;; ADDITIONAL SECTION:
ns1.freedesktop.org.	68997	IN	A	131.252.210.177
ns2.freedesktop.org.	68997	IN	A	89.16.189.59
ns3.freedesktop.org.	68997	IN	A	89.16.189.54

;; Query time: 1008 msec
;; SERVER: 141.14.16.1#53(141.14.16.1)
;; WHEN: Wed Mar 14 12:12:51 CET 2018
;; MSG SIZE  rcvd: 189

@paulmenzel
Copy link
Contributor Author

@paulmenzel paulmenzel commented Mar 14, 2018

To me it sounds a little bit like issue #7040 is still not fixed.

@paulmenzel
Copy link
Contributor Author

@paulmenzel paulmenzel commented Mar 14, 2018

After restarting systemd-resolved (to enable debugging), the issues is gone for now.

@paulmenzel
Copy link
Contributor Author

@paulmenzel paulmenzel commented Mar 14, 2018

With debug enabled, the messages below are show right before the failed look up.

Mar 14 13:53:52 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for ryan IN A
Mar 14 13:53:52 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 38609 for <ryan IN A> scope llmnr on vlan.mgmt0/INET.
Mar 14 13:53:52 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 38609 on interface 4/AF_INET.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 61354.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 61354.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 61354 for <ryan IN A> on scope llmnr on net00/INET now complete with <attempts-max-reached> from none (unsigned).
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 38609.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 38609.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 38609 for <ryan IN A> on scope llmnr on vlan.mgmt0/INET now complete with <attempts-max-reached> from none (unsigned).
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 61354.
Mar 14 13:53:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 38609.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Got DNS stub UDP query packet for id 24252
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Looking up RR for harry.molgen.mpg.de IN A.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Removing cache entry for oc-molgen.gnz.mpg.de IN AAAA (expired 25s ago)
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Removing cache entry for mpg.de IN DNSKEY (expired 15s ago)
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for harry.molgen.mpg.de IN A
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 42348 for <harry.molgen.mpg.de IN A> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 42348.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Following CNAME/DNAME harry.molgen.mpg.de → mx.molgen.mpg.de.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for mx.molgen.mpg.de IN A
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 21367 for <mx.molgen.mpg.de IN A> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 21367.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending response packet with id 24252 on interface 1/AF_INET.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing query...
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Got DNS stub UDP query packet for id 42700
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Looking up RR for harry.molgen.mpg.de IN AAAA.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for harry.molgen.mpg.de IN AAAA
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 13834 for <harry.molgen.mpg.de IN AAAA> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 13834.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Following CNAME/DNAME harry.molgen.mpg.de → mx.molgen.mpg.de.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for mx.molgen.mpg.de IN AAAA
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 37092 for <mx.molgen.mpg.de IN AAAA> scope dns on */*.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 37092.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Using DNS server 141.14.16.1 for transaction 37092.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 37092.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing query...
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 37092. (rcode=SUCCESS)
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Not validating response for 37092, used server feature level does not support DNSSEC.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: DNSSEC validation failed for question mx.molgen.mpg.de IN AAAA: incompatible-server
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 37092 for <mx.molgen.mpg.de IN AAAA> on scope dns on */* now complete with <dnssec-failed> from network (unsigned).
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending response packet with id 42700 on interface 1/AF_INET.
Mar 14 13:54:27 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 37092.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Got DNS stub UDP query packet for id 52139
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Looking up RR for sally.molgen.mpg.de IN A.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for sally.molgen.mpg.de IN A
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 45447 for <sally.molgen.mpg.de IN A> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 45447.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Following CNAME/DNAME sally.molgen.mpg.de → sally1.molgen.mpg.de.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for sally1.molgen.mpg.de IN A
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 31481 for <sally1.molgen.mpg.de IN A> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 31481.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending response packet with id 52139 on interface 1/AF_INET.
Mar 14 13:54:38 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing query...

@buczek
Copy link
Contributor

@buczek buczek commented Mar 15, 2018

(Talking about the same failure event as my colleague Paul)

[ EDIT: Not necessarily herokussl.com to blame for the bad dns replies, it looks like some "Intrusion Prevention System" messed with it ]

I think the problem is, that systemd-resolved blames/downgrades the configured forwarding server (here: 141.14.16.1) for failures of third-party servers. It looks like some servers of herokussl.com were seriously broken and return invalid answers (swapping TYPE and CLASS). I've seen this directly from these servers but only have a typescript of such a reply from the cache of a Google server:

buczek@theinternet:~$ dig @8.8.8.8 +norecurse +nocdflag www.overleaf.com A

; <<>> DiG 9.9.6-P1 <<>> @8.8.8.8 +norecurse +nocdflag www.overleaf.com A
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 31496
;; flags: qr ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;www.overleaf.com.		IN	A

;; Query time: 15 msec
;; SERVER: 8.8.8.8#53(8.8.8.8)
;; WHEN: Thu Mar 15 07:58:41 CET 2018
;; MSG SIZE  rcvd: 45

buczek@theinternet:~$ dig @8.8.8.8 +nocdflag www.overleaf.com A

; <<>> DiG 9.9.6-P1 <<>> @8.8.8.8 +nocdflag www.overleaf.com A
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 5223
;; flags: qr rd ra; QUERY: 1, ANSWER: 5, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;www.overleaf.com.		IN	A

;; ANSWER SECTION:
www.overleaf.com.	299	IN	CNAME	kagoshima-2051.herokussl.com.
kagoshima-2051.herokussl.com. 2313 IN	CNAME	elb055193-586424513.us-east-1.elb.amazonaws.com.
elb055193-586424513.us-east-1.elb.amazonaws.com. 54 IN A 107.22.199.70
elb055193-586424513.us-east-1.elb.amazonaws.com. 54 IN A 54.243.71.251
elb055193-586424513.us-east-1.elb.amazonaws.com. 54 IN A 50.17.211.222

;; Query time: 27 msec
;; SERVER: 8.8.8.8#53(8.8.8.8)
;; WHEN: Thu Mar 15 08:01:20 CET 2018
;; MSG SIZE  rcvd: 190

buczek@theinternet:~$ dig @8.8.8.8 kagoshima-2051.herokussl.com. NS
;; Question section mismatch: got kagoshima-2051.herokussl.com/A/CLASS2
;; Question section mismatch: got kagoshima-2051.herokussl.com/A/CLASS2
;; Question section mismatch: got kagoshima-2051.herokussl.com/A/CLASS2

; <<>> DiG 9.9.6-P1 <<>> @8.8.8.8 kagoshima-2051.herokussl.com. NS
; (1 server found)
;; global options: +cmd
;; connection timed out; no servers could be reached

In our systemd-resolved log you see, that 141.14.16.1 is 'downgraded' as a result of failures to resolve these specific names. Lines from the log which I think are relevant to this issue with some blank lines added for visibility:

Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing query...
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Got DNS stub UDP query packet for id 25091
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Looking up RR for www.overleaf.com IN AAAA.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for www.overleaf.com IN AAAA
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 54688 for <www.overleaf.com IN AAAA> scope dns on */*.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO for transaction 54688.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Using DNS server 141.14.16.1 for transaction 54688.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 54688.

Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 54688. (rcode=SERVFAIL)
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP+EDNS0.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 54688.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for www.overleaf.com IN AAAA
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 54688 for <www.overleaf.com IN AAAA> scope dns on */*.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 54688.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 54688.

Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 54688. (rcode=NXDOMAIN)
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Downgrading transaction feature level fixed an RCODE error, downgrading server 141.14.16.1 too.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Not validating response for 54688, used server feature level does not support DNSSEC.
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: DNSSEC validation failed for question www.overleaf.com IN AAAA: incompatible-server
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 54688 for <www.overleaf.com IN AAAA> on scope dns on */* now complete with <dnssec-failed> from network (unsigned).
Mar 14 13:40:49 theinternet.molgen.mpg.de systemd-resolved[10186]: Freeing transaction 54688.

Additionally (minor), the forwarding server lost the "LARGE" feature before due to failures of the third-party servers. Maybe the timeouts are incompatible, because the forwarder is returning the first "SERVFAIL" after 10 seconds, when systemd-resolved has taken action long before. Maybe the external servers do answer, but with bogus data which is not forwarded:

Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 19327. (rcode=SUCCESS)
Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Requesting parent SOA to validate transaction 19327 (hiroshima-8246.herokussl.com, unsigned CNAME/DNAME/DS RRset).
Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA

Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO+LARGE for transaction 11242.
Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Using DNS server 141.14.16.1 for transaction 11242.
Mar 14 12:50:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO+LARGE for transaction 11242.
Mar 14 12:50:24 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO+LARGE for transaction 11242.
Mar 14 12:50:25 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.

Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Lost too many UDP packets, downgrading feature level...
Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Using degraded feature set (UDP+EDNS0+DO) for DNS server 141.14.16.1.

Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO for transaction 11242.
Mar 14 12:50:29 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 11242. (rcode=SERVFAIL)
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP+EDNS0.
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 11242.
Mar 14 12:50:33 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 11242.
Mar 14 12:50:34 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 11242.
Mar 14 12:50:35 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 11242.
Mar 14 12:50:39 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 11242. (rcode=SERVFAIL)
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP.
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 11242.
Mar 14 12:50:43 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 11242.
Mar 14 12:50:45 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 11242.
Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 11242.
Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN SOA
Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> scope dns on */*.
Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 11242.
Mar 14 12:50:50 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 11242.

Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 11242. (rcode=SERVFAIL)
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error: SERVFAIL
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Requesting DS to validate transaction 11242 (herokussl.com, unsigned empty SOA/NS response).

Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO for transaction 52959.
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Using DNS server 141.14.16.1 for transaction 52959.
Mar 14 12:50:53 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 52959.
Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO for transaction 52959.
Mar 14 12:50:57 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 52959.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0+DO for transaction 52959.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 52959. (rcode=SERVFAIL)
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP+EDNS0.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 52959.
Mar 14 12:51:03 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.
Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 52959.

Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP+EDNS0 for transaction 52959.
Mar 14 12:51:08 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 52959. (rcode=SERVFAIL)
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP.
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 52959.
Mar 14 12:51:13 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Timeout reached on transaction 52959.
Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Retrying transaction 52959.
Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Cache miss for herokussl.com IN DS
Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> scope dns on */*.
Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Using feature level UDP for transaction 52959.
Mar 14 12:51:18 theinternet.molgen.mpg.de systemd-resolved[10186]: Sending query packet with id 52959.

Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Processing incoming packet on transaction 52959. (rcode=SERVFAIL)
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Server returned error: SERVFAIL

Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Requesting parent SOA to validate transaction 52959 (herokussl.com, unsigned empty DS response).
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Positive cache hit for com IN SOA
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 62137 for <com IN SOA> on scope dns on */* now complete with <success> from cache (authenticated).
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Validating response from transaction 52959 (herokussl.com IN DS).
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Found verdict for lookup herokussl.com IN DS: bogus
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: DNSSEC validation failed for question herokussl.com IN DS: no-signature
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 52959 for <herokussl.com IN DS> on scope dns on */* now complete with <dnssec-failed> from network (unsigned).
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Auxiliary DNSSEC RR query failed validation: no-signature
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: DNSSEC validation failed for question herokussl.com IN SOA: no-signature
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 11242 for <herokussl.com IN SOA> on scope dns on */* now complete with <dnssec-failed> from network (unsigned).
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Auxiliary DNSSEC RR query failed validation: no-signature
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: DNSSEC validation failed for question hiroshima-8246.herokussl.com IN AAAA: no-signature
Mar 14 12:51:23 theinternet.molgen.mpg.de systemd-resolved[10186]: Transaction 19327 for <hiroshima-8246.herokussl.com IN AAAA> on scope dns on */* now complete with <dnssec-failed> from network (unsigned).

@yuwata yuwata added the resolve label Mar 19, 2018
@poettering
Copy link
Member

@poettering poettering commented Mar 21, 2018

Hmm, @paulmenzel and @buczek you are using the same DNS server?

So it appears your DNS servers are flaky, and can't do DNSSEC reliably, hence the behaviour you are seeing is expected, no?

@poettering poettering added the needs-reporter-feedback label Mar 21, 2018
@buczek
Copy link
Contributor

@buczek buczek commented Mar 21, 2018

Yes, we are using the same DNS server. We are talking about the same failure on the same system. The configured nameserver 141.14.16.1 is assumed to be stable by itself. However, as 141.14.16.1 has to query external servers, an individual query might take long.

In the logs above you see 141.14.16.1 return a SERVFAIL after 10 seconds, because of some external nameserver failure (while at the same time promptly replying to other queries, which were omitted from the quoted log). I suspect, that because of the delay, it was "downgraded" by systemd-resolved, maybe up the point when it was no longer considered for DNSSEC and all further name resolutions failed.

@buczek
Copy link
Contributor

@buczek buczek commented Apr 7, 2018

Related to #7974 ( 10s timeout of the bind server ).

@ott
Copy link
Contributor

@ott ott commented May 22, 2018

@bubeck I agree.

@ott
Copy link
Contributor

@ott ott commented Aug 31, 2018

@bubeck @paulmenzel I provided a patch that addressed #7974 and it was integrated into v239. Perhaps this version lessens the problem for you.

@buczek
Copy link
Contributor

@buczek buczek commented Jun 20, 2019

Sorry for not replying for so long.

We are on v242 now and the general problem is still there.

I've delegated a zone to a non-answering ip-address. Our configuration for systemd-resolved includes "FallbackDNS=141.14.16.1" and "DNSSEC=yes".

Querying for a name in the invalid zone will downgrade 141.14.16.1 , although this server behaves perfectly well and replies with SERVFAIL after the usual 10 second timeout.

Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Got DNS stub UDP query packet for id 21508
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Looking up RR for test.invalid.molgen.mpg.de IN A.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Switching to fallback DNS server 141.14.16.1.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0+DO+LARGE for transaction 1377.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Using DNS server 141.14.16.1 for transaction 1377.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:43:53 theinternet.molgen.mpg.de systemd-resolved[3025]: Processing query...
Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Timeout reached on transaction 1377.

Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0+DO+LARGE for transaction 1377.
Jun 20 16:43:58 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Processing incoming packet on transaction 1377 (rcode=SERVFAIL).
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP+EDNS0+DO.

Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0+DO for transaction 1377.
Jun 20 16:44:03 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Timeout reached on transaction 1377.

Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0+DO for transaction 1377.
Jun 20 16:44:08 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Processing incoming packet on transaction 1377 (rcode=SERVFAIL).
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP+EDNS0.

Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0 for transaction 1377.
Jun 20 16:44:13 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Timeout reached on transaction 1377.

Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP+EDNS0 for transaction 1377.
Jun 20 16:44:18 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Processing incoming packet on transaction 1377 (rcode=SERVFAIL).
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Server returned error SERVFAIL, retrying transaction with reduced feature level UDP.

Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP for transaction 1377.
Jun 20 16:44:23 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Timeout reached on transaction 1377.
Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Retrying transaction 1377.

Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Cache miss for test.invalid.molgen.mpg.de IN A
Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Transaction 1377 for <test.invalid.molgen.mpg.de IN A> scope dns on */*.
Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Using feature level UDP for transaction 1377.
Jun 20 16:44:28 theinternet.molgen.mpg.de systemd-resolved[3025]: Sending query packet with id 1377.
Jun 20 16:44:33 theinternet.molgen.mpg.de systemd-resolved[3025]: Processing incoming packet on transaction 1377 (rcode=SERVFAIL).
Jun 20 16:44:33 theinternet.molgen.mpg.de systemd-resolved[3025]: Server returned error: SERVFAIL
Jun 20 16:44:33 theinternet.molgen.mpg.de systemd-resolved[3025]: Verified we get a response at feature level UDP from DNS server 141.14.16.1.

Jun 20 16:44:33 theinternet.molgen.mpg.de systemd-resolved[3025]: Requesting SOA (→ test.invalid.molgen.mpg.de) to validate transaction 1377 (test.invalid.molgen.mpg.de, unsigned empty non-SOA/NS/DS response).

now everything repeats for the SOA query...

@letoams
Copy link

@letoams letoams commented Nov 2, 2020

This bug could partially be caused by the mixed cache bug.
try this:

success when using:
systemctl restart systemd-resolved
dig +dnssec freebsd.org
[shows dnssec records]

failure using:
systemctl restart systemd-resolved
dig freebsd.org
[shows no dnssec records as expected]
dig +dnssec freebsd.org
[mistakenly also shows no dnssec records]

@molgen-edv
Copy link

@molgen-edv molgen-edv commented Nov 2, 2020

@letoams: Thanks. But the problem you describe can't be reproduced on our site:

buczek@sigint:~$ sudo systemctl restart systemd-resolved
buczek@sigint:~$ dig +dnssec freebsd.org

; <<>> DiG 9.9.6-P1 <<>> +dnssec freebsd.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 8537
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;freebsd.org.			IN	A

;; ANSWER SECTION:
freebsd.org.		3600	IN	A	96.47.72.84
freebsd.org.		3600	IN	RRSIG	A 8 2 3600 20201115043416 20201101021715 2520 freebsd.org. W0+5Jbe7efb4HmupzNf5VOZbCNAV9RK1pTYnYBoQyIa7vVX5c66uyvBr FMTLnC5Yp7QM8tOobuScRjvacTDi36o/ioROYmW+PBxAj9XhSWg+3ZSN Ma1SoNHgRelrWCG3Ct6K88h0u7jpcGMR7EeP9lLt7T73Jwt3xA4ttHun aI0u/WMAx+pkYUkalWtvfokQRTAWHZB7xsLgvEB86APPxW9ivmjW7DMV MLRsk5P0F6CXUT91OKDXPy9jd3C4OvbnR/gzy+YYqx8PcCvriM0A4Ydr xKm4VKokrJotFMa2amjpZIkzzztjO+OIqvYeygdDrYMm2DRld7HkcXl1 qxPuuw==

;; Query time: 7 msec
;; SERVER: 141.14.16.1#53(141.14.16.1)
;; WHEN: Mon Nov 02 15:45:45 CET 2020
;; MSG SIZE  rcvd: 355

buczek@sigint:~$ sudo systemctl restart systemd-resolved
buczek@sigint:~$ dig freebsd.org

; <<>> DiG 9.9.6-P1 <<>> freebsd.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 5769
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;freebsd.org.			IN	A

;; ANSWER SECTION:
freebsd.org.		3581	IN	A	96.47.72.84

;; Query time: 0 msec
;; SERVER: 141.14.16.1#53(141.14.16.1)
;; WHEN: Mon Nov 02 15:46:04 CET 2020
;; MSG SIZE  rcvd: 56

buczek@sigint:~$ dig +dnssec freebsd.org

; <<>> DiG 9.9.6-P1 <<>> +dnssec freebsd.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 13433
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
;; QUESTION SECTION:
;freebsd.org.			IN	A

;; ANSWER SECTION:
freebsd.org.		3574	IN	A	96.47.72.84
freebsd.org.		3574	IN	RRSIG	A 8 2 3600 20201115043416 20201101021715 2520 freebsd.org. W0+5Jbe7efb4HmupzNf5VOZbCNAV9RK1pTYnYBoQyIa7vVX5c66uyvBr FMTLnC5Yp7QM8tOobuScRjvacTDi36o/ioROYmW+PBxAj9XhSWg+3ZSN Ma1SoNHgRelrWCG3Ct6K88h0u7jpcGMR7EeP9lLt7T73Jwt3xA4ttHun aI0u/WMAx+pkYUkalWtvfokQRTAWHZB7xsLgvEB86APPxW9ivmjW7DMV MLRsk5P0F6CXUT91OKDXPy9jd3C4OvbnR/gzy+YYqx8PcCvriM0A4Ydr xKm4VKokrJotFMa2amjpZIkzzztjO+OIqvYeygdDrYMm2DRld7HkcXl1 qxPuuw==

;; Query time: 0 msec
;; SERVER: 141.14.16.1#53(141.14.16.1)
;; WHEN: Mon Nov 02 15:46:11 CET 2020
;; MSG SIZE  rcvd: 355


@letoams
Copy link

@letoams letoams commented Nov 2, 2020

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
dnssec needs-reporter-feedback resolve
Development

No branches or pull requests

7 participants