Unbound DNSSEC Failing to Docker

Issue Description

I know this is not a Pi-hole issue and may just be an unbound configuration issue or, simply Docker/AWS DNS is configured wrong for DNSSEC.
I noticed I could no longer pull Docker images after moving my Pi-Hole into production. I have DNSSEC enabled in Pi-Hole and the Upstream DNS Server pointed to the local unbound instance at 127.0.0.1#5335.

Following documentation and using the unbound Configure unbound - Pi-hole documentation, I get an NXDOMAIN response for production.cloudflare.docker.com which is preventing my Docker hosts from pulling Docker images.

The only two ways I have been able to resolve this is to either disable DNSSEC in Pi-Hole Admin --> Settings --> DNS --> Uncheck Use DNSSEC or by modifying /etc/unbound/unbound.conf.d/pi-hole.conf and forwarding all queries to Cloudflare via TLS.

forward-zone:
  name: "."
  forward-tls-upstream: yes
  forward-addr: 1.1.1.1@853

Expected Behaviour:

➜  ~ dig production.cloudflare.docker.com @127.0.0.1#5335

; <<>> DiG 9.10.6 <<>> production.cloudflare.docker.com @192.168.7.20
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 22364
;; flags: qr rd ra; QUERY: 1, ANSWER: 5, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;production.cloudflare.docker.com. IN	A

;; ANSWER SECTION:
production.cloudflare.docker.com. 281 IN A	104.18.122.25
production.cloudflare.docker.com. 281 IN A	104.18.123.25
production.cloudflare.docker.com. 281 IN A	104.18.124.25
production.cloudflare.docker.com. 281 IN A	104.18.121.25
production.cloudflare.docker.com. 281 IN A	104.18.125.25

;; Query time: 83 msec
;; SERVER: 192.168.7.20#53(192.168.7.20)
;; WHEN: Tue Oct 18 10:42:25 EDT 2022
;; MSG SIZE  rcvd: 141

Running on a Raspberry Pi 4B

➜  ~ pihole -v
  Pi-hole version is v5.13 (Latest: v5.13)
  AdminLTE version is v5.16 (Latest: v5.16)
  FTL version is v5.18.2 (Latest: v5.18.2)
➜  ~ lsb_release -s -d
Ubuntu 22.04.1 LTS
➜  ~ uname -o -r -m
5.15.0-1016-raspi aarch64 GNU/Linux

Actual Behaviour:

➜  ~ dig production.cloudflare.docker.com @127.0.0.1 -p 5335

; <<>> DiG 9.18.1-1ubuntu1.2-Ubuntu <<>> production.cloudflare.docker.com @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 64316
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;production.cloudflare.docker.com. IN	A

;; AUTHORITY SECTION:
docker.com.		324	IN	SOA	ns-207.awsdns-25.com. awsdns-hostmaster.amazon.com. 1 7200 900 1209600 86400

;; Query time: 1799 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1) (UDP)
;; WHEN: Tue Oct 18 10:48:26 EDT 2022
;; MSG SIZE  rcvd: 139

Debug Token:

Debug Token - Uploaded Oct 18 2022 10:50 AM Eastern

Supporting config

Just to post it, here is my entire /etc/unbound/unbound.conf.d/pi-hole.conf

server:
  # If no logfile is specified, syslog is used
  logfile: "/var/log/unbound.log"
  verbosity: 5

  interface: 127.0.0.1
  port: 5335
  do-ip4: yes
  do-udp: yes
  do-tcp: yes

  # May be set to yes if you have IPv6 connectivity
  do-ip6: no

  # You want to leave this to no unless you have *native* IPv6. With 6to4 and
  # Terredo tunnels your web browser should favor IPv4 for the same reasons
  prefer-ip6: no

  # Use this only when you downloaded the list of primary root servers!
  # If you use the default dns-root-data package, unbound will find it automatically
  #root-hints: "/var/lib/unbound/root.hints"

  # Trust glue only if it is within the server's authority
  harden-glue: yes

  # Require DNSSEC data for trust-anchored zones, if such data is absent, the zone becomes BOGUS
  harden-dnssec-stripped: yes

  # Don't use Capitalization randomization as it known to cause DNSSEC issues sometimes
  # see https://discourse.pi-hole.net/t/unbound-stubby-or-dnscrypt-proxy/9378 for further details
  use-caps-for-id: no

  # Reduce EDNS reassembly buffer size.
  # IP fragmentation is unreliable on the Internet today, and can cause
  # transmission failures when large DNS messages are sent via UDP. Even
  # when fragmentation does work, it may not be secure; it is theoretically
  # possible to spoof parts of a fragmented DNS message, without easy
  # detection at the receiving end. Recently, there was an excellent study
  # >>> Defragmenting DNS - Determining the optimal maximum UDP response size for DNS <<<
  # by Axel Koolhaas, and Tjeerd Slokker (https://indico.dns-oarc.net/event/36/contributions/776/)
  # in collaboration with NLnet Labs explored DNS using real world data from the
  # the RIPE Atlas probes and the researchers suggested different values for
  # IPv4 and IPv6 and in different scenarios. They advise that servers should
  # be configured to limit DNS messages sent over UDP to a size that will not
  # trigger fragmentation on typical network links. DNS servers can switch
  # from UDP to TCP when a DNS response is too big to fit in this limited
  # buffer size. This value has also been suggested in DNS Flag Day 2020.
  edns-buffer-size: 1232

  # Perform prefetching of close to expired message cache entries
  # This only applies to domains that have been frequently queried
  prefetch: yes

  # One thread should be sufficient, can be increased on beefy machines. In reality for most users running on small networks or on a single 
