opnsense / core

OPNsense GUI, API and systems backend
https://opnsense.org/
BSD 2-Clause "Simplified" License
3.09k stars 701 forks source link

No DNS resolution for 10 mins when specific interface's state changes to UP #7426

Open jangzn opened 2 months ago

jangzn commented 2 months ago

Important notices

Before you add a new report, we ask you kindly to acknowledge the following:

Describe the bug DNS resolution not working from any network for about 10 mins when client directly connected to interface with identifier opt1 comes online. GUI access is still working. It looks like many actions are performed internally over and over within this 10 mins of downtime and error action rfc2136.reload.opt1 not found for user root is reported multiple times. A clear and concise description of what the bug is, including last known working version (if any). The general log file shows, that the interface's state is changed multiple times before it finally remains in UP.

To Reproduce Not sure if this is what caused the issue but here is what I did:

Expected behavior Internet connection and DNS resolution keep working on all networks when the machine connected to opt1 comes online.

Describe alternatives you considered

Screenshots None

Relevant log files Audit Log: 2024-05-01T16:52:26 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:52:22 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:51:06 Error configd.py action rfc2136.reload.opt1 not found for user root 2024-05-01T16:51:00 Informational configd.py action allowed template.reload for user root
2024-05-01T16:49:19 Informational configd.py action allowed unbound.cache for user root
2024-05-01T16:49:18 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:49:18 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:49:17 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:49:17 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:49:16 Informational configd.py action allowed interface.routes.list for user root
2024-05-01T16:49:16 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:49:15 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:49:15 Informational configd.py action allowed interface.linkup.start for user root 2024-05-01T16:49:14 Informational configd.py action allowed interface.linkup.stop for user root
2024-05-01T16:49:14 Error configd.py action rfc2136.reload.opt1 not found for user root
2024-05-01T16:49:09 Informational configd.py action allowed template.reload for user root
2024-05-01T16:49:06 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:49:00 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:48:57 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:48:53 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:48:18 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:47:24 Informational configd.py action allowed unbound.cache for user root
2024-05-01T16:47:23 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:47:22 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:47:22 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:47:22 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:47:21 Informational configd.py action allowed interface.routes.list for user root
2024-05-01T16:47:20 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:47:20 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:47:20 Informational configd.py action allowed interface.linkup.start for user root 2024-05-01T16:47:19 Informational configd.py action allowed interface.linkup.stop for user root
2024-05-01T16:47:18 Error configd.py action rfc2136.reload.opt1 not found for user root
2024-05-01T16:47:14 Informational configd.py action allowed template.reload for user root
2024-05-01T16:47:06 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:47:02 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:45:29 Informational configd.py action allowed unbound.cache for user root
2024-05-01T16:45:28 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:45:27 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:45:27 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:45:26 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:45:26 Informational configd.py action allowed interface.routes.list for user root
2024-05-01T16:45:25 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:45:24 Informational configd.py action allowed interface.linkup.start for user root 2024-05-01T16:45:23 Informational configd.py action allowed interface.linkup.stop for user root
2024-05-01T16:45:23 Error configd.py action rfc2136.reload.opt1 not found for user root
2024-05-01T16:45:19 Informational configd.py action allowed template.reload for user root
2024-05-01T16:44:58 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:57 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:56 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:55 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:53 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:52 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:48 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:48 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:46 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:46 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:15 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:11 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:11 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:06 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:06 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:44:01 Informational configd.py action allowed system.status for user root
2024-05-01T16:44:01 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:43:32 Informational configd.py action allowed unbound.cache for user root
2024-05-01T16:43:31 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:43:31 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:43:31 Informational configd.py action allowed system.status for user root
2024-05-01T16:43:30 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:43:30 Informational configd.py action allowed system.diag.log for user root
2024-05-01T16:43:30 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:43:29 Informational configd.py action allowed interface.routes.list for user root
2024-05-01T16:43:29 Informational configd.py action allowed ipsec.list.legacy_vti for user root
2024-05-01T16:43:28 Informational configd.py action allowed interface.linkup.start for user root 2024-05-01T16:43:27 Informational configd.py action allowed interface.linkup.stop for user root
2024-05-01T16:43:27 Error configd.py action rfc2136.reload.opt1 not found for user root
2024-05-01T16:43:22 Informational configd.py action allowed template.reload for user root

