Unbound Just Stops Working!

Expected Behaviour:

I am currently running two Pi-holes—one as the primary DNS and the other as secondary. The setup should work seamlessly with OPNsense managing the firewall and network traffic, allowing all DNS queries to flow through the Pi-holes without interruptions. When connecting to WireGuard, DNS queries should continue to be handled by Pi-hole as expected (NAT Rule, don't have Permit all origins enabled), and Unbound should remain operational without any crashes or failures, even when running speed tests or performing other network-heavy activities.

Actual Behaviour:

At random times, the setup stops working, and logs show SERVFAIL errors occurring with Unbound. Looking into OPNsense firewall logs, traffic is being allowed between the LAN and WAN as expected, but despite this, DNS resolution fails.

One consistent way to trigger the failure is by connecting to WireGuard on any device and running a speed test, which causes Unbound to stop working and DNS queries to fail across the network. Logs also show entries like OK (answered by 127.0.0.1#5335 BOGUS (refused upstream)), with some queries getting answered from cache, and some just slipping through the cracks somehow. The only way to restore functionality is by rebooting OPNsense, and also the piholes.

Steps Tried

  • Ran Unbound directly on OPNsense to see if it resolved the issue.
  • Verified that NTP times are correctly synced on both OPNsense and the Pi-holes.
  • Checked all firewall rules, which seem to be configured correctly.

Config Files

resolv.conf

# Generated by NetworkManager
search home.arpa
nameserver 192.168.1.2
nameserver 192.168.1.3

Unbound Config

server:
    # If no logfile is specified, syslog is used
    # logfile: "/var/log/unbound/unbound.log"
    logfile: /home/joseph/logs/unbound.log
    log-time-ascii: yes
    log-queries: yes
    log-replies: yes
    verbosity: 1

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

    prefer-ip6: no

    harden-glue: yes

    harden-dnssec-stripped: yes

    use-caps-for-id: no

    edns-buffer-size: 1232

    prefetch: yes

    num-threads: 1

    so-rcvbuf: 1m

    private-address: 192.168.0.0/16
    private-address: 169.254.0.0/16
    private-address: 172.16.0.0/12
    private-address: 10.0.0.0/8
    private-address: fd00::/8
    private-address: fe80::/10

Debug Token:

https://tricorder.pi-hole.net/B753aji4/

This indicates that Pi-hole's upstream at 127.0.0.1#533 (unbound, presumably?) has rejected the query without providing any further details, i.e. your issue is with your upstream, not with Pi-hole.

You'd have to look into unbound to analyse and address your issue.

Some Unbound log/journal pointers (ditch the logfile: directive):

Oh I was questioned why to ditch the logfile: directive when diagnosing.
There is no log-rotate in place/configured to maintain and archive the log file.
It will just keep on growing until the filesystem is full.
Also its impractical to diagnose if the filesize is too large.
Think about greping or browsing with less.

If no logfile: is specified, everything gets logged by the systemd-journald.service which can be queried with the journalctl command.
The journal size is maintained by this service.
And if you up verbosity to three minimal in the Unbound config file, you can see individual queries in the journal and how they are processed ... for diagnosing.

Thanks! I changed the verbosity to 3 and ran a live view of journalctl for Unbound. Then I did a speed test while connected to WireGuard from a client, and boom—my home connection dropped. I didn’t see any obvious issues in the logs, but let me attach them so you can take a look and see if anything stands out.

Pihole Query Log

2024-10-15 11:43:44	AAAA	client.wns.windows.com	Omars-Xbox	OK (sent to localhost#5335)	N/A	
2024-10-15 11:43:43	AAAA	fp-us-att.rcs.telephony.goog	192.168.1.133	OK (sent to localhost#5335)	N/A	
2024-10-15 11:43:43	A	deviceapi.messaging.arlo.com	Side-Porch-Camera	OK (sent to localhost#5335)	N/A

These are a few examples, it seems like "N/A" for reply is not good.

Unbound Log

Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: iterator operate: query clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: processQueryTargets: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: sending query: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: sending to target: <com.> 192.41.162.30#53
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=295404 rrset=555219 infra=140419 val=106199 subnet=74504
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: iterator operate: query clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: processQueryTargets: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: sending query: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: sending to target: <com.> 192.41.162.30#53
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=295404 rrset=555219 infra=140419 val=106199 subnet=74504
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: iterator operate: query clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: processQueryTargets: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: sending query: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: sending to target: <com.> 192.41.162.30#53
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=295404 rrset=555219 infra=140419 val=106199 subnet=74504
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: iterator operate: query clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: processQueryTargets: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] info: sending query: clients3.google.com. AAAA IN
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: sending to target: <com.> 192.41.162.30#53
Oct 15 11:43:11 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=295404 rrset=555219 infra=140419 val=106199 subnet=74504

More logs

Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: Failed to get a delegation, giving up
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_new
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: removing 2 labels
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: removing 1 labels
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: Failed to get a delegation, giving up
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_new
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: removing 2 labels
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: removing 1 labels
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_state_initial event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response REFUSED
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: Failed to get a delegation, giving up
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_state_initial event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_subquery event:module_event_pass
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_noreply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: sending to target: <net.> 192.31.80.30#53
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303837 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: validator[module 1] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: subnetcache[module 0] operate: extstate:module_wait_module event:module_event_moddone
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: cache memory msg=303765 rrset=582205 infra=156899 val=109549 subnet=74504
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: iterator[module 2] operate: extstate:module_wait_reply event:module_event_reply
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: out of query targets -- returning SERVFAIL
Oct 15 11:53:06 pihole-master unbound[208391]: [208391:0] debug: return error response SERVFAIL

I’d really appreciate any help—I’m stuck right now and not sure what’s causing the issue. Like mentioned, the WAN or LAN connection is not down. OPNSense logs show that traffic is in fact moving between the LAN and WAN.

Above says its trying to query DNS server IP 192.41.162.30 but not receiving a reply "module_event_noreply":

module_event_noreply ---> no reply, timeout or other error

When this happens, could you run below equivalent dig command on the Pi-hole host and post the output here pls?

dig +norecurse @192.41.162.30 clients3.google.com. aaaa

Also for below equivalent one run a Windows, MacOS or Linux client?

nslookup -type=aaaa clients3.google.com. 192.41.162.30

About that IP, thats the authoritative one for the com. TLD:

$ dig +short -x 192.41.162.30
l.gtld-servers.net.
$ dig +short com. ns
j.gtld-servers.net.
m.gtld-servers.net.
g.gtld-servers.net.
c.gtld-servers.net.
h.gtld-servers.net.
f.gtld-servers.net.
d.gtld-servers.net.
a.gtld-servers.net.
i.gtld-servers.net.
e.gtld-servers.net.
k.gtld-servers.net.
b.gtld-servers.net.
l.gtld-servers.net.

Hello!

Pihole Host Dig Output

joseph@pihole-master:~ $ dig +norecurse @192.41.162.30 clients3.google.com. aaaa
;; communications error to 192.41.162.30#53: timed out
;; communications error to 192.41.162.30#53: timed out
;; communications error to 192.41.162.30#53: timed out

; <<>> DiG 9.18.28-1~deb12u2-Debian <<>> +norecurse @192.41.162.30 clients3.google.com. aaaa
; (1 server found)
;; global options: +cmd
;; no servers could be reached

Windows Client nslookup Output

DNS request timed out.
timeout was 2 seconds.
Server: UnKnown
Address: 192.41.162.30

DNS request timed out.
timeout was 2 seconds.
*** Request to UnKnown timed-out

After some testing, it seems like Unbound might not be the issue after all. I changed the Pi-holes' DNS servers to 8.8.8.8 and 1.1.1.1. But as soon as I connected to WireGuard and ran a speed test, the problem happened again—my home connection broke until I restarted both the Pi-holes and OPNsense.

The more I dig into it, the more it seems like this might be an OPNsense issue. I may need to explore alternatives to WireGuard, like Tailscale, or figure out why OPNsense is acting up.

Here's a screenshot of the traffic when the issue started and during the downtime:

The left side is incoming, right side is outgoing. Orange is WAN, blue is LAN, and green is the WireGuard server. Everything looks fine, connection-wise. Just seems like DNS shits itself on my network no matter if it's unbound, or a public DNS resolver after a speed test or heavy load is needed.

If its a transfer speed test that you're referring to, Pi-hole or Unbound has very little to do for that as DNS queries are cached on Pi-hole, Unbound and the client itself.

In below example, thats 14400 seconds (four hours) that the records should stay cached on the clients before a new DNS query is neccesary to update the records in cache:

$ dig +short speedtest.net. ns
ns-787.awsdns-34.net.
ns-1071.awsdns-05.org.
ns-1643.awsdns-13.co.uk.
ns-372.awsdns-46.com.
$ dig +norecurse +noall +answer @ns-787.awsdns-34.net. speedtest.net.
speedtest.net.          14400   IN      A       151.101.66.219
speedtest.net.          14400   IN      A       151.101.2.219
speedtest.net.          14400   IN      A       151.101.130.219
speedtest.net.          14400   IN      A       151.101.194.219

Why would a speed test break DNS then? I’m a bit confused.

DNS resolution has no impact on ISP bandwidth speed tests, as that is measuring direct communication between a test client and a speed testing server after successful DNS resolution.

The other way round, a speed test saturating your router's available download bandwidth may impact any other traffic (not just DNS) by your router being slower to accept replies.
For DNS, this may impact reply times, but not significantly.

Your trigger scenario, however, may impose additional load:

If you host a VPN server in your home network, your router has to send out all packets that a VPN client downloads, i.e. your router's upstream bandwidth becomes your VPN client's maximum download bandwith.

Consequently, running a speed test in such a scenario could saturate your router's upload bandwidth (for asymmetrical connections, long before it could saturate download bandwidth).
Depending on how your router would prioritise packets, this may significantly impact any other traffic, as packets would have to wait for the router to forward them to the Internet.
The longer that wait, the more likely a client would be to timeout, which in turn may prompt it to repeat its request, further increasing the backlog.

This would be in line with your observations:
Your unbound log as well as your dig and nslookup results show time outs.

What you've shared would not indicate unbound crashing somehow.
On the contrary, your Pi-hole and unbound log excerpts demonstrate that DNS resolution was operational all the time, but unbound was simply waiting for upstream answers.

After the speed test finishes, it may take a while before things are back to normal again. As soon as bandwidth becomes available again, all clients impacted by that wait (and possibly also your router itself) may try to work through their backlog of hanging requests by resending them - once they'd have exceeded their individual time out thresholds.

If you have to reboot OPNsense to get operational again, then that would indicate an issue with OPNsense, rather than unbound.

Adding to above, you should consider trying other diagnostic tools besides nslookup or dig.
When things go south, you could try do a ping to Google's DNS server @8.8.8.8 from that Wireguard connected client eg:

ping 8.8.8.8

Or if the client runs Linux (and I believe also on MacOS), do a traceroute for even more details:

traceroute -n 8.8.8.8

Or below equivalent one if the client runs Windows:

tracert -d 8.8.8.8

These tests dont involve DNS at all.
Ping requests is ICMP only.

Compare those results with when its still working.

EDIT: Oh, you could do the traceroute and ping on the Pi-hole host as well!

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