machine, it should be unnecessary to seek performance enhancement by increasing num-threads above 1.
  num-threads: 1

  # Ensure kernel buffer is large enough to not lose messages in traffic spikes
  so-rcvbuf: 1m

  # Ensure privacy of local IP ranges
  private-address: 192.168.0.0/16
  private-address: 169.254.0.0/16
  private-address: 172.16.0.0/12
  private-address: 10.0.0.0/8
  private-address: fd00::/8
  private-address: fe80::/10

I cannot recreate your observation:
production.cloudflare.docker.com resolves correctly with my Pi-hole/unbound configuration, with DNSSEC enabled.

Is your Pi-hole host machine's time and time zone information correct?

But:

Did that dig actually return anything?
On my machinbe, it "couldn't get address for '127.0.0.1#5335'".
EDIT: So maybe that's some sort of copy-paste thing from constructing the expected behaviour example?

➜ ~ dig production.cloudflare.docker.com @127.0.0.1#5335

I thought I corrected that in my post. dig production.cloudflare.docker.com @127.0.0.1 -p 5335 is the command and it still responds with status NXDOMAIN (I just did a fresh OS install and install of unbound and Pi-Hole. I don't know if it makes a difference but I am running Ubuntu Server 22.0.4 and installed unbound via Ubuntu's package manager apt

➜  ~ dig production.cloudflare.docker.com @127.0.0.1 -p 5335

; <<>> DiG 9.18.1-1ubuntu1.2-Ubuntu <<>> production.cloudflare.docker.com @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 40566
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;production.cloudflare.docker.com. IN	A

;; AUTHORITY SECTION:
docker.com.		30	IN	SOA	ns-207.awsdns-25.com. awsdns-hostmaster.amazon.com. 1 7200 900 1209600 86400

;; Query time: 67 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1) (UDP)
;; WHEN: Tue Oct 18 17:03:50 EDT 2022
;; MSG SIZE  rcvd: 139

Is your Pi-hole host machine's time and time zone information correct?

Yes, it is.

➜  ~ timedatectl status
               Local time: Tue 2022-10-18 17:06:18 EDT
           Universal time: Tue 2022-10-18 21:06:18 UTC
                 RTC time: n/a
                Time zone: America/New_York (EDT, -0400)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
➜  ~ timedatectl timesync-status
       Server: 147.182.158.78 (north-america.pool.ntp.org)
Poll interval: 8min 32s (min: 32s; max 34min 8s)
         Leap: normal
      Version: 4
      Stratum: 2
    Reference: 61B7CE58
    Precision: 16us (-16)
Root distance: 22.582ms (max: 5s)
       Offset: +2.708ms
        Delay: 42.957ms
       Jitter: 2.705ms
 Packet count: 5
    Frequency: -11.905ppm

I also cannot reproduce your results:

dig production.cloudflare.docker.com @127.0.0.1 -p 5335

; <<>> DiG 9.11.5-P4-5.1+deb10u8-Debian <<>> production.cloudflare.docker.com @127.0.0.1 -p 5335
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 29034
;; flags: qr rd ra; QUERY: 1, ANSWER: 5, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;production.cloudflare.docker.com. IN	A

