search

NLnetLabs / unbound

Unbound is a validating, recursive, and caching DNS resolver.
https://nlnetlabs.nl/unbound
BSD 3-Clause "New" or "Revised" License
3.04k stars 349 forks source link

Forwarding to mixed block of IPv4 and IPv6 name server addresses effectively doubles the query response time #899

Closed RobbieTT closed 1 year ago

RobbieTT commented 1 year ago

Forwarding to a mixed block of IPv4 and IPv6 name server addresses effectively doubles the query response time, as the IPv6 sever address query does not start until the IPv4 query has completed (ie it runs sequentially, not in parallel). Additionally, both IPv4 and IPv6 queries have to be fully resolved before any answer is provided to clients.

unbound Version 1.17.1 as bundled with pfSense Plus Version 23.05-Release

Desired behaviour:

With a list of forwarding name servers containing both IPv4 and IPv6 addresses (example below) the lookups should run in parallel with the option of selecting the fastest response from the 2 chosen servers selected by unbound in the normal manner. This would also provide an element of fallback should either the IPv4 or IPv6 address fail to provide a response, as well as a faster 'first-past-the-post' response.

It is accepted that the number of queries sent will still be doubled (as it is now) but by running in parallel it would avoid a faster IPv4 response being masked to the client until the IPv6 query has started and run to completion (or vice versa). As a stretch target, it would be ideal if the normal unbound forwarder selection behaviour was IPv4/6 agnostic, allowing either address protocol to be utilised by the selection algorithm, as this would halve the traffic and mimic the current behaviour if only IPv4 or IPv6 addressed forwarders were in use.

Attachments PCAP overview showing sequential IPv4 query-response + IPv6 query-response-answer 6 & answer 4:

245245570-3a8edf00-47ce-40d7-86b4-33ae70de4e4a

Forwarding addresses used in the above example:

forward-zone: name: "." forward-tls-upstream: yes forward-addr: 9.9.9.9@853#dns.quad9.net forward-addr: 149.112.112.112@853#dns.quad9.net forward-addr: 2620:fe::fe@853#dns.quad9.net forward-addr: 2620:fe::9@853#dns.quad9.net

☕️

wcawijngaards commented 1 year ago

There seems to be a bunch of things going on, and some comments on each part could be useful. I'll put them down one by one.

For Unbound, normally, queries are processed in parallel. The server selection algorithm treats IPv4 and IPv6 equally. So it should be fine. When a query gets an answer from the upstream, it is immediately provided to the client, it does not wait for other client queries. In some cases it may wait for internally generated queries to validate DNSSEC security, but it does not wait until a client has been answered.

wcawijngaards commented 1 year ago

The pcap seems to show, from what I can tell on that screenshot, there is first traffic over IPv4 and later traffic over IPv6. This would be a normal sequence of events if the following happens, for example. The client asks a query, randomly the IPv4 is chosen, a one in 4 chance, roughly, that provides an answer. The answer is returned to the client. The client then asks another query. Randomly the IPv6 upstream is chosen to answer it, and this then provides an answer. That is then also returned to the client. The reason it is not in parallel, is that the client, the querier, is making queries in sequence. Like for example asking for an A and then later for a AAAA address, or other query types than IPv4 and IPv6 addresses. This is the standard behaviour of some queriers, notably things like resolv.conf and systemd, but there may also be options to have them make parallel queries.

Unbound has options to prefer the fastest server from the set. But normally this is not needed, and I think also not here. The default has a mix of randomness and preferring faster target from unresponsive targets, and also filtering unusual response targets, and I think is probably fine. Perhaps the response time issue that is seen, is not the ping-time responsiveness, but in fact the DNS resolution time. I mean, when a query is not in the cache for the destination, the server has to look up the data and this takes time. Much longer than the fast ping time that the upstream has. If this is considered an issue, what you could do, is not use forwarding, but instead have unbound run full resolver, and make this lookups itself. Then unbound is slow and takes that time to look up the data. But that behaviour is then visible, in the logs of Unbound, instead of hidden behind the upstream forwarder. That separates the concern of upstream forwarder speed from the resolution speed, or, makes it visible in logs. That said, there are options to make unbound prefer the fastest ping time, fast-server-permil: 900 for example, selects the fastest 90% of the time. The fast-server-num option can fine tune it. The prefer-ip6 and prefer-ip4 options can make unbound's server selection algorithm prefer that type of address, it would still be parallel for making lookups. But select those addresses by preference.

wcawijngaards commented 1 year ago

It is possible to get information from unbound, and that could be easier to read, or have more information than the pcap, with like verbosity: 5, unbound has extensive logs, and also prints the querier address for incoming queries. It would be useful to have this information, because it can reveal what is going on inside unbound. Can you get these logs? Then it could be used to debug the sequential processing issue.

It could also be useful to have more control over the incoming queries, in some way. Not sure what is used now, perhaps use a commandline lookup tool, and then control the sequential or parallel lookups by typing them one after the other or at the same time, in a different commandline terminal?

Also the unbound logs would show what is happening inside the TLS channel, but that content does not seem to be a problem, right now.

RobbieTT commented 1 year ago

Thanks to all.

The pcap seems to show, from what I can tell on that screenshot, there is first traffic over IPv4 and later traffic over IPv6. This would be a normal sequence of events if the following happens, for example. The client asks a query, randomly the IPv4 is chosen, a one in 4 chance, roughly, that provides an answer. The answer is returned to the client. The client then asks another query. Randomly the IPv6 upstream is chosen to answer it, and this then provides an answer. That is then also returned to the client. The reason it is not in parallel, is that the client, the querier, is making queries in sequence. Like for example asking for an A and then later for a AAAA address, or other query types than IPv4 and IPv6 addresses.

In the pcap example above it was a single client asking a single query with pcap taken on the WAN side of the router/firewall. The domain name was kia.com, as I knew this would not be in the cache:

Regarding the fast-server-permil, the pfSense documentation states a value of 900 is set by them as standard. This could be the case but I did not see it explicitly set in the unbound.conffile. I have already noted a mismatch between an unrelated setting in the pfSense GUI vs unbound config, which works in the opposite sense of that stated, so this may need an expert eye on my actual unbound config using pfSense unbound's default settings for forwarding:

Click: Actual unbound.conf file (redacted) ` [23.05-RELEASE][admin@Router-8.redacted.me]/root: unbound-checkconf /var/unbound/unbound.conf unbound-checkconf: no errors in /var/unbound/unbound.conf [23.05-RELEASE][admin@Router-8.redacted.me]/root: cat /var/unbound/unbound.conf ########################## # Unbound Configuration ########################## ## # Server configuration ## server: chroot: /var/unbound username: "unbound" directory: "/var/unbound" pidfile: "/var/run/unbound.pid" use-syslog: yes port: 53 verbosity: 1 hide-identity: yes hide-version: yes harden-glue: yes do-ip4: yes do-ip6: yes do-udp: yes do-tcp: yes do-daemonize: yes module-config: "iterator" unwanted-reply-threshold: 0 num-queries-per-thread: 512 jostle-timeout: 200 infra-keep-probing: yes infra-host-ttl: 900 infra-cache-numhosts: 20000 outgoing-num-tcp: 10 incoming-num-tcp: 10 edns-buffer-size: 1432 cache-max-ttl: 86400 cache-min-ttl: 2400 harden-dnssec-stripped: no msg-cache-size: 50m rrset-cache-size: 100m num-threads: 4 msg-cache-slabs: 4 rrset-cache-slabs: 4 infra-cache-slabs: 4 key-cache-slabs: 4 outgoing-range: 4096 #so-rcvbuf: 4m prefetch: yes prefetch-key: yes use-caps-for-id: no serve-expired: yes aggressive-nsec: no # Statistics # Unbound Statistics statistics-interval: 0 extended-statistics: yes statistics-cumulative: yes # TLS Configuration tls-cert-bundle: "/etc/ssl/cert.pem" # Interface IP addresses to bind to interface: 172.16.1.1 interface: 2a02:redacted interface: 10.0.1.1 interface: 2a02:redacted interface: 127.0.0.1 interface: ::10.10.10.1 # Outgoing interfaces to be used outgoing-interface: 93.redacted outgoing-interface: 2a02:redacted outgoing-interface: 127.0.0.1 outgoing-interface: ::10.10.10.1 # DNS Rebinding # For DNS Rebinding prevention private-address: 127.0.0.0/8 private-address: 10.0.0.0/8 private-address: ::ffff:a00:0/104 private-address: 172.16.0.0/12 private-address: ::ffff:ac10:0/108 private-address: 169.254.0.0/16 private-address: ::ffff:a9fe:0/112 private-address: 192.168.0.0/16 private-address: ::ffff:c0a8:0/112 private-address: fd00::/8 private-address: fe80::/10 # Access lists include: /var/unbound/access_lists.conf # Static host entries include: /var/unbound/host_entries.conf # dhcp lease entries include: /var/unbound/dhcpleases_entries.conf # Domain overrides include: /var/unbound/domainoverrides.conf # Forwarding forward-zone: name: "." forward-tls-upstream: yes forward-addr: 9.9.9.9@853#dns.quad9.net forward-addr: 149.112.112.112@853#dns.quad9.net forward-addr: 2620:fe::fe@853#dns.quad9.net forward-addr: 2620:fe::9@853#dns.quad9.net # Unbound custom options server: log-queries: yes server:include: /var/unbound/pfb_dnsbl.*conf ### # Remote Control Config ### include: /var/unbound/remotecontrol.conf [23.05-RELEASE][admin@Router-8.redacted.me]/root: `