General log: 2024-05-01T16:49:19 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do()) 2024-05-01T16:49:19 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do()) 2024-05-01T16:49:19 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2024-05-01T16:49:17 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2024-05-01T16:49:17 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp () 2024-05-01T16:49:17 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt1))
2024-05-01T16:49:17 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt1)
2024-05-01T16:49:16 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'
2024-05-01T16:49:15 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb1)
2024-05-01T16:49:14 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb1)
2024-05-01T16:47:24 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do()) 2024-05-01T16:47:24 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do()) 2024-05-01T16:47:24 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2024-05-01T16:47:21 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2024-05-01T16:47:21 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp () 2024-05-01T16:47:21 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt1))
2024-05-01T16:47:21 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt1)
2024-05-01T16:47:21 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'
2024-05-01T16:47:20 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb1)
2024-05-01T16:47:19 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb1)
2024-05-01T16:45:29 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do()) 2024-05-01T16:45:29 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do()) 2024-05-01T16:45:29 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2024-05-01T16:45:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2024-05-01T16:45:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp () 2024-05-01T16:45:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt1))
2024-05-01T16:45:26 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt1)
2024-05-01T16:45:26 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'
2024-05-01T16:45:25 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb1)
2024-05-01T16:45:24 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb1)
2024-05-01T16:43:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do()) 2024-05-01T16:43:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do()) 2024-05-01T16:43:32 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dns ()
2024-05-01T16:43:30 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
2024-05-01T16:43:30 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure dhcp () 2024-05-01T16:43:30 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt1))
2024-05-01T16:43:30 Notice opnsense /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt1)
2024-05-01T16:43:29 Notice opnsense /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'
2024-05-01T16:43:28 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb1)
2024-05-01T16:43:27 Notice opnsense /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb1)
2024-05-01T16:42:55 Notice kernel <6>igb1: link state changed to UP
2024-05-01T16:42:51 Notice kernel <6>igb1: link state changed to DOWN 2024-05-01T16:42:37 Notice kernel <6>igb1: link state changed to UP
2024-05-01T16:42:33 Notice kernel <6>igb1: link state changed to DOWN 2024-05-01T16:42:26 Notice kernel <6>igb1: link state changed to UP
2024-05-01T16:42:23 Notice kernel <6>igb1: link state changed to DOWN 2024-05-01T16:42:21 Notice kernel <6>igb1: link state changed to UP
2024-05-01T16:42:17 Notice kernel <6>igb1: link state changed to DOWN

Additional context Similar error was reported in forum

Environment OPNsense 24.1.6 (amd64). AMD Embedded G series GX-412TC Intel i211AT

lewisporter commented 2 months ago

Having a similar issue. I updated my switch and the internet wasn't working when the switch came back online. DNS seemed broken, and unbound was eating 100% of the CPU. I tried restarting the service via the UI and killing unbound via SSH - no improvement. In the end, I had to reboot the router.

Found this in the logs, repeating many times:


 configd.py 53584 - [meta sequenceId="1"] action allowed interface.linkup.start for user root
 configd.py 53584 - [meta sequenceId="2"] action allowed ipsec.list.legacy_vti for user root
 configd.py 53584 - [meta sequenceId="3"] action allowed interface.routes.list for user root
 configd.py 53584 - [meta sequenceId="4"] action allowed unbound.cache for user root
 configd.py 53584 - [meta sequenceId="5"] action allowed template.reload for user root
 configd.py 53584 - [meta sequenceId="6"] action rfc2136.reload.lan not found for user root
 configd.py 53584 - [meta sequenceId="7"] action allowed interface.linkup.stop for user root
 configd.py 53584 - [meta sequenceId="8"] action allowed interface.linkup.start for user root
 configd.py 53584 - [meta sequenceId="9"] action allowed ipsec.list.legacy_vti for user root
 configd.py 53584 - [meta sequenceId="10"] action allowed interface.routes.list for user root
 configd.py 53584 - [meta sequenceId="11"] action allowed unbound.cache for user root
 configd.py 53584 - [meta sequenceId="12"] action allowed template.reload for user root
 configd.py 53584 - [meta sequenceId="13"] action rfc2136.reload.lan not found for user root

From looking at the resolver logs, it seems like something was aggressively killing and restarting unbound in a loop.

cardosocardoso commented 1 month ago

Is there any solution to this at all? I've been trying to troubleshoot to no avail. There are plenty of posts about this on reddit but no one seems to find a culprit. I tried disabling unbound, tried changing ports, it always goes back to this error.

2024-05-20T10:42:48-03:00 | Error | configd.py | action rfc2136.reload.lan not found for user root |  
2024-05-20T09:03:20-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-20T09:02:55-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:14-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:13-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:12-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:11-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:10-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root |  
2024-05-19T01:29:08-03:00 | Error | configd.py | action rfc2136.reload.opt1 not found for user root

I think I'm rolling back to a previous version until this is solved. P.S. My installation is pretty much barebones. DHCP, 2 wans, 1 lan, all the default opnsense rules.

AdSchellevis commented 1 month ago

When not using the rfc2136 plugin, this message can be ignored, looks like a remnant from legacy code (it's only trying to execute something that doesn't exist).

https://github.com/opnsense/core/blob/611ee6a4a23f0a297d23efe544340f909e9c1199/src/etc/inc/interfaces.inc#L2374

If this message repeats often, the network connection might be unstable (up/down events)

tsense1337 commented 4 days ago

I have a similar problem since version 24.1.6. On my Alix Apu board. There are two machines in a CARP (Pfsync) cluster. After a restart, the first master machine can access the Internet for approx. 2 minutes, e.g. Refresh feed. The firewall then reports:

Currently running OPNsense 24.1.9_4 at Thu Jul 4 10:23:20 CEST 2024 Fetching changelog information, please wait... fetch: https://pkg.opnsense.org/FreeBSD:13:amd64/24.1/sets/changelog.txz: Network is unreachable Updating OPNsense repository catalog... pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/24.1/latest/meta.txz: Network is unreachable repository OPNsense has no meta file, using default settings pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/24.1/latest/packagesite.pkg: Network is unreachable pkg: https://pkg.opnsense.org/FreeBSD:13:amd64/24.1/latest/packagesite.txz: Network is unreachable Unable to update repository OPNsense Error updating repositories! Checking integrity... done (0 conflicting) Your packages are up to date.

Internet access works permanently on the slave machine. The problem only arose in the update to 24.1.6. The following messages also appear on both firewalls: 2024-06-24T07:36:08 Error configd.py action rfc2136.reload.wan not found for user root
2024-06-24T07:35:39 Error configd.py action rfc2136.reload.lan not found for user root what else can I check?