;; ANSWER SECTION:
production.cloudflare.docker.com. 300 IN A	104.18.125.25
production.cloudflare.docker.com. 300 IN A	104.18.122.25
production.cloudflare.docker.com. 300 IN A	104.18.124.25
production.cloudflare.docker.com. 300 IN A	104.18.123.25
production.cloudflare.docker.com. 300 IN A	104.18.121.25

;; Query time: 142 msec
;; SERVER: 127.0.0.1#5335(127.0.0.1)
;; WHEN: Tue Oct 18 16:06:05 CDT 2022
;; MSG SIZE  rcvd: 141

Increase your unbound log verbosity to 5 (edit: I see your is currently at 5), restart unbound and repeat the dig command. Then look in the unbound log for the details of the transaction and see where it is failing.

Don't forget to reduce the verbosity after this, or the log file will fill quite quickly.

We would like this output, which shows all the unbound configuration files:

sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*

➜  ~ sudo grep -v '#\|^$' -R /etc/unbound/unbound.conf*
/etc/unbound/unbound.conf:include-toplevel: "/etc/unbound/unbound.conf.d/*.conf"
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:server:
/etc/unbound/unbound.conf.d/root-auto-trust-anchor-file.conf:    auto-trust-anchor-file: "/var/lib/unbound/root.key"
/etc/unbound/unbound.conf.d/pi-hole.conf:server:
/etc/unbound/unbound.conf.d/pi-hole.conf:  logfile: "/var/log/unbound/unbound.log"
/etc/unbound/unbound.conf.d/pi-hole.conf:  verbosity: 1
/etc/unbound/unbound.conf.d/pi-hole.conf:  interface: 127.0.0.1
/etc/unbound/unbound.conf.d/pi-hole.conf:  port: 5335
/etc/unbound/unbound.conf.d/pi-hole.conf:  do-ip4: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  do-udp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  do-tcp: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  do-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:  prefer-ip6: no
/etc/unbound/unbound.conf.d/pi-hole.conf:  harden-glue: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  harden-dnssec-stripped: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  use-caps-for-id: no
/etc/unbound/unbound.conf.d/pi-hole.conf:  edns-buffer-size: 1232
/etc/unbound/unbound.conf.d/pi-hole.conf:  prefetch: yes
/etc/unbound/unbound.conf.d/pi-hole.conf:  num-threads: 1
/etc/unbound/unbound.conf.d/pi-hole.conf:  so-rcvbuf: 1m
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: 192.168.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: 169.254.0.0/16
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: 172.16.0.0/12
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: 10.0.0.0/8
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: fd00::/8
/etc/unbound/unbound.conf.d/pi-hole.conf:  private-address: fe80::/10

Just throwing this out there, as well. It looks like you may be running RaspbianOS and I am running Ubuntu Server 22.0.4 LTS.

➜  ~ unbound -V    
Version 1.13.1

What version of unbound is included in Raspbian?

Interestingly enough, I followed the log setup instructions from documentation and get zero logs in /var/log/unbound/unbound.log regardless of my verbosity level.

In Armbian Buster, which is where that command was run:

`Version 1.9.0'

In Raspbian Bullseye, it's

`Version 1.13.1'

You may not have the correct permissions on the directory or file.

Our guide (by default) uses /var/log/syslog.