It is possible to get information from unbound, and that could be easier to read, or have more information than the pcap, with like verbosity: 5, unbound has extensive logs, and also prints the querier address for incoming queries. It would be useful to have this information, because it can reveal what is going on inside unbound. Can you get these logs? Then it could be used to debug the sequential processing issue.

Yes, that should be possible at the verbosity level requested.

It could also be useful to have more control over the incoming queries, in some way. Not sure what is used now, perhaps use a commandline lookup tool

I have been using dig from either a LAN client or from pfSense/BSD CLI. I have a further option to perform a look-up via the pfSense GUI directly but I presume that offers nothing different, under the hood.

Is dig sufficient for testing and is there an easy way to disable the cache temporarily (ie without killing the 'warm' cache contents) so I don't have to dream-up unlikely domain names?

wcawijngaards commented 1 year ago

How surprising that it makes two queries to resolve the domain name. If it gets one query, I would expect only one upstream query. The logs could tell what is going on. Or maybe it is a CNAME and then it resolves the target of the cname. In which case it looks very normal.

The config looks okay. Nothing I would note.

The unbound-control utility has a command to flush the cache for a name, it is then resolved the next time it is asked. unbound-control flush example.com for example.

It is not making two concurrent queries then, there is only one query coming in, and this is getting answered.

dig should be great for testing. It is also possible to use dig or a commandline tool to make queries towards the upstream servers, at their IPv4 and IPv6 address, and then it shows what they answer.

Is it just this one time, or is IPv6 a lot slower than IPv4? I would imagine that the upstream resolver is located roughly in the same place, so the time increase is a bit. If the IPv6 connection has a lot of lag on it, something that can be attributed to tunnels, perhaps prefer-ip4: yes is an option that can increase the speed.

RobbieTT commented 1 year ago

...dig should be great for testing. It is also possible to use dig or a commandline tool to make queries towards the upstream servers, at their IPv4 and IPv6 address, and then it shows what they answer.

Perfect.

Is it just this one time, or is IPv6 a lot slower than IPv4? I would imagine that the upstream resolver is located roughly in the same place, so the time increase is a bit.

Typically Ipv6 is slightly faster and the raw returns from the forwarder are typically in the <12ms range. Handshakes and DoT increase that by multiples; add in a use of a temporarily slower server and things can become quite protracted.

2023-06-20 at 21 48 03

☕️

wcawijngaards commented 1 year ago

The screenshot of timers, shows that the ping times are fine. But the IPv6 addresses, both of them, have an RTO that is much larger than the RTT, this is an increase because of recent timeouts. It has exponentially backed off. The IPv4 addresses are fine, and do not seem to have a lot of timeouts, even though 1 is listed in the timeout other column. The ping is fine, when it connects, but the IPv6 addresses have timeouts, perhaps this is causing slowdown.

RobbieTT commented 1 year ago

The ping is fine, when it connects, but the IPv6 addresses have timeouts, perhaps this is causing slowdown.

It could be exactly that but I am not sure how these counters work. If they are cumulative the errors over the ~12 days the router has been 'up' they look inconsequential.

Another thing I don't understand in the table is the reported ping time, which varies between 20 to 28 ms. If I ping any of those servers directly they return an average of 7.522 ms. I have run ping plotter against them and the trace is reassuringly flat. Pinging from the router itself to 9.9.9.9 directly provides these figures:

[23.05-RELEASE][admin@Router-8.redacted.me]/root: ping 9.9.9.9
PING 9.9.9.9 (9.9.9.9): 56 data bytes
64 bytes from 9.9.9.9: icmp_seq=0 ttl=62 time=7.470 ms
64 bytes from 9.9.9.9: icmp_seq=1 ttl=62 time=7.590 ms
64 bytes from 9.9.9.9: icmp_seq=2 ttl=62 time=7.571 ms
64 bytes from 9.9.9.9: icmp_seq=3 ttl=62 time=7.529 ms
64 bytes from 9.9.9.9: icmp_seq=4 ttl=62 time=7.534 ms
64 bytes from 9.9.9.9: icmp_seq=5 ttl=62 time=7.392 ms
64 bytes from 9.9.9.9: icmp_seq=6 ttl=62 time=7.483 ms
64 bytes from 9.9.9.9: icmp_seq=7 ttl=62 time=7.589 ms
64 bytes from 9.9.9.9: icmp_seq=8 ttl=62 time=7.563 ms
64 bytes from 9.9.9.9: icmp_seq=9 ttl=62 time=7.504 ms
^C
--- 9.9.9.9 ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 7.392/7.522/7.590/0.059 ms
[23.05-RELEASE][admin@Router-8.redacted.me]/root:

The values are those expected of my connection but not representative of the table extracted from unbound.

Pinging from a wired client behind the router is no different (aside from the TTL & added latency of the extra hop):

[snip]
64 bytes from 9.9.9.9: icmp_seq=9 ttl=61 time=7.888 ms
^C
--- 9.9.9.9 ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 7.703/7.816/7.919/0.076 ms
rob@Smaug ~ %

Of course, the unbound data requested of me earlier can only help (waiting for a suitable network opportunity) but if any clarity can be added on how to correctly interpret the data in the unbound table above would be helpful.

☕️

wcawijngaards commented 1 year ago

The higher value of the ping is likely the TLS handshake that is counted in. If forward-tls-upstream was turned off, unbound would use UDP and then get those ping values too. Yes the logs could be useful. The timeouts look to be a problem, to me, because the high value of 600+ msec compared to the roundtrip time of 70-80 msec, that is about 8x, or 3 timeouts that happened in sequence. So both of them have had 3 connections fail. Now the RTO is so large, that unbound is likely no longer choosing them and is using only the IPv4 addresses by preference.

RobbieTT commented 1 year ago

Answering one of my own questions as just took a snapshot of the unbound table as it sits this morning:

2023-06-21 at 09 44 43

So the timeout errors are not cumulative but the ping values still look odd - especially achieving a value below the physical latency of my connection.

RobbieTT commented 1 year ago

@wcawijngaards our responses crossed each other but your comments makes my table above look even weirder. I'll let you ponder them but I suspect that you probably don't have enough data from me just yet to fully explain them.

☕️

wcawijngaards commented 1 year ago

The low value is very likely due to lack of information, there are almost no observations of a roundtrip, and the estimate is mostly variance, the average is just uncertain. So that is not really a problem. The RTT value is the ping value and the variance combined, and the RTO value has timeout backoff applied to it. No, the timeouts are kept track of temporarily, and this table shows again timeouts that have happened.

RobbieTT commented 1 year ago

@wcawijngaards Thanks for the subtle prod over TCP, I could have added +tcp to the ping command but, well, I didn't - Doh!

I'm now fighting the unbound-control flush example.com command as it returns the following

[23.05-RELEASE][admin@Router-8.redacted.me]/root: unbound-control flush example.com
[1687341019] unbound-control[54714:0] warning: control-enable is 'no' in the config file.
[1687341019] unbound-control[54714:0] error: connect: Connection refused for 127.0.0.1 port 8953
[23.05-RELEASE][admin@Router-8.redacted.me]/root:

This makes simple & repeatable testing somewhat challenging.

The pfSense config of unbound has this at the very end:

###
# Remote Control Config
###
include: /var/unbound/remotecontrol.conf

The file referenced contains this:

[23.05-RELEASE][admin@Router-8.redacted.me]/root: cat /var/unbound/remotecontrol.conf
remote-control:
    control-enable: yes
    control-interface: 127.0.0.1
    control-port: 953
    server-key-file: "/var/unbound/unbound_server.key"
    server-cert-file: "/var/unbound/unbound_server.pem"
    control-key-file: "/var/unbound/unbound_control.key"
    control-cert-file: "/var/unbound/unbound_control.pem"
[23.05-RELEASE][admin@Router-8.redacted.me]/root:

So it does not reflect the example in the unbound documentation and, in this case, it does not work.

Any ideas on what needs fixing?

☕️

[I seem to be dragging you around with my unfamiliarity with unbound & pfSense; I do apologise and appreciate the help.]

wcawijngaards commented 1 year ago

The unbound-control tool seems to be reading from a different config file. The -c option can be used to specify one.

RobbieTT commented 1 year ago

I tried the -c command to point at the actual unbound.conf file location but it didn't accept it:

[23.05-RELEASE][admin@Router-8.redacted.me]/root: unbound-control -c /var/unbound/unbound.conf
Usage:  unbound-control [options] command
    Remote control utility for unbound server. 
