[Bug 1668771] Re: [SRU] systemd-resolved negative caching for extended period of time

Fri Jul 26 17:15:05 UTC 2019

Without the patch for LP: #1668771 resolved caches the SERVFAIL answer.

root at bionic:/home/multipass# host www.montemar.cl
Host www.montemar.cl not found: 2(SERVFAIL)
root at bionic:/home/multipass# journalctl -u systemd-resolved -f
-- Logs begin at Fri 2019-07-26 13:10:01 -04. --
Jul 26 13:13:12 bionic systemd-resolved[3167]: Transaction 25942 for <www.montemar.cl IN A> scope dns on ens3/*.
Jul 26 13:13:12 bionic systemd-resolved[3167]: Using feature level UDP for transaction 25942.
Jul 26 13:13:12 bionic systemd-resolved[3167]: Sending query packet with id 25942.
Jul 26 13:13:12 bionic systemd-resolved[3167]: Processing incoming packet on transaction 25942. (rcode=SERVFAIL)
Jul 26 13:13:12 bionic systemd-resolved[3167]: Server returned error: SERVFAIL
Jul 26 13:13:12 bionic systemd-resolved[3167]: Verified we get a response at feature level UDP from DNS server 10.91.4.1.
Jul 26 13:13:12 bionic systemd-resolved[3167]: Added SERVFAIL cache entry for www.montemar.cl IN A 30s
Jul 26 13:13:12 bionic systemd-resolved[3167]: Transaction 25942 for <www.montemar.cl IN A> on scope dns on ens3/* now complete with <rcode-failure> from network (unsigned).
Jul 26 13:13:12 bionic systemd-resolved[3167]: Sending response packet with id 26821 on interface 1/AF_INET.
Jul 26 13:13:12 bionic systemd-resolved[3167]: Freeing transaction 25942.

With the patch for LP: #1668771 resolved + setting Cache: 'no-negative'
doesn't caches the SERVFAIL option

root at bionic:/home/multipass# host www.montemar.cl
Host www.montemar.cl not found: 2(SERVFAIL)
root at bionic:/home/multipass# journalctl -u systemd-resolved -f
-- Logs begin at Fri 2019-07-26 13:10:01 -04. --
Jul 26 13:13:40 bionic systemd-resolved[3199]: Transaction 48671 for <www.montemar.cl IN A> scope dns on ens3/*.
Jul 26 13:13:40 bionic systemd-resolved[3199]: Using feature level UDP for transaction 48671.
Jul 26 13:13:40 bionic systemd-resolved[3199]: Sending query packet with id 48671.
Jul 26 13:13:40 bionic systemd-resolved[3199]: Processing incoming packet on transaction 48671. (rcode=SERVFAIL)
Jul 26 13:13:40 bionic systemd-resolved[3199]: Server returned error: SERVFAIL
Jul 26 13:13:40 bionic systemd-resolved[3199]: Verified we get a response at feature level UDP from DNS server 10.91.4.1.
Jul 26 13:13:40 bionic systemd-resolved[3199]: Not caching negative entry for: www.montemar.cl IN A, cache mode set to no-negative
Jul 26 13:13:40 bionic systemd-resolved[3199]: Transaction 48671 for <www.montemar.cl IN A> on scope dns on ens3/* now complete with <rcode-failure> from network (unsigned).
Jul 26 13:13:40 bionic systemd-resolved[3199]: Sending response packet with id 25454 on interface 1/AF_INET.
Jul 26 13:13:40 bionic systemd-resolved[3199]: Freeing transaction 48671.

Marking this as verified and working.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1668771

Title:
  [SRU] systemd-resolved negative caching for extended period of time

Status in systemd:
  New
Status in systemd package in Ubuntu:
  In Progress
Status in systemd source package in Bionic:
  Fix Committed
Status in systemd source package in Disco:
  Fix Committed
Status in systemd source package in Eoan:
  In Progress

Bug description:
  [Impact]

   * If a DNS lookup returns SERVFAIL, systemd-resolved seems to cache
  the result for very long (infinity?). I have to restart systemd-
  resolved to have the negative caching purged.

  * After SERVFAIL DNS server issue has been resolved, chromium/firefox
  still returns DNS error despite host can correctly resolve the name.

  [Test Case]

  * If a lookup returns SERVFAIL systemd-resolved will cache the result for 30s (See 201d995),
  however, there are several use cases on which this condition is not acceptable (See #5552 comments)
  and the only workaround would be to disable cache entirely or flush it , which isn't optimal.

  * Configure /etc/systemd/resolved.conf as follows:

  Cache=yes (default)

  * Restart systemd-resolved (systemctl restart systemd-
  resolved.service)

  * Run a host/getent command against a entry that will return SERVFAIL
  and check the journalctl output to see that the reply gets served from
  cache.

  root at systemd-disco:/home/ubuntu# host www.no-record.cl
  Host www.montemar.cl not found: 2(SERVFAIL)
  root at systemd-disco:/home/ubuntu# journalctl -u systemd-resolved -n
  -- Logs begin at Fri 2019-07-12 18:09:42 UTC, end at Tue 2019-07-23 15:10:17 UTC. --
  Jul 23 15:10:10 systemd-disco systemd-resolved[1282]: Transaction 6222 for <ntp.ubuntu.com IN AAAA> on scope dns on ens3/* now complete with <success>
  Jul 23 15:10:10 systemd-disco systemd-resolved[1282]: Sending response packet with id 61042 on interface 1/AF_INET.
  Jul 23 15:10:10 systemd-disco systemd-resolved[1282]: Freeing transaction 6222.
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Got DNS stub UDP query packet for id 53580
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Looking up RR for  www.no-record.cl IN A.
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: RCODE SERVFAIL cache hit for  www.no-record.cl IN A
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Transaction 58570 for < www.no-record.cl IN A> on scope dns on ens3/* now complete with <rcode-fai
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Freeing transaction 58570.
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Sending response packet with id 53580 on interface 1/AF_INET.
  Jul 23 15:10:17 systemd-disco systemd-resolved[1282]: Processing query...

  [Regression Potential]

   * The default options (Yes/No) will remain as default Yes, behaving in the same original
  way, by setting it to no-negative any negative answer will be skipped
  from being cached.

  * No regression potential has been detected as this just introduces
  a new possible option for the Cache configuration directive.

  [Fix]

  With the cache option set to 'no-negative', negative DNS answers
  are entirely avoided to being cached.

  root at systemd-disco:/home/ubuntu# host www.metaklass.org
  Host www.metaklass.org not found: 2(SERVFAIL)

  * Look at the systemd-resolved entries
  root at systemd-disco:/home/ubuntu# journalctl -u systemd-resolved -n
  -- Logs begin at Fri 2019-07-12 18:09:42 UTC, end at Fri 2019-07-12 18:48:31 UTC. --
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Cache miss for www.metaklass.org IN A
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Transaction 22382 for <www.metaklass.org IN A> scope dns on ens3/.
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Using feature level UDP for transaction 22382.
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Sending query packet with id 22382.
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Processing incoming packet on transaction 22382 (rcode=SERVFAIL).
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Server returned error: SERVFAIL
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Not caching negative entry for: www.metaklass.org IN A, cache mode set to no-negative
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Transaction 22382 for <www.metaklass.org IN A> on scope dns on ens3/ now complete with from network (unsigned).
  Jul 12 18:48:31 systemd-disco systemd-resolved[2635]: Sending response packet with id 31060 on interface 1/AF_INET.

  The following patch https://github.com/systemd/systemd/pull/13047
  implements the required changes.

  [Other Info]

  Note that systemd in Eoan is being upgraded to upstream 242, so I am
  not adding this to Eoan now, as I don't want to disturb the merge. If
  needed after the merge, I'll add to Eoan.

To manage notifications about this bug go to:
https://bugs.launchpad.net/systemd/+bug/1668771/+subscriptions