You are correct. I am getting logs now. I thought I scripted it to chown to the unbound user. Setting back to 5, running dig and getting the logs. One minute.


Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: udp request from ip4 127.0.0.1 port 55550 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: start
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_new
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: subnet operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet: not found in cache. pass to next module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: subnet module exit state is module_wait_module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator: pass to next module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: validator module exit state is module_wait_module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: process_request: new external request event
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state INIT REQUEST STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: resolving production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: request has dependency depth of 0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: cache delegation returns delegpt
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: DelegationPoint<com.>: 13 names (13 missing), 13 addrs (0 result, 13 avail) cacheNS
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   a.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   h.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   m.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   f.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   d.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   c.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   g.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   b.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   i.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   l.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   k.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   e.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   j.gtld-servers.net.  A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.48.79.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.12.94.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.52.178.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.43.172.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.33.14.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.42.93.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.26.92.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.35.51.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.55.83.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.54.112.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.5.6.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: resolving (init part 2):  production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: resolving (init part 3):  production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: processQueryTargets: production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: DelegationPoint<com.>: 13 names (0 missing), 13 addrs (0 result, 13 avail) cacheNS
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   a.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   h.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   m.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   f.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   d.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   c.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   g.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   b.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   i.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   l.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   k.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   e.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   j.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.48.79.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.12.94.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.52.178.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.43.172.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.33.14.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.42.93.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.26.92.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.35.51.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.55.83.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.54.112.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.5.6.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: removing 2 labels
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: attempt to get extra 3 targets
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.5.6.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=310 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.54.112.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=310 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.55.83.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.35.51.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=270 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.26.92.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.42.93.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.33.14.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.43.172.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=256 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.52.178.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.12.94.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.48.79.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: selrtt 360256
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: chase to recursion lame server
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: chase to dnssec lame server
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: sending query: docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: sending to target: <com.> 192.31.80.30#53
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: dnssec status: expected but lame_query anyway
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: EDNS lookup known=1 vs=0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: serviced query UDP timeout=270 msec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: inserted new pending reply id=6612
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: opened UDP if=0 port=56128
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: comm point start listening 11 (-1 msec)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: iterator module exit state is module_wait_reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 3 recursion replies sent, 0 replies dropped, 0 states jostled out
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: average recursion processing time 0.583109 sec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: histogram of recursion processing times
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: [25%]=0 median[50%]=0 [75%]=0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: lower(secs) upper(secs) recursions
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.000000    0.000001 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.131072    0.262144 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    1.000000    2.000000 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: 0RDd mod2 rep production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: cache memory msg=77465 rrset=83532 infra=15582 val=69418 subnet=74504
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: answer cb
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: Incoming reply id = 6612
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: Incoming reply addr = ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: lookup size is 1 entries
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: received udp reply.
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: udp message[91:0] 66128180000100020000000106646F636B657203636F6D000001000106646F636B657203636F6D00000100010000012C00048DC1D51406646F636B657203636F6D00000100010000012C00048DC1D51500002904D0000080000000
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: outnet handle udp reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: measured roundtrip at 38 msec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: svcd callbacks start
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: worker svcd callback for qstate 0xaaaae08bc0c0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: start
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: iterator operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: process_response: new external response event
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: scrub for com. NS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: response for production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: reply from <com.> 192.31.80.30#53
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; flags: qr rd ra ; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; QUESTION SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: docker.com.#011IN#011A
Oct 18 17:24:58 ns2 unbound[2362]: ;; ANSWER SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: docker.com.#011300#011IN#011A#011141.193.213.20
Oct 18 17:24:58 ns2 unbound[2362]: docker.com.#011300#011IN#011A#011141.193.213.21
Oct 18 17:24:58 ns2 unbound[2362]: ;; AUTHORITY SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; ADDITIONAL SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; MSG SIZE  rcvd: 60
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: query response was ANSWER
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state QUERY TARGETS STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: processQueryTargets: production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: DelegationPoint<com.>: 13 names (0 missing), 13 addrs (13 result, 0 avail) cacheNS
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   a.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   h.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   m.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   f.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   d.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   c.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   g.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   b.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   i.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   l.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   k.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   e.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:   j.gtld-servers.net. * A
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.48.79.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.12.94.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.52.178.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.43.172.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.33.14.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.42.93.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.26.92.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.35.51.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.55.83.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.54.112.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    ip4 192.5.6.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: removing 1 labels
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: attempt to get extra 3 targets
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.48.79.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.12.94.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.52.178.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=256 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.43.172.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.33.14.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.42.93.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=311 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.26.92.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.31.80.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=242 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.35.51.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.55.83.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=306 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.54.112.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=310 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: servselect ip4 192.5.6.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug:    rtt=310 REC_LAME
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: selrtt 360242
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: chase to recursion lame server
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: chase to dnssec lame server
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: sending query: cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: sending to target: <com.> 192.41.162.30#53
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: dnssec status: expected but lame_query anyway
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: EDNS lookup known=1 vs=0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: serviced query UDP timeout=256 msec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: inserted new pending reply id=548b
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: opened UDP if=0 port=26648
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: comm point start listening 12 (-1 msec)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: iterator module exit state is module_wait_reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 3 recursion replies sent, 0 replies dropped, 0 states jostled out
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: average recursion processing time 0.583109 sec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: histogram of recursion processing times
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: [25%]=0 median[50%]=0 [75%]=0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: lower(secs) upper(secs) recursions
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.000000    0.000001 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.131072    0.262144 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    1.000000    2.000000 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: 0RDd mod2 rep production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: cache memory msg=77465 rrset=83532 infra=15582 val=69418 subnet=74504
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: svcd callbacks end
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: serviced_delete
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: close of port 56128
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: comm_point_close of 11: event_del
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: close fd 11
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: answer cb
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: Incoming reply id = 548b
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: Incoming reply addr = ip4 192.41.162.30 port 53 (len 16)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: lookup size is 1 entries
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: received udp reply.
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: udp message[144:0] 548B818300010000000100010A636C6F7564666C61726506646F636B657203636F6D000001000106646F636B657203636F6D00000600010000001E0048066E732D32303709617773646E732D323503636F6D0011617773646E732D686F73746D617374657206616D617A6F6E03636F6D000000000100001C2000000384001275000001518000002904D0000080000000
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: outnet handle udp reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: measured roundtrip at 17 msec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: svcd callbacks start
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: worker svcd callback for qstate 0xaaaae08bc0c0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: start
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: iterator operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: process_response: new external response event
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: scrub for com. NS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: response for production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: reply from <com.> 192.41.162.30#53
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: incoming scrubbed packet: ;; ->>HEADER<<- opcode: QUERY, rcode: NXDOMAIN, id: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; QUESTION SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: cloudflare.docker.com.#011IN#011A
Oct 18 17:24:58 ns2 unbound[2362]: ;; ANSWER SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; AUTHORITY SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: docker.com.#01130#011IN#011SOA#011ns-207.awsdns-25.com. awsdns-hostmaster.amazon.com. 1 7200 900 1209600 86400
Oct 18 17:24:58 ns2 unbound[2362]: ;; ADDITIONAL SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; MSG SIZE  rcvd: 117
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state QUERY RESPONSE STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: query response was NXDOMAIN ANSWER
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: finishing processing for production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: iterator module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator: nextmodule returned
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: val handle processing q with state VAL_INIT_STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator classification nameerror
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: no signer, using production.cloudflare.docker.com. TYPE0 CLASS0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: val handle processing q with state VAL_FINDKEY_STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator: FindKey production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: current keyname com. DNSKEY IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: target keyname production.cloudflare.docker.com. DNSKEY IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: striplab 2
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: next keyname docker.com. DNSKEY IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: No DS RRset
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: generate request docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: validator module exit state is module_wait_subquery
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet[module 0] operate: extstate:module_state_initial event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: subnet operate: query docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet: pass to next module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: subnet module exit state is module_wait_module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator operate: query docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator: pass to next module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: validator module exit state is module_wait_module
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: process_request: new external request event
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state INIT REQUEST STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: resolving docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: request has dependency depth of 0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: msg from cache lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; flags: qr rd ra ; QUERY: 1, ANSWER: 0, AUTHORITY: 6, ADDITIONAL: 0
Oct 18 17:24:58 ns2 unbound[2362]: ;; QUESTION SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: docker.com.#011IN#011DS
Oct 18 17:24:58 ns2 unbound[2362]: ;; ANSWER SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; AUTHORITY SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: CK0POJMG874LJREF7EFN8430QVIT8BSM.com.#01125220#011IN#011NSEC3#0111 1 0 - ck0q2d6ni4i7eqh8na30ns61o48ul8g5 NS SOA RRSIG DNSKEY NSEC3PARAM ;{flags: optout}
Oct 18 17:24:58 ns2 unbound[2362]: CK0POJMG874LJREF7EFN8430QVIT8BSM.com.#01125220#011IN#011RRSIG#011NSEC3 8 2 86400 20221022042440 20221015031440 32298 com. mHMUqA9ScK1Cq8VuAlPTPHgJ7bAPl+WDpIPjo3d8Yhmpe4cJc5zUnzRIbLsEK5UyUfSn2Ytj5QF0J6XcShdavB9KWOBf5OVsstqXoi3oh59NuuyaKMZ5WRZ4TnY/aa79W7nMIB9mim4XKgdl3Tp7Oo40FrbvZ4JRf0onGxwknZn3QbFrkzK7dJk/JIRGyR0yrif6fnmHRCOmWsdYkMiFog== ;{id = 32298}
Oct 18 17:24:58 ns2 unbound[2362]: com.#011467#011IN#011SOA#011a.gtld-servers.net. nstld.verisign-grs.com. 1666127837 1800 900 604800 86400
Oct 18 17:24:58 ns2 unbound[2362]: com.#011467#011IN#011RRSIG#011SOA 8 1 900 20221025211717 20221018200717 53929 com. CAKV5rnaaApiEiCKbCJ3/ogOy+hOsrvA/Vgdl8WKjBLTr+nXQHQuM2Nf1XvraNPXvfLTLNw7OpAzMuUKVfyMAWKfxwoL4XL2etBzJmeK7ipItrW8s9ku5S7uzeJnEgO/j2I0p4wGBPceh2FA6BNnBtQr87hnZDSgUngHC5uZLbffEXkdQ+ArOwGBt6YT7eUtgZwOa1WlJZKaM7Pg7rt01A== ;{id = 53929}
Oct 18 17:24:58 ns2 unbound[2362]: 8CELDSU2MN5PAAUQM465IP3UJ7AAEFTR.com.#01168243#011IN#011NSEC3#0111 1 0 - 8celjrvjr4epps1k7ab5q6njpdrrrmrq NS DS RRSIG ;{flags: optout}
Oct 18 17:24:58 ns2 unbound[2362]: 8CELDSU2MN5PAAUQM465IP3UJ7AAEFTR.com.#01168243#011IN#011RRSIG#011NSEC3 8 2 86400 20221023042851 20221016031851 53929 com. Dc7xKaCVh0tu0iAltivziZDQhsdZr+dMCkuINwVyfN/VmTaUDFcueA/Q9Th5S8Vvg/p9EYtyqMFisnLysvCPJ7LO62G6bWRJafdYJPlTgt+EADUGQESfHV6HH/Y9fxqS7YXIypcSvh7EPfEH8odLe23uHsK7iCIGNfU11FNHPsZlvm1FLVgLQDpASeDgrwnbYn+ug++ME3L+V1f0BkUcUg== ;{id = 53929}
Oct 18 17:24:58 ns2 unbound[2362]: ;; ADDITIONAL SECTION:
Oct 18 17:24:58 ns2 unbound[2362]: ;; MSG SIZE  rcvd: 845
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: msg ttl is 467, prefetch ttl 379
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: returning answer from cache.
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: iter_handle processing q with state FINISHED RESPONSE STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: finishing processing for docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: iterator module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator operate: query docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator: nextmodule returned
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: not validating response, is valrec(validation recursion lookup)
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: validator module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: subnet operate: query docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: subnet module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator: inform_super, sub is docker.com. DS IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: super is production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: nsec3: keysize 1280 bits, max iterations 500
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: ce candidate com. TYPE0 CLASS0
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: NSEC3s for the referral proved no DS.
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: validator[module 1] operate: extstate:module_wait_subquery event:module_event_pass
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: validator operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: val handle processing q with state VAL_VALIDATE_STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: Verified that unsigned response is INSECURE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: val handle processing q with state VAL_FINISHED_STATE
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: validator module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: subnet[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: subnet operate: query production.cloudflare.docker.com. A IN
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: mesh_run: subnet module exit state is module_finished
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: query took 0.055736 sec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 4 recursion replies sent, 0 replies dropped, 0 states jostled out
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: average recursion processing time 0.451266 sec
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: histogram of recursion processing times
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: [25%]=1e-06 median[50%]=0.065536 [75%]=0.262144
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info: lower(secs) upper(secs) recursions
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.000000    0.000001 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.032768    0.065536 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    0.131072    0.262144 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] info:    1.000000    2.000000 1
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: cache memory msg=77465 rrset=83532 infra=15582 val=69418 subnet=74504
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: svcd callbacks end
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: serviced_delete
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: close of port 26648
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: comm_point_close of 12: event_del
Oct 18 17:24:58 ns2 unbound[2362]: [1666128298] unbound[2362:0] debug: close fd 12
➜  ~ 

I'm no expert when it comes to interpreting unbound logs, but I'm afraid yours above won't tell us much - it just shows the answer was drawn from unbound's cache:

But before you go about another attempt to log the actual recursion:
We currently have a very similar report, involving unbound and hub.docker.com, where resolution seems to have returned to normal:

If production.cloudflare.docker.com would be resolving again for you as well, that could suggest some transient issues with the configuration of authoritative DNS records, rather than unbound or Pi-hole.

Hello jmcomb

Indeed your issue is related to mine.
As I reported in my topic yesterday, docker hub was resolving again. But today
it is not anymore. Did some testing here and there and sometimes it worked sometimes not. I couldn't find a pattern.

I enabled unbound logging and will take a look at it later and report back.

The workaround that I have in place, for now is:

  1. Edit and Add the following to the end of /etc/unbound/unbound.conf.d/pi-hole.conf:
forward-zone:
  name: "docker.com"
  forward-tls-upstream: yes
  forward-addr: 1.1.1.1@853
  forward-addr: 1.0.0.1@853
  1. Restart unbound via sudo systemctl restart unbound

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.