[...snip]

I also checked the unbound-control status, post the -c command:

[23.05-RELEASE][admin@Router-8.redacted.me]/root: unbound-control status
[1687349207] unbound-control[67259:0] warning: control-enable is 'no' in the config file.
[1687349207] unbound-control[67259:0] error: connect: Connection refused for 127.0.0.1 port 8953
unbound is stopped
[23.05-RELEASE][admin@Router-8.redacted.me]/root:

I'm not sure if this is relevant or not but the remotecontrol.conf file has a control-port of 953 vs 8953 shown above:

[23.05-RELEASE][admin@Router-8.redacted.me]/root: cat /var/unbound/remotecontrol.conf
remote-control:
    control-enable: yes
    control-interface: 127.0.0.1
    control-port: 953
    server-key-file: "/var/unbound/unbound_server.key"
    server-cert-file: "/var/unbound/unbound_server.pem"
    control-key-file: "/var/unbound/unbound_control.key"
    control-cert-file: "/var/unbound/unbound_control.pem"
[23.05-RELEASE][admin@Router-8.redacted.me]/root:

I'm either lost in unbound syntax or failing to understand how pfSense arranges the unbound.conf and the additional files it points to.

☕️ time

wcawijngaards commented 1 year ago

The first command is failing because there is no command on the commandline. The second has a status command.

RobbieTT commented 1 year ago

Aargh, I think my brain has failed and your patience is appreciated. I guess I should have been typing:

unbound-control -c /var/unbound/unbound.conf flush example.com

RobbieTT commented 1 year ago

unbound set at verbosity 5, using just 2 Quad9 IPv4 server addresses, so I am presuming no major issues here:

Click: unbound log v5 for approx 1 second (redacted) Jun 27 16:15:32 Router-8 unbound[96737]: [96737:0] debug: chdir to /var/unbound Jun 27 16:15:32 Router-8 unbound[96737]: [96737:0] debug: chroot to /var/unbound Jun 27 16:15:32 Router-8 unbound[96737]: [96737:0] debug: drop user privileges, run as unbound Jun 27 16:15:32 Router-8 unbound[96737]: [96737:0] debug: duplicate acl address ignored. Jun 27 16:15:34 Router-8 unbound[96737]: [96737:0] info: implicit transparent local-zone . TYPE0 IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: ignoring duplicate RR: localhost. AAAA ::1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: ignoring duplicate RR: localhost. A 127.0.0.1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: module config: "iterator" Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] notice: init module 0: iterator Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: target fetch policy for level 0 is 3 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: target fetch policy for level 1 is 2 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: target fetch policy for level 2 is 1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: target fetch policy for level 3 is 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: target fetch policy for level 4 is 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: donotq: 127.0.0.0/8 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: donotq: ::1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: total of 59448 outgoing ports available Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: start threads Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: Forward zone server list: Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: no config, using builtin root hints. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: start of service (unbound 1.17.1). Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: new control connection from ip4 127.0.0.1 port 43446 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm point stop listening 34 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm point start listening 34 (120000 msec) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: Forward zone server list: Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: Forward zone server list: Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: Forward zone server list: Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: no config, using builtin root hints. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: no config, using builtin root hints. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 2a02:reda:cted:1:61d1:952d:4c9a:41c8 MBP-Rob.redacted.me. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: using localzone redacted.me. transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 30989 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: resolving outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: no config, using builtin root hints. Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: processQueryTargets: outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 30739 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: resolving outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: attempt to get extra 3 targets Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: 2a02:reda:cted:1:61d1:952d:4c9a:41c8 MBP-Rob.redacted.me. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: processQueryTargets: outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: attempt to get extra 3 targets Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: sending query: outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: sending to target: <.> 149.112.112.112#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: 2a02:reda:cted:1:61d1:952d:4c9a:41c8 imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: dnssec status: not expected Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: using localzone redacted.me. transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 0RDd mod0 rep outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: 2a02:reda:cted:1:61d1:952d:4c9a:41c8 imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: sending query: outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: sending to target: <.> 9.9.9.9#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: dnssec status: not expected Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: udp request from ip6 2a02:reda:cted:1:61d1:952d:4c9a:41c8 port 52983 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 0RDd mod0 rep outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: udp request from ip6 2a02:reda:cted:1:61d1:952d:4c9a:41c8 port 63116 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: resolving imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: resolving imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 40294 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: resolving outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: processQueryTargets: imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: attempt to get extra 3 targets Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: processQueryTargets: imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: attempt to get extra 3 targets Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 2a02:reda:cted:1:61d1:952d:4c9a:41c8 imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: processQueryTargets: outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: sending query: imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: sending to target: <.> 9.9.9.9#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: dnssec status: not expected Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: udp request from ip6 2a02:reda:cted:1:61d1:952d:4c9a:41c8 port 52983 (len 28) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: attempt to get extra 3 targets Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: sending query: imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: sending to target: <.> 9.9.9.9#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: sending query: outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: dnssec status: not expected Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: process_request: new external request event Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: resolving imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 0RDd mod0 rep outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 1RDd mod0 rep outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: processQueryTargets: imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: selrtt 376 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: sending to target: <.> 9.9.9.9#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: mesh_run: end 2 recursion states (2 with reply, 0 detached), 2 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 1RDd mod0 rep outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: mesh_run: start Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: request has dependency depth of 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: udp request from ip4 10.0.1.29 port 31365 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: resolving outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 10.0.1.29 outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: forwarding request Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: processQueryTargets: outlook.office.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: udp request from ip4 10.0.1.29 port 36295 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: sending query: imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: sending to target: <.> 149.112.112.112#853 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: udp request from ip4 10.0.1.29 port 34263 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] info: 10.0.1.29 outlook.office.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: using localzone . transparent Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] info: 10.0.1.10 MBP-Rob.redacted.me. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: udp request from ip4 10.0.1.29 port 50799 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: 0RDd mod0 rep imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: 1RDd mod0 rep imap.gmail.com. AAAA IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: dnssec status: not expected Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: reuse_tcp_find: num reuse streams 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: reuse_tcp_find: num reuse streams 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] info: 0RDd mod0 rep imap.gmail.com. A IN Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: reuse_tcp_insert 9.9.9.9#853 fd -1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm point start listening 35 (-1 msec) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: startlistening 35 mode rw Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: reuse_tcp_find Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: reuse_tcp_find check inexact match Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: reuse_tcp_find Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: reuse_tcp_find: num reuse streams 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: cache memory msg=66072 rrset=66072 infra=8306 val=0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: reuse_tcp_insert 149.112.112.112#853 fd -1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: tcp bound to src ip4 re.da.ct.ed port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: comm point start listening 36 (-1 msec) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_find Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_find: num reuse streams 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: reuse_tcp_find: num reuse streams 1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: reuse_tcp_find: num reuse streams 1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: pending_tcp_query: found reuse 9.9.9.9#853 fd 38 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: pending_tcp_query: new fd, connect Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: pending_tcp_query: reuse, store Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_insert 9.9.9.9#853 fd -1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: comm point start listening 39 (-1 msec) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: startlistening 39 mode rw Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: serviced send timer Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: pending_tcp_query Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_find Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_find check inexact match Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: tcp bound to src ip4 re.da.ct.ed port 0 (len 16) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: reuse_tcp_insert 149.112.112.112#853 fd -1 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: comm point start listening 40 (-1 msec) Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: startlistening 40 mode rw Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm point listen_for_rw 35 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: comm point listen_for_rw 38 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: comm point listen_for_rw 36 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: comm point listen_for_rw 39 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm point listen_for_rw 37 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: comm point listen_for_rw 40 0 Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: remote control connection authenticated Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] info: control cmd: stats_noreset Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: write stats cmd Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: wait for stats reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: got control cmd stats_noreset Jun 27 16:15:40 Router-8 unbound[96737]: [96737:1] debug: write stats replymsg Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: write stats cmd Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: wait for stats reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: got control cmd stats_noreset Jun 27 16:15:40 Router-8 unbound[96737]: [96737:2] debug: write stats replymsg Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: write stats cmd Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: wait for stats reply Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: got control cmd stats_noreset Jun 27 16:15:40 Router-8 unbound[96737]: [96737:3] debug: write stats replymsg Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: remote control operation completed Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: comm_point_close of 34: event_del Jun 27 16:15:40 Router-8 unbound[96737]: [96737:0] debug: close fd 34 [23.05-RELEASE][admin@Router-8.redacted.me]/root:

I'll re-run with the Quad9 IPv6 name servers added to the forwarding list when network traffic allows.

☕️

RobbieTT commented 1 year ago

@wcawijngaards

It is possible to get information from unbound, and that could be easier to read, or have more information than the pcap, with like verbosity: 5, unbound has extensive logs, and also prints the querier address for incoming queries. It would be useful to have this information, because it can reveal what is going on inside unbound. Can you get these logs? Then it could be used to debug the sequential processing issue.

Also the unbound logs would show what is happening inside the TLS channel, but that content does not seem to be a problem, right now.

As requested:

