[SOLVED] Unbound restarting every 1 minute

[tomtom]

[FIX]: Unplugged the Apple TV from ethernet and connected via wifi.

[EDIT]: Looks like the issue is an Apple TV that recently moved from WiFi to ethernet has two active leases in the DHCP table. Once it moved to ethernet I gave it a static lease which seems to have caused the issue. (This was not the issue)

2022-02-01T16:36:47   Error   dhcpd   uid lease 192.168.5.101 for client XX:XX:XX:XX:XX:XX is duplicate on 192.168.5.0/24   
2022-02-01T16:36:47   Error   dhcpd   from the dynamic address pool for 192.168.5.0/24   
2022-02-01T16:36:47   Error   dhcpd   Remove host declaration s_opt2_0 or remove 192.168.5.101   
2022-02-01T16:36:47   Error   dhcpd   Dynamic and static leases present for 192.168.5.101.

I'm not sure I understand why it has a dynamic and static lease given that the WiFi and ethernet have a different mac addresses and each interface is on a different subnet?

Looks to have solved the issue I will report back if not.


Hi All,

I recently did a fresh install of Opnsense 22. It's on a bare-metal i3 6100 with a 4 port intel nic and 3 realtek 2.5gb nics.

I had noticed issues with brief internet outages happening frequently and found that unbound was restarting every minute.

There don't appear to be any errors and I'm not sure what is going on. I do not have DHCP static mappings checked. I am using DNS over TLS using cloudflare servers.

Does anyone have any insight or how I might investigate this issue?

Thanks
Tom

This is the logs on one of the restarts:

2022-02-01T11:58:13   Notice   unbound   [81467:0] notice: init module 1: iterator   
2022-02-01T11:58:13   Notice   unbound   [81467:0] notice: init module 0: validator   
2022-02-01T11:57:49   Notice   unbound   [81467:0] notice: Restart of unbound 1.14.0.   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.065536 0.131072 2   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: lower(secs) upper(secs) recursions   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: [25%]=0 median[50%]=0 [75%]=0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: histogram of recursion processing times   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: average recursion processing time 0.079397 sec   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 3: requestlist max 0 avg 0 exceeded 0 jostled 0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 3: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.065536 0.131072 2   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: lower(secs) upper(secs) recursions   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: [25%]=0 median[50%]=0 [75%]=0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: histogram of recursion processing times   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: average recursion processing time 0.092854 sec   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 2 recursion replies sent, 0 replies dropped, 0 states jostled out   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 2: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.524288 1.000000 1   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.032768 0.065536 2   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.000000 0.000001 2   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: lower(secs) upper(secs) recursions   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: [25%]=6.25e-07 median[50%]=0.04096 [75%]=0.06144   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: histogram of recursion processing times   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: average recursion processing time 0.131735 sec   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 5 recursion replies sent, 0 replies dropped, 0 states jostled out   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 1: 5 queries, 0 answers from cache, 5 recursions, 0 prefetch, 0 rejected by ip ratelimiting   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.065536 0.131072 1   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: 0.032768 0.065536 2   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: lower(secs) upper(secs) recursions   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: [25%]=0 median[50%]=0 [75%]=0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: histogram of recursion processing times   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: average recursion processing time 0.072292 sec   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: mesh has 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 3 recursion replies sent, 0 replies dropped, 0 states jostled out   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 0: requestlist max 1 avg 0.333333 exceeded 0 jostled 0   
2022-02-01T11:57:49   Informational   unbound   [81467:0] info: server stats for thread 0: 3 queries, 0 answers from cache, 3 recursions, 0 prefetch, 0 rejected by ip ratelimiting   
2022-02-01T11:57:48   Informational   unbound   [81467:0] info: service stopped (unbound 1.14.0).   
2022-02-01T11:57:47   Informational   unbound   [81467:0] info: query response was ANSWER

[tomtom]

I have traced the issue down to this log entry which repeats regularly.

2022-02-02T18:54:36   Error   opnsense   /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for static opt2(igb2)   
2022-02-02T18:54:35   Notice   opnsense   plugins_configure hosts (execute task : unbound_hosts_generate())   
2022-02-02T18:54:35   Notice   opnsense   plugins_configure hosts (execute task : dnsmasq_hosts_generate())   
2022-02-02T18:54:35   Notice   opnsense   plugins_configure hosts ()   
2022-02-02T18:54:35   Error   opnsense   /usr/local/etc/rc.newwanip: On (IP address: 192.168.5.1) (interface: OdroidATV[opt2]) (real interface: igb2).   
2022-02-02T18:54:35   Error   opnsense   /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'igb2'   
2022-02-02T18:54:35   Error   opnsense   /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for static opt2(igb2)   
2022-02-02T18:54:32   Error   opnsense   /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for static opt2(igb2)

I have an Apple TV plugged into this interface. I have removed all static leases.

When the apple TV is in standby it causes the above issue. When on there is no problem.