Click: unbound log verbosity 5 for IPv4 and IPv6 forwarders [Quad9] (redacted) [23.05-RELEASE][admin@Router-8.redacted.me]/root: cat /var/log/resolver.log Jun 27 17:12:09 Router-8 unbound[71149]: [71149:0] debug: chdir to /var/unbound Jun 27 17:12:09 Router-8 unbound[71149]: [71149:0] debug: chroot to /var/unbound Jun 27 17:12:09 Router-8 unbound[71149]: [71149:0] debug: drop user privileges, run as unbound Jun 27 17:12:09 Router-8 unbound[71149]: [71149:0] debug: duplicate acl address ignored. Jun 27 17:12:11 Router-8 unbound[71149]: [71149:0] info: implicit transparent local-zone . TYPE0 IN Jun 27 17:12:17 Router-8 unbound[71149]: [71149:0] debug: ignoring duplicate RR: localhost. AAAA ::1 Jun 27 17:12:17 Router-8 unbound[71149]: [71149:0] debug: ignoring duplicate RR: localhost. A 127.0.0.1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: module config: "iterator" Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] notice: init module 0: iterator Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: target fetch policy for level 0 is 3 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: target fetch policy for level 1 is 2 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: target fetch policy for level 2 is 1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: target fetch policy for level 3 is 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: target fetch policy for level 4 is 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: donotq: 127.0.0.0/8 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: donotq: ::1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: total of 59448 outgoing ports available Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: start threads Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: Forward zone server list: Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: no config, using builtin root hints. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: start of service (unbound 1.17.1). Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: new control connection from ip4 127.0.0.1 port 52154 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point stop listening 33 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point start listening 33 (120000 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: Forward zone server list: Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: Forward zone server list: Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: Forward zone server list: Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: no config, using builtin root hints. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: no config, using builtin root hints. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: udp request from ip6 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 port 53963 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone redacted.me. transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: no config, using builtin root hints. Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip6 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 port 65123 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: resolving _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: using localzone redacted.me. transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: resolving lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: udp request from ip6 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 port 65123 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: processQueryTargets: _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: processQueryTargets: lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: resolving lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: processQueryTargets: lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: udp request from ip6 2a02:reda:cted:1:c9e4:dcd0:9b5d:3182 port 53963 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: resolving _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: processQueryTargets: _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: sending query: lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: sending query: _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: sending to target: <.> 9.9.9.9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: sending query: lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: sending to target: <.> 9.9.9.9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 0RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 0RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 0RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 10.0.1.59 Router-8.redacted.me. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: sending query: _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: using localzone redacted.me. transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 10.0.1.11 time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 10.0.1.11 stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip4 10.0.1.11 port 49424 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 0RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: resolving time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: udp request from ip4 10.0.1.11 port 57897 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: processQueryTargets: time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: resolving stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: processQueryTargets: weather-data.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip4 10.0.1.11 port 51354 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: processQueryTargets: stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: resolving time.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: sending query: weather-data.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: sending to target: <.> 2620:fe::9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: sending query: time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 0RDd mod0 rep weather-data.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 1RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: sending query: stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: sending to target: <.> 2620:fe::9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 10.0.1.11 stocks-data-service.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: mesh_run: end 2 recursion states (2 with reply, 0 detached), 2 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 1RDd mod0 rep stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 0RDd mod0 rep time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: udp request from ip4 10.0.1.11 port 56723 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 10.0.1.11 gsp-ssl.ls.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: udp request from ip4 10.0.1.11 port 55464 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 0RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 1RDd mod0 rep time.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: resolving stocks-data-service.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 10.0.1.11 weather-data.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip4 10.0.1.11 port 62208 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: processQueryTargets: weather-data.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: sending query: stocks-data-service.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: sending query: gsp-ssl.ls.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: mesh_run: end 3 recursion states (3 with reply, 0 detached), 3 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 0RDd mod0 rep weather-data.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: sending query: stocks-data-service.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 1RDd mod0 rep stocks-data-service.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 2RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: mesh_run: end 3 recursion states (3 with reply, 0 detached), 3 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 1RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 2RDd mod0 rep stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 1RDd mod0 rep stocks-data-service.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 10.0.1.11 gsp-ssl.ls.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: mesh_run: end 3 recursion states (3 with reply, 0 detached), 4 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: resolving weather-data.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 10.0.1.11 gsp-ssl.ls.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: udp request from ip4 10.0.1.11 port 59396 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 1RDd mod0 rep time.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: udp request from ip4 10.0.1.11 port 60241 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: resolving gsp-ssl.ls.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 2RDd mod0 rep weather-data.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 10.0.1.29 eu-mobile.events.data.microsoft.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 10.0.1.29 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: sending query: weather-data.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 10.0.1.29 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: sending query: gsp-ssl.ls.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: sending to target: <.> 9.9.9.9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 0RDd mod0 rep weather-data.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: sending query: gsp-ssl.ls.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 10.0.1.59 Router-8.redacted.me.redacted.me. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: sending to target: <.> 9.9.9.9#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 2RDd mod0 rep stocks-data-service.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip4 10.0.1.59 port 54024 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 1RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: mesh_run: end 4 recursion states (4 with reply, 0 detached), 4 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 2RDd mod0 rep gsp-ssl.ls.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 0RDd mod0 rep time.apple.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 3RDd mod0 rep stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 10.0.1.11 dns.quad9.net. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: processQueryTargets: Router-8.redacted.me.redacted.me. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 10.0.1.11 dns.quad9.net. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: process_request: new external request event Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 10.0.1.11 dns.quad9.net. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: udp request from ip4 10.0.1.11 port 65054 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: udp request from ip4 10.0.1.11 port 49573 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: mesh_run: start Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: sending query: Router-8.redacted.me.redacted.me. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: sending query: dns.quad9.net. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: mesh_run: end 4 recursion states (4 with reply, 0 detached), 5 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: sending to target: <.> 2620:fe::fe#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 1RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: mesh_run: end 5 recursion states (5 with reply, 0 detached), 5 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 2RDd mod0 rep time.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 3RDd mod0 rep weather-data.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 1RDd mod0 rep weather-data.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 3RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: sending query: dns.quad9.net. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone redacted.me. transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: mesh_run: end 5 recursion states (5 with reply, 0 detached), 5 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 0RDd mod0 rep dns.quad9.net. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] info: 10.0.1.35 _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: mesh_run: end 5 recursion states (5 with reply, 0 detached), 5 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 2RDd mod0 rep lb._dns-sd._udp.redacted.me. PTR IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: using localzone . transparent Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: udp request from ip4 10.0.1.35 port 61824 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: udp request from ip4 172.16.1.46 port 40992 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: 4RDd mod0 rep stocks-data-service.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 2RDd mod0 rep dns.quad9.net. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] info: 4RDd mod0 rep _dns.resolver.arpa. SVCB IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find: num reuse streams 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find: num reuse streams 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: request has dependency depth of 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: forwarding request Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_insert 9.9.9.9#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point start listening 36 (-1 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_insert 9.9.9.9#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point start listening 34 (-1 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: startlistening 34 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: tcp bound to src ip6 2a02:red:act:ed:92ec:77ff:fe1b:70aa port 0 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: processQueryTargets: svcs.myharmony.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: startlistening 35 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_insert 2620:fe::fe#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: attempt to get extra 3 targets Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: startlistening 38 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point start listening 37 (-1 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query: found reuse 2620:fe::fe#853 fd 35 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: servselect ip4 9.9.9.9 port 853 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rtt=376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: rtt=376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query: found reuse 9.9.9.9#853 fd 34 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: servselect ip6 2620:fe::fe port 853 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: selrtt 376 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: sending query: svcs.myharmony.com. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query: reuse, store Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: dnssec status: not expected Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 1RDd mod0 rep Router-8.redacted.me.redacted.me. A IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_insert 2620:fe::9#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find: num reuse streams 2 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 3RDd mod0 rep time.apple.com. AAAA IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: comm point start listening 39 (-1 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: startlistening 39 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] info: 4RDd mod0 rep weather-data.apple.com. HTTPS IN Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find: num reuse streams 2 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_insert 149.112.112.112#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_insert 2620:fe::9#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: startlistening 40 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: tcp bound to src ip4 re.da.ct.ed port 0 (len 16) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: reuse_tcp_find: num reuse streams 2 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: reuse_tcp_find: num reuse streams 3 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: pending_tcp_query: found reuse 2620:fe::9#853 fd 39 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_insert 149.112.112.112#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: startlistening 42 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: pending_tcp_query: reuse, store Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: pending_tcp_query: found reuse 149.112.112.112#853 fd 38 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: tcp bound to src ip6 ::10.10.10.1 port 0 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_insert 2620:fe::fe#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point start listening 43 (-1 msec) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: startlistening 43 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find: num reuse streams 2 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: new fd, connect Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: tcp bound to src ip6 2a02:red:act:ed:92ec:77ff:fe1b:70aa port 0 (len 28) Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_insert 2620:fe::9#853 fd -1 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: startlistening 44 mode rw Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find: num reuse streams 3 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: found reuse 149.112.112.112#853 fd 42 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: reuse, store Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: remote control connection authenticated Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: control cmd: stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: remote control operation completed Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: comm point listen_for_rw 35 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm_point_close of 33: event_del Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 37 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: close fd 33 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: comm point listen_for_rw 39 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 34 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point listen_for_rw 36 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 40 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point listen_for_rw 38 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 42 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 44 0 Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chdir to /var/unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chroot to /var/unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: drop user privileges, run as unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: duplicate acl address ignored. Jun 27 17:14:34 Router-8 unbound[71284]: [71284:0] info: implicit transparent local-zone . TYPE0 IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: ignoring duplicate RR: localhost. AAAA ::1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: ignoring duplicate RR: localhost. A 127.0.0.1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: module config: "iterator" Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] notice: init module 0: iterator Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 0 is 3 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 1 is 2 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 2 is 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 3 is 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 4 is 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: donotq: 127.0.0.0/8 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: donotq: ::1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: total of 59448 outgoing ports available Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: start threads Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: libevent 2.1.12-stable uses kqueue method. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: Forward zone server list: Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: no config, using builtin root hints. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: start of service (unbound 1.17.1). Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: new control connection from ip4 127.0.0.1 port 13578 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm point stop listening 33 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm point start listening 33 (120000 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: Forward zone server list: Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: no config, using builtin root hints. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: Forward zone server list: Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: Forward zone server list: Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 54960 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: no config, using builtin root hints. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: resolving api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: request has dependency depth of 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: no config, using builtin root hints. Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: processQueryTargets: api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 56633 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 61927 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: resolving api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: request has dependency depth of 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 53468 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: processQueryTargets: api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: resolving api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: request has dependency depth of 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: processQueryTargets: api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: resolving ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: request has dependency depth of 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: sending query: api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: sending query: api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: sending query: api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: sending to target: <.> 2620:fe::fe#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: processQueryTargets: ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 0RDd mod0 rep api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 0RDd mod0 rep api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 0RDd mod0 rep api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 63362 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: sending query: ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: resolving ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iter_handle processing q with state QUERY TARGETS STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: resolving ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 54960 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: processQueryTargets: ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: sending query: ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: resolving api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: sending query: ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: processQueryTargets: api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: sending to target: <.> 9.9.9.9#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: mesh_run: end 2 recursion states (2 with reply, 0 detached), 2 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: mesh_run: end 2 recursion states (2 with reply, 0 detached), 2 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 0RDd mod0 rep ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 56633 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 1RDd mod0 rep ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 1RDd mod0 rep api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: request has dependency depth of 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 api.apple-cloudkit.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: processQueryTargets: api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 55793 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: mesh_run: start Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: resolving ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: sending query: api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: processQueryTargets: ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: resolving ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: processQueryTargets: ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 0RDd mod0 rep api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 1RDd mod0 rep api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: 0RDd mod0 rep api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: udp request from ip6 2a02:reda:cted:1:a5ee:8b62:2978:475 port 63362 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: sending query: ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: sending to target: <.> 2620:fe::fe#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: iter_handle processing q with state INIT REQUEST STATE Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: resolving ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: 2a02:reda:cted:1:a5ee:8b62:2978:475 eu-mobile.events.data.microsoft.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: processQueryTargets: ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: sending query: ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: mesh_run: end 3 recursion states (3 with reply, 0 detached), 3 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 0RDd mod0 rep ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 1RDd mod0 rep api.apple-cloudkit.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: [dns.quad9.net] ip4 149.112.112.112 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] info: 2RDd mod0 rep ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: mesh_run: end 3 recursion states (3 with reply, 0 detached), 4 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: using localzone . transparent Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: cache memory msg=66072 rrset=66072 infra=7808 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: attempt to get extra 3 targets Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: udp request from ip4 172.16.1.46 port 58298 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 1RDd mod0 rep ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: rpz: iterator module callback: have_rpz=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: servselect ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: selrtt 376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: process_request: new external request event Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: resolving svcs.myharmony.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] info: 2RDd mod0 rep ocsp.edge.digicert.com. HTTPS IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: sending query: ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: forwarding request Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: processQueryTargets: svcs.myharmony.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: cache memory msg=66072 rrset=66072 infra=8057 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: dnssec status: not expected Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: DelegationPoint<.>: 0 names (0 missing), 4 addrs (0 result, 4 avail) parentNS Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip6 2620:fe::9 port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: [dns.quad9.net] ip4 9.9.9.9 port 853 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: servselect ip6 2620:fe::fe port 853 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: rtt=376 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: sending to target: <.> 149.112.112.112#853 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: mesh_run: iterator module exit state is module_wait_reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: 0RDd mod0 rep svcs.myharmony.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: 2RDd mod0 rep ocsp.edge.digicert.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: reuse_tcp_find: num reuse streams 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 0RDd mod0 rep ocsp.edge.digicert.com. A IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] info: 1RDd mod0 rep api.apple-cloudkit.com. AAAA IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: reuse_tcp_insert 2620:fe::fe#853 fd -1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: tcp bound to src ip6 ::10.10.10.1 port 0 (len 28) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: reuse_tcp_insert 2620:fe::9#853 fd -1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm point start listening 35 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: pending_tcp_query: new fd, connect Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: cache memory msg=66072 rrset=66072 infra=8555 val=0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find: num reuse streams 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: reuse_tcp_insert 149.112.112.112#853 fd -1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm point start listening 37 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query: new fd, connect Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: startlistening 34 mode rw Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: comm point start listening 36 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: startlistening 36 mode rw Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: reuse_tcp_find check inexact match Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: pending_tcp_query: reuse, store Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: startlistening 38 mode rw Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: tcp bound to src ip4 127.0.0.1 port 0 (len 16) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: serviced send timer Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: comm point start listening 39 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find check inexact match Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: pending_tcp_query: new fd, connect Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query: found reuse 149.112.112.112#853 fd 38 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: reuse_tcp_find Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: reuse_tcp_find check inexact match Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query: reuse, store Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: pending_tcp_query: found reuse 9.9.9.9#853 fd 39 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find: num reuse streams 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: pending_tcp_query: reuse, store Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_find check inexact match Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: pending_tcp_query: new fd, connect Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: comm point start listening 40 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: the query is using TLS encryption, for dns.quad9.net Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: reuse_tcp_insert 2620:fe::9#853 fd -1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: outnet_tcp_take_query_setup: setup packet to write len 128 timeout 3000 msec Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: comm point start listening 41 (-1 msec) Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: comm point listen_for_rw 34 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: comm point listen_for_rw 36 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: comm point listen_for_rw 38 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: comm point listen_for_rw 39 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: remote control connection authenticated Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: comm point listen_for_rw 40 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] info: control cmd: stats_noreset Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: write stats cmd Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: wait for stats reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: got control cmd stats_noreset Jun 27 17:14:40 Router-8 unbound[71284]: [71284:1] debug: write stats replymsg Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: comm point listen_for_rw 41 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: write stats cmd Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: wait for stats reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: got control cmd stats_noreset Jun 27 17:14:40 Router-8 unbound[71284]: [71284:2] debug: write stats replymsg Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: write stats cmd Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: wait for stats reply Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: got control cmd stats_noreset Jun 27 17:14:40 Router-8 unbound[71284]: [71284:3] debug: write stats replymsg Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: remote control operation completed Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm_point_close of 33: event_del Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: close fd 33 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: comm point listen_for_rw 37 0 [23.05-RELEASE][admin@Router-8.redacted.me]/root:
Click: unbound-control stats_noreset: (redacted) [23.05-RELEASE][admin@Router-8.redacted.me]/root: unbound-control -c /var/unbound/unbound.conf stats_noreset thread0.num.queries=4939 thread0.num.queries_ip_ratelimited=0 thread0.num.cachehits=4355 thread0.num.cachemiss=584 thread0.num.prefetch=1243 thread0.num.expired=1052 thread0.num.recursivereplies=584 thread0.num.dnscrypt.crypted=0 thread0.num.dnscrypt.cert=0 thread0.num.dnscrypt.cleartext=0 thread0.num.dnscrypt.malformed=0 thread0.requestlist.avg=0.735085 thread0.requestlist.max=22 thread0.requestlist.overwritten=0 thread0.requestlist.exceeded=0 thread0.requestlist.current.all=0 thread0.requestlist.current.user=0 thread0.recursion.time.avg=0.115453 thread0.recursion.time.median=0.0525554 thread0.tcpusage=0 thread1.num.queries=6576 thread1.num.queries_ip_ratelimited=0 thread1.num.cachehits=5710 thread1.num.cachemiss=866 thread1.num.prefetch=1833 thread1.num.expired=1608 thread1.num.recursivereplies=866 thread1.num.dnscrypt.crypted=0 thread1.num.dnscrypt.cert=0 thread1.num.dnscrypt.cleartext=0 thread1.num.dnscrypt.malformed=0 thread1.requestlist.avg=0.443127 thread1.requestlist.max=18 thread1.requestlist.overwritten=0 thread1.requestlist.exceeded=0 thread1.requestlist.current.all=0 thread1.requestlist.current.user=0 thread1.recursion.time.avg=0.132903 thread1.recursion.time.median=0.0495591 thread1.tcpusage=0 thread2.num.queries=23633 thread2.num.queries_ip_ratelimited=0 thread2.num.cachehits=21870 thread2.num.cachemiss=1763 thread2.num.prefetch=3185 thread2.num.expired=2731 thread2.num.recursivereplies=1763 thread2.num.dnscrypt.crypted=0 thread2.num.dnscrypt.cert=0 thread2.num.dnscrypt.cleartext=0 thread2.num.dnscrypt.malformed=0 thread2.requestlist.avg=0.514551 thread2.requestlist.max=22 thread2.requestlist.overwritten=0 thread2.requestlist.exceeded=0 thread2.requestlist.current.all=0 thread2.requestlist.current.user=0 thread2.recursion.time.avg=0.106303 thread2.recursion.time.median=0.0394584 thread2.tcpusage=0 thread3.num.queries=15430 thread3.num.queries_ip_ratelimited=0 thread3.num.cachehits=14018 thread3.num.cachemiss=1412 thread3.num.prefetch=2764 thread3.num.expired=2388 thread3.num.recursivereplies=1412 thread3.num.dnscrypt.crypted=0 thread3.num.dnscrypt.cert=0 thread3.num.dnscrypt.cleartext=0 thread3.num.dnscrypt.malformed=0 thread3.requestlist.avg=0.511734 thread3.requestlist.max=27 thread3.requestlist.overwritten=0 thread3.requestlist.exceeded=0 thread3.requestlist.current.all=0 thread3.requestlist.current.user=0 thread3.recursion.time.avg=0.109135 thread3.recursion.time.median=0.0415061 thread3.tcpusage=0 total.num.queries=50578 total.num.queries_ip_ratelimited=0 total.num.cachehits=45953 total.num.cachemiss=4625 total.num.prefetch=9025 total.num.expired=7779 total.num.recursivereplies=4625 total.num.dnscrypt.crypted=0 total.num.dnscrypt.cert=0 total.num.dnscrypt.cleartext=0 total.num.dnscrypt.malformed=0 total.requestlist.avg=0.529084 total.requestlist.max=27 total.requestlist.overwritten=0 total.requestlist.exceeded=0 total.requestlist.current.all=0 total.requestlist.current.user=0 total.recursion.time.avg=0.113304 total.recursion.time.median=0.0457698 total.tcpusage=0 time.now=1687938371.478558 time.up=49451.752524 time.elapsed=49451.752524 mem.cache.rrset=911002 mem.cache.message=1314474 mem.mod.iterator=16572 mem.mod.validator=0 mem.mod.respip=0 mem.cache.dnscrypt_shared_secret=0 mem.cache.dnscrypt_nonce=0 mem.mod.dynlibmod=0 mem.streamwait=0 mem.http.query_buffer=0 mem.http.response_buffer=0 histogram.000000.000000.to.000000.000001=137 histogram.000000.000001.to.000000.000002=0 histogram.000000.000002.to.000000.000004=0 histogram.000000.000004.to.000000.000008=0 histogram.000000.000008.to.000000.000016=0 histogram.000000.000016.to.000000.000032=0 histogram.000000.000032.to.000000.000064=0 histogram.000000.000064.to.000000.000128=0 histogram.000000.000128.to.000000.000256=0 histogram.000000.000256.to.000000.000512=0 histogram.000000.000512.to.000000.001024=0 histogram.000000.001024.to.000000.002048=0 histogram.000000.002048.to.000000.004096=0 histogram.000000.004096.to.000000.008192=0 histogram.000000.008192.to.000000.016384=979 histogram.000000.016384.to.000000.032768=674 histogram.000000.032768.to.000000.065536=1530 histogram.000000.065536.to.000000.131072=685 histogram.000000.131072.to.000000.262144=367 histogram.000000.262144.to.000000.524288=134 histogram.000000.524288.to.000001.000000=42 histogram.000001.000000.to.000002.000000=10 histogram.000002.000000.to.000004.000000=62 histogram.000004.000000.to.000008.000000=5 histogram.000008.000000.to.000016.000000=0 histogram.000016.000000.to.000032.000000=0 histogram.000032.000000.to.000064.000000=0 histogram.000064.000000.to.000128.000000=0 histogram.000128.000000.to.000256.000000=0 histogram.000256.000000.to.000512.000000=0 histogram.000512.000000.to.001024.000000=0 histogram.001024.000000.to.002048.000000=0 histogram.002048.000000.to.004096.000000=0 histogram.004096.000000.to.008192.000000=0 histogram.008192.000000.to.016384.000000=0 histogram.016384.000000.to.032768.000000=0 histogram.032768.000000.to.065536.000000=0 histogram.065536.000000.to.131072.000000=0 histogram.131072.000000.to.262144.000000=0 histogram.262144.000000.to.524288.000000=0 num.query.type.TYPE0=26 num.query.type.A=16156 num.query.type.CNAME=125 num.query.type.SOA=27 num.query.type.PTR=3365 num.query.type.TXT=31 num.query.type.AAAA=15843 num.query.type.SRV=283 num.query.type.SVCB=1299 num.query.type.HTTPS=13423 num.query.class.CLASS0=26 num.query.class.IN=50552 num.query.opcode.QUERY=50578 num.query.tcp=13 num.query.tcpout=10641 num.query.udpout=0 num.query.tls=0 num.query.tls.resume=0 num.query.ipv6=39352 num.query.https=0 num.query.flags.QR=0 num.query.flags.AA=0 num.query.flags.TC=0 num.query.flags.RD=50578 num.query.flags.RA=0 num.query.flags.Z=0 num.query.flags.AD=0 num.query.flags.CD=0 num.query.edns.present=0 num.query.edns.DO=0 num.answer.rcode.NOERROR=49214 num.answer.rcode.FORMERR=0 num.answer.rcode.SERVFAIL=0 num.answer.rcode.NXDOMAIN=1338 num.answer.rcode.NOTIMPL=0 num.answer.rcode.REFUSED=26 num.answer.rcode.nodata=12975 num.query.ratelimited=0 num.answer.secure=0 num.answer.bogus=0 num.rrset.bogus=0 num.query.aggressive.NOERROR=0 num.query.aggressive.NXDOMAIN=0 unwanted.queries=0 unwanted.replies=0 msg.cache.count=4928 rrset.cache.count=3146 infra.cache.count=4 key.cache.count=0 dnscrypt_shared_secret.cache.count=0 dnscrypt_nonce.cache.count=0 num.query.dnscrypt.shared_secret.cachemiss=0 num.query.dnscrypt.replay=0 num.query.authzone.up=0 num.query.authzone.down=0 [23.05-RELEASE][admin@Router-8.redacted.me]/root:

The DNS Resolver Infrastructure Cache Speed summaries can look quite wild:

20230628-pfSense-DNS Resolver-IPv4 and IPv6 Servers-21
20230629-pfSense-DNS Resolver-IPv4 and IPv6 Servers-24

I hope these help you shed some light as to why the query response time can become so protracted when using both IPv4 and IPv6 forwarders.

☕️

wcawijngaards commented 1 year ago

In the logs there is one oddity, it seems this happens:

Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 44 0
Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chdir to /var/unbound

That looks like unbound 71149 ceases to exist, and then about two minutes and 14 seconds later it starts again. That, if intentional is harmless, but there would normally be logs about the shutdown sequence.

From the infra cache stats, it looks like there are a lot of timeouts happening. Also for an IPv4 address, I spot. And the other timeouts for IPv6 addresses. These timeouts cause unbound to pause and wait, and I think, but I already mentioned earlier, are the cause of the wait times. Something must be wrong with the connection. I would think that fixing the upstream connectivity would likely be the issue.

Somehow this does not happen if only IPv4 is used? The presence of IPv6 traffic causes packet drops?

From the logs, there is no mention of dropped connections in there. Also because they are fairly short, I guess they did not capture them. I guess it would not look like anything in particular, if this is some sort of loss of network connectivity. Normally, networks connectivity does not have this kind of packet drops, like 0 drops, would be expected. Also to these forwarders, would not expect packet drops.

Perhaps prefer-ip4 can help, if ip6 network connectivity just does not work right, eg. has packet drops. Or fix the IPv6 connection. But then there is also some packet drops for IPv4. The TLS connections lag a bunch, and this is the TLS stack that does that. If the forwarders are configured to use UDP, unbound chooses a timeout, and that would likely be fairly short, 93 msec, for the IPv4 addresses, and this retry is quick and easy. It may be easier to help around this packet lossy network connection, as a packet drop for IPv4 then is only a couple hundred msec of delay, once in a while.

Unbound can configure retries, the default is 5 retries to a server, outbound-msg-retry: 5. Also the wait times for UDP responses can be configured, infra-cache-min-rtt: 50 and infra-cache-max-rtt: 120000. But the defaults are fine, and unbound should retry for the IPv4 failures. I would then disable the IPv6 forwarder addresses because of the packet loss on IPv6. And then use UDP to more easily recover from the packet loss on IPv4. Not sure if this is helpful, perhaps diagnosing the actual network connection fixes the more underlying issue. It is possible to make queries from the commandline to the upstream IP addresses, but to see the packet loss that would need a lot of repeats or so.

RobbieTT commented 1 year ago

In the logs there is one oddity, it seems this happens:

Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 44 0
Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chdir to /var/unbound

That looks like unbound 71149 ceases to exist, and then about two minutes and 14 seconds later it starts again. That, if intentional is harmless, but there would normally be logs about the shutdown sequence.

Click: Oddity expanded (redacted): ``` Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: found reuse 149.112.112.112#853 fd 42 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: serviced send timer Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: reuse_tcp_find check inexact match Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: pending_tcp_query: reuse, store Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: remote control connection authenticated Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: control cmd: stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: write stats cmd Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: wait for stats reply Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: got control cmd stats_noreset Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: write stats replymsg Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: remote control operation completed Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: comm point listen_for_rw 35 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm_point_close of 33: event_del Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 37 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: close fd 33 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:2] debug: comm point listen_for_rw 39 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 34 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point listen_for_rw 36 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:1] debug: comm point listen_for_rw 40 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] debug: comm point listen_for_rw 38 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 42 0 Jun 27 17:12:18 Router-8 unbound[71149]: [71149:3] debug: comm point listen_for_rw 44 0 Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chdir to /var/unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: chroot to /var/unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: drop user privileges, run as unbound Jun 27 17:14:32 Router-8 unbound[71284]: [71284:0] debug: duplicate acl address ignored. Jun 27 17:14:34 Router-8 unbound[71284]: [71284:0] info: implicit transparent local-zone . TYPE0 IN Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: ignoring duplicate RR: localhost. AAAA ::1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: ignoring duplicate RR: localhost. A 127.0.0.1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: module config: "iterator" Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] notice: init module 0: iterator Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 0 is 3 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 1 is 2 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 2 is 1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 3 is 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: target fetch policy for level 4 is 0 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: donotq: 127.0.0.0/8 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: donotq: ::1 Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: total of 59448 outgoing ports available Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: start threads Jun 27 17:14:40 Router-8 unbound[71284]: [71284:0] debug: libevent 2.1.12-stable uses kqueue method. ```

I presume it was caused by this line:

Jun 27 17:12:18 Router-8 unbound[71149]: [71149:0] info: control cmd: stats_noreset

From the infra cache stats, it looks like there are a lot of timeouts happening. Also for an IPv4 address, I spot. And the other timeouts for IPv6 addresses. These timeouts cause unbound to pause and wait, and I think, but I already mentioned earlier, are the cause of the wait times. Something must be wrong with the connection. I would think that fixing the upstream connectivity would likely be the issue.

The upstream connection to the forwarders is perfect with hardly a ripple on PingPlotter and steady at 7.2ms. It is a 1 Gbit fibre service via a 2.5 GbE ONT. Clearly I am blind to what happens behind Quad9's door but I tried the same tests with the Cloudflare equivalents and there was no change in the symptoms or performance.

Somehow this does not happen if only IPv4 is used? The presence of IPv6 traffic causes packet drops? From the logs, there is no mention of dropped connections in there. Also because they are fairly short, I guess they did not capture them. I guess it would not look like anything in particular, if this is some sort of loss of network connectivity. Normally, networks connectivity does not have this kind of packet drops, like 0 drops, would be expected. Also to these forwarders, would not expect packet drops.

The issue appears when you add IPv6 addresses to the forwarder list. When I added Cloudflare IPv6 addresses to the 4 current forwarders the problem increased further - more IPv6 addresses = more issues. I'm not seeing anything that suggests dropped packets on the WAN side and the PCAPs support this; only that the timings get longer and are cumulative, tripping a timer somewhere.

Perhaps prefer-ip4 can help, if ip6 network connectivity just does not work right, eg. has packet drops. Or fix the IPv6 connection. But then there is also some packet drops for IPv4. The TLS connections lag a bunch, and this is the TLS stack that does that. If the forwarders are configured to use UDP, unbound chooses a timeout, and that would likely be fairly short, 93 msec, for the IPv4 addresses, and this retry is quick and easy. It may be easier to help around this packet lossy network connection, as a packet drop for IPv4 then is only a couple hundred msec of delay, once in a while.

If it comes to it I will have to remove the IPv6 addresses but this is not ideal. I'd rather stick with DoT, so the TLS / TCP handshakes are just one of those things. If UDP is the answer it kind of of defeats the reason I moved away from Dnsmasq as my caching dns service.

Unbound can configure retries, the default is 5 retries to a server...

Where should I look for these retries (if present) as all I see in the pcaps is the sequential use of IPv6 after the IPv4 and the total time of these queries driving up the answer time?

Whilst you should read the next observation with care, as I am far from sure of what I am seeing myself, but some of the expanded / delinquent timings seem to be associated with additional probing post the main request (prefetch activity?) - with the client only receiving its actual answer once all the other queries are complete. Again, I am not sure of what is going on under the hood but there is a lot more activity going on when the query times go sideways. Timings get summed and multiplied whilst the pcaps show nothing but protracted but otherwise normal activity.

I included a unbound-control stats_noreset snapshot in the previous post and to my eyes it looks normal - would you expect to see failures in this data if packets were being dropped or malformed somewhere?

Apologies with the clipped data provided previously, I was limited by the character limit. I do have larger logs so feel free to point me at things to look at or grep from.

Thanks again for looking at this.

☕️

wcawijngaards commented 1 year ago

So, if the upstream is working fine, the issue must be close to the server. If not actually the server itself. This happens when IPv6 is used, and more IPv6 causes more issues. The issues are packet drops, for IPv6, but also a packet drop for IPv4 is visible in the infra stats. This then causes slowdown.

The first ipv4 and then ipv6 behaviour is caused by unbound selecting the best servers, and that is the ipv4 servers because they do not packet drop. Then unbound retries and attempts the IPv6 servers after that. That means the IPv4 failed somehow. it could also be random selection, and that should be even weighted, because that is what the unbound server selection code does.

The statistics output did not look problematic to me, there is the long resolution times when timeouts must be happening.

If the problem is close to the server, something must be wrong. If unbound is just creating a socket, then the system, network card, cable, network router or more network equipment up to the working WAN link is then likely the cause, and drops packets once IPv6 gets enabled. The failure where the process ceases to exist is not explained by the stats_noreset command, that should not end the server process. The process seems to have been killed, and then it is restarted two minutes later. If that is caused by a failure in hardware, like the mainboard, or overheating, and then the router restarts, that could explain it, and may also explain packet drop behaviour. Or the problem could be in software, if the machine is out of memory, unbound should log out of memory, but the linux OOM killer, can kill the process if the machine is out of memory without further logs from Unbound. And the machine could run out of memory because the extra ipv6 sockets use buffer memory. Perhaps it drops packets because of lack of buffer space, causing the connection failures?

Unbound does not actually perform probing, there is a root key sentinel lookup in recent versions, but that is only once. And other queries only happen in line with client queries. Sometimes unbound sends another lookup because of a failure, or CNAME chasing.

RobbieTT commented 1 year ago

Unbound is running on a Netgate 6100 Max (v23.05.1 on FreeBSD 14.0-Current). It has ix and igc interfaces, with the WAN on an igc (2.5 GbE) interface but running at 1 GbE. The LANs are SFP+ DACs and the 6100 comes with its standard 8GB RAM & Atom C3558 (with QAT active). The only non-standard hardware is the SSD, which is a pure Optane drive (64GB). It has physical resources to spare but I appreciate that may not always mean available, if there is a config issue:

2023-07-03 at 14 51 31

For more granular details, top does not seem to show anything of note (at least to my eyes). NB that my WAN is via PPPoE so it places most of the actual traffic via a single core due to the BSD vs PPPoE issue:

Click: top -HaSPOddity (redacted): ``` last pid: 36001; load averages: 0.27, 0.28, 0.27 up 3+16:57:12 14:31:36 333 threads: 5 running, 289 sleeping, 39 waiting CPU 0: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle CPU 1: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle CPU 2: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle CPU 3: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle Mem: 136M Active, 451M Inact, 1272M Wired, 120K Buf, 5926M Free ARC: 747M Total, 236M MFU, 486M MRU, 794K Anon, 3430K Header, 20M Other 672M Compressed, 1305M Uncompressed, 1.94:1 Ratio Swap: 1024M Total, 1024M Free PID USERNAME PRI NICE SIZE RES STATE C TIME WCPU COMMAND 11 root 187 ki31 0B 64K CPU0 0 87.6H 99.87% [idle{idle: cpu0}] 11 root 187 ki31 0B 64K CPU1 1 84.1H 98.59% [idle{idle: cpu1}] 11 root 187 ki31 0B 64K CPU3 3 83.9H 97.12% [idle{idle: cpu3}] 11 root 187 ki31 0B 64K RUN 2 84.2H 92.10% [idle{idle: cpu2}] 89797 root 21 0 14M 4584K CPU2 2 0:01 7.49% top -HaSP 42120 root 20 0 21M 10M select 1 0:00 0.93% sshd: admin@pts/0 (sshd) 0 root -60 - 0B 1696K - 3 1:28 0.48% [kernel{if_io_tqg_3}] 0 root -60 - 0B 1696K - 2 2:07 0.37% [kernel{if_io_tqg_2}] 0 root -64 - 0B 1696K - 0 6:28 0.18% [kernel{dummynet}] 0 root -60 - 0B 1696K - 0 10:04 0.14% [kernel{if_io_tqg_0}] 12 root -60 - 0B 560K WAIT 1 4:11 0.12% [intr{swi1: netisr 3}] 12 root -60 - 0B 560K WAIT 3 4:16 0.12% [intr{swi1: netisr 1}] 47798 root 20 0 13M 2908K sbwait 0 0:06 0.06% /usr/local/bin/dpinger -S -r 0 -i WAN_DHCP6 -B fe80::reda:cted:fe1 2454 unbound 20 0 327M 273M kqread 3 16:56 0.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound} 34027 avahi 20 0 14M 4308K select 1 12:05 0.00% avahi-daemon: running [Router-8.local] (avahi-daemon) 2454 unbound 20 0 327M 273M kqread 1 8:17 0.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound} 2454 unbound 20 0 327M 273M kqread 0 7:45 0.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound} 2454 unbound 20 0 327M 273M kqread 1 5:38 0.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound} 12 root -60 - 0B 560K WAIT 3 4:44 0.00% [intr{swi1: netisr 2}] 0 root -60 - 0B 1696K - 2 3:34 0.00% [kernel{if_config_tqg_0}] 90738 root 60 0 72M 43M nanslp 0 2:01 0.00% /usr/local/bin/php -f /usr/local/pkg/pfblockerng/pfblockerng.inc q 0 root -12 - 0B 1696K - 2 1:54 0.00% [kernel{z_wr_iss_0}] 0 root -12 - 0B 1696K - 1 1:54 0.00% [kernel{z_wr_iss_1}] 0 root -12 - 0B 1696K - 3 1:53 0.00% [kernel{z_wr_iss_2}] 0 root -60 - 0B 1696K - 1 1:38 0.00% [kernel{if_io_tqg_1}] 89160 root 20 0 21M 9488K kqread 0 1:35 0.00% /usr/local/sbin/lighttpd_pfb -f /var/unbound/pfb_dnsbl_lighty.conf 89577 root 20 0 75M 43M piperd 2 1:30 0.00% /usr/local/bin/php -f /usr/local/pkg/pfblockerng/pfblockerng.inc i 6 root -8 - 0B 928K tx->tx 3 1:20 0.00% [zfskern{txg_thread_enter}] 66956 root 68 20 13M 2776K wait 1 1:11 0.00% /bin/sh /var/db/rrd/updaterrd.sh 7 root -16 - 0B 16K pftm 2 0:59 0.00% [pf purge] 12 root -60 - 0B 560K WAIT 1 0:57 0.00% [intr{swi1: netisr 0}] 0 root -16 - 0B 1696K - 2 0:43 0.00% [kernel{z_wr_int_0}] 0 root -16 - 0B 1696K - 0 0:43 0.00% [kernel{z_wr_int_1}] 0 root -16 - 0B 1696K - 3 0:43 0.00% [kernel{z_wr_int_2}] 47462 root 20 0 149M 83M accept 3 0:43 0.00% php-fpm: pool nginx (php-fpm){php-fpm} 86856 root 68 0 153M 86M accept 0 0:41 0.00% php-fpm: pool nginx (php-fpm){php-fpm} 969 root 68 0 153M 87M accept 0 0:38 0.00% php-fpm: pool nginx (php-fpm){php-fpm} 47169 root 20 0 13M 2844K nanslp 3 0:36 0.00% /usr/local/bin/dpinger -S -r 0 -i WAN_PPPOE -B 93.red.act.ed -p /va 2 root -60 - 0B 64K WAIT 0 0:35 0.00% [clock{clock (0)}] 968 root 68 0 145M 82M accept 3 0:33 0.00% php-fpm: pool nginx (php-fpm) 8 root -16 - 0B 16K - 2 0:33 0.00% [rand_harvestq] 0 root -16 - 0B 1696K swapin 2 0:33 0.00% [kernel{swapper}] 84274 root 20 0 15M 5636K nanslp 0 0:32 0.00% /usr/local/sbin/vnstatd -d -p /var/run/vnstat/vnstat.pid --config 18629 root 20 0 24M 9108K select 1 0:31 0.00% /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/run 6 root -8 - 0B 928K dbuf_e 2 0:26 0.00% [zfskern{dbuf_evict_thread}] 47798 root 20 0 13M 2908K nanslp 3 0:24 0.00% /usr/local/bin/dpinger -S -r 0 -i WAN_DHCP6 -B fe80::reda:cted:fe1 94277 root 20 0 17M 6920K select 1 0:20 0.00% /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid 89753 root 20 0 12M 2476K kqread 3 0:16 0.00% /usr/bin/tail_pfb -n0 -F /var/log/filter.log` ```

I've not found any errors in my WAN traffic or with the simple cabling from the router to the ONT. For most of the testing I am not using the LAN side, to rule out the influence of switches, DACs, RJ45 etc. The LAN side errors recorded are non-zero (~460 total 'in' packets, so many orders of magnitude below 1%).

Looking a bit wider I did find 2 things of note. Running the icmpcheck.popcount.org 'Frag Test' it fully passed on IPv6 but did have issues with IPv4; somewhat the reverse of what I was expecting:

20230702-icmpcheck popcount org-ICMP Frag Test copy

The other thing of note was simultaneously comparing IPv4 and IPv6 to Quad9 using PingPlotter. This is being run on a headless Mac acting as a server on a 10 GbE link, so it does remove the purity of testing from the router alone. I have zero packet loss from the server-switch-switch-router-WAN-ISP link on either IPv4 or IPv6 but there is significant packet loss on IPv6 further upstream, just 1 hop away from Quad9's servers (the PingPlotter 'timeout' is set to the default 3000ms):

20230703-unbound-pingplot-quad9 IPv4 vs IPv6-redacted

Could this be the potential WAN-side issue you were looking for?

☕️

(If I can test in a better or more productive way just point me in the right direction.)

RobbieTT commented 1 year ago

Looking at the IPv6 address that the packets are being dropped at it corresponds to this place:

LONAP is a "not for profit" Layer 2 Internet Exchange Point (IXP) based in London. Our data-centres host a network of interconnected switches providing free-flowing peering to help minimise interconnection costs. We provide exclusive connectivity between members, who are effectively LONAP stakeholders. This ensures that LONAP members enjoy excellent value and maximum benefits:

https://www.lonap.net

☕️

wcawijngaards commented 1 year ago

It is nice that LONAP delivers not-for-profit IXP connectivity. The 25% packet loss indication looks like the WAN-side issue we were looking for. The 0.2 % for IPv4 is also important to note, because that means degraded performance. The cutout of the process is also worrying, in that the server process disappeared.

But likely the 25% packet loss for IPv6, apparently some of the time, is certainly something that grinds connectivity to a halt. I do not think that TCP or TLS is going to cope with that sort of number. And it seems to not be doing so, in this issue.

So, a solution is to not list the IPv6 addresses. Still have the 0.2% IPv4 trouble and process cutout issues. But then it avoids the 25% packet loss.

Another is to use UDP, instead of TLS. In that case, Unbound performs the retries and they are much faster and light weight, comparatively, so that would be able to work. But since the IPv6 host is the same host as the IPv4 address, it is simply another way to contact that upstream service, perhaps this is not as useful as just using IPv4.

Also, it is possible to remove the forward altogether, and have unbound run as full resolver, contacting authority servers. Because that is likely not going over that packet loss hop towards the particular upstream forwarder service, for most lookups, it would likely work. It is then not using TLS.

Unbound is configured to not use fragments, if possible, something that is advocated for DNS servers. So the fragment failure is not really an issue, at all.

RobbieTT commented 1 year ago

@wcawijngaards - Thanks again and I have raised a support ticket (#32073) with Quad9 and I will report back here with any details they provide.

☕️

RobbieTT commented 1 year ago

Quad9 are on the case as they can:

...replicate the packet loss to multiple destination IPv6 addresses on different networks, where the packet loss is occurring on the router of one of our upstream providers.

☕️

RobbieTT commented 1 year ago

Quad9 appears to have resolved the issue with both IPv6 changes and a significant capacity upgrade that went live yesterday evening:

Thanks for your patience. We've deployed considerably more capacity in London, and a lot of traffic shifted to our new "qlhr1" PoP. Can you tell us if your metrics have improved since yesterday evening (UTC)?

My unbound resolver stats now look very healthy:

2023-09-01 at 17 04 41

Thanks to all and I am marking this topic as closed.

☕️