Slow bringup on interface with many VLANs

[bb4242]

Hello all. Thanks to everyone who contributes to opnsense, it's a wonderful project. 

I'm running opnsense as a home router on a protectli FW4B. One of the protectli's ethernet interfaces (igb2) is directly connected (i.e. without a switch in between) to an Intel NUC running proxmox, which hosts 16 virtual machines. Each of these VMs is on a separate VLAN, so there are 16 VLAN interfaces (igb2_vlanXX) configured in opnsense. There are firewall rules configured to allow certain traffic to pass between the VMs and the rest of the home network.

I've noticed recently that when I reboot the NUC, network connectivity is unstable for about 12 minutes before things settle down and the VMs are all reachable again. Looking at the opnsense logs (the full logs are attached), there are first a series of messages related to the link being lost on igb2 (this is expected because of the direct connection between the protectli and the NUC) and then restored as the NUC reboots:


<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="1"] <6>igb2: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="2"] <6>igb2_vlan34: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="3"] <6>igb2_vlan35: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="4"] <6>igb2_vlan32: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="5"] <6>igb2_vlan33: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="6"] <6>igb2_vlan21: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="7"] <6>igb2_vlan36: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="8"] <6>igb2_vlan23: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="9"] <6>igb2_vlan22: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="10"] <6>igb2_vlan25: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="11"] <6>igb2_vlan24: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="12"] <6>igb2_vlan27: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="13"] <6>igb2_vlan29: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="14"] <6>igb2_vlan28: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="15"] <6>igb2_vlan31: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="16"] <6>igb2_vlan90: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain kernel - - [meta sequenceId="17"] <6>igb2_vlan30: link state changed to DOWN
<13>1 2023-07-20T08:28:37-05:00 opnsense.localdomain opnsense 12674 - [meta sequenceId="18"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb2)
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="19"] <6>igb2: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="20"] <6>igb2_vlan34: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="21"] <6>igb2_vlan35: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="22"] <6>igb2_vlan32: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="23"] <6>igb2_vlan33: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="24"] <6>igb2_vlan21: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="25"] <6>igb2_vlan36: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="26"] <6>igb2_vlan23: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="27"] <6>igb2_vlan22: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="28"] <6>igb2_vlan25: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="29"] <6>igb2_vlan24: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="30"] <6>igb2_vlan27: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="31"] <6>igb2_vlan29: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="32"] <6>igb2_vlan28: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="33"] <6>igb2_vlan31: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="34"] <6>igb2_vlan90: link state changed to UP
<13>1 2023-07-20T08:28:40-05:00 opnsense.localdomain kernel - - [meta sequenceId="35"] <6>igb2_vlan30: link state changed to UP


Following this, opnsense starts bringing up igb2 followed by each VLAN interface individually:


<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="120"] /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb2)
<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="121"] /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'
<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="122"] /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt1)
<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="123"] /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt1))
<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="124"] /usr/local/etc/rc.linkup: plugins_configure dhcp ()
<13>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="125"] /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
<12>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="126"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt2
<12>1 2023-07-20T08:29:25-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="127"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt12
<12>1 2023-07-20T08:29:26-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="128"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt22
<13>1 2023-07-20T08:29:26-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="129"] /usr/local/etc/rc.linkup: plugins_configure dns ()
<13>1 2023-07-20T08:29:26-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="130"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())
<13>1 2023-07-20T08:29:26-05:00 opnsense.localdomain opnsense 58565 - [meta sequenceId="131"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())
<13>1 2023-07-20T08:29:35-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="132"] /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt19(igb2_vlan34)
<13>1 2023-07-20T08:29:36-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="133"] /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt19'
<13>1 2023-07-20T08:29:36-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="134"] /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt19)
<13>1 2023-07-20T08:29:36-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="135"] /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt19))
<13>1 2023-07-20T08:29:36-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="136"] /usr/local/etc/rc.linkup: plugins_configure dhcp ()
<13>1 2023-07-20T08:29:36-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="137"] /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
<12>1 2023-07-20T08:29:38-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="138"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt2
<12>1 2023-07-20T08:29:38-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="139"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt12
<12>1 2023-07-20T08:29:39-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="140"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt22
<13>1 2023-07-20T08:29:39-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="141"] /usr/local/etc/rc.linkup: plugins_configure dns ()
<13>1 2023-07-20T08:29:39-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="142"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())
<13>1 2023-07-20T08:29:39-05:00 opnsense.localdomain opnsense 96631 - [meta sequenceId="143"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())
<13>1 2023-07-20T08:29:47-05:00 opnsense.localdomain opnsense 55951 - [meta sequenceId="144"] /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt21(igb2_vlan35)
<13>1 2023-07-20T08:29:48-05:00 opnsense.localdomain opnsense 55951 - [meta sequenceId="145"] /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt21'


Looking at the log timestamps, it seems that there is a ~10 second delay between bringing up each interface, so it takes about 16*10=160 seconds to bring up all of these interfaces. However, after the last interface is brought up, they are all taken down again and the process repeats:


<13>1 2023-07-20T08:32:28-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="302"] /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt14'
<13>1 2023-07-20T08:32:28-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="303"] /usr/local/etc/rc.linkup: plugins_configure ipsec (,opt14)
<13>1 2023-07-20T08:32:28-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="304"] /usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,opt14))
<13>1 2023-07-20T08:32:28-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="305"] /usr/local/etc/rc.linkup: plugins_configure dhcp ()
<13>1 2023-07-20T08:32:28-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="306"] /usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())
<12>1 2023-07-20T08:32:29-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="307"] /usr/local/etc/rc.linkup: dhcpd_dhcp4_configure() found no suitable IPv4 address on opt2
<13>1 2023-07-20T08:32:30-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="308"] /usr/local/etc/rc.linkup: plugins_configure dns ()
<13>1 2023-07-20T08:32:30-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="309"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())
<13>1 2023-07-20T08:32:30-05:00 opnsense.localdomain opnsense 91638 - [meta sequenceId="310"] /usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())
<13>1 2023-07-20T08:32:38-05:00 opnsense.localdomain opnsense 55018 - [meta sequenceId="311"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt1(igb2)
<13>1 2023-07-20T08:32:42-05:00 opnsense.localdomain opnsense 84570 - [meta sequenceId="312"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt19(igb2_vlan34)
<13>1 2023-07-20T08:32:45-05:00 opnsense.localdomain opnsense 93844 - [meta sequenceId="313"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt21(igb2_vlan35)
<13>1 2023-07-20T08:32:48-05:00 opnsense.localdomain opnsense 23369 - [meta sequenceId="314"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt16(igb2_vlan32)
<13>1 2023-07-20T08:32:50-05:00 opnsense.localdomain opnsense 34216 - [meta sequenceId="315"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt17(igb2_vlan33)
<13>1 2023-07-20T08:32:53-05:00 opnsense.localdomain opnsense 65567 - [meta sequenceId="316"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt5(igb2_vlan21)
<13>1 2023-07-20T08:32:55-05:00 opnsense.localdomain opnsense 76256 - [meta sequenceId="317"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt22(igb2_vlan36)
<13>1 2023-07-20T08:32:58-05:00 opnsense.localdomain opnsense 7471 - [meta sequenceId="318"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt7(igb2_vlan23)
<13>1 2023-07-20T08:33:00-05:00 opnsense.localdomain opnsense 20412 - [meta sequenceId="319"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt6(igb2_vlan22)
<13>1 2023-07-20T08:33:03-05:00 opnsense.localdomain opnsense 50947 - [meta sequenceId="320"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt8(igb2_vlan25)
<13>1 2023-07-20T08:33:05-05:00 opnsense.localdomain opnsense 77944 - [meta sequenceId="321"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt4(igb2_vlan24)
<13>1 2023-07-20T08:33:08-05:00 opnsense.localdomain opnsense 87395 - [meta sequenceId="322"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt9(igb2_vlan27)
<13>1 2023-07-20T08:33:11-05:00 opnsense.localdomain opnsense 18056 - [meta sequenceId="323"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt13(igb2_vlan29)
<13>1 2023-07-20T08:33:13-05:00 opnsense.localdomain opnsense 28371 - [meta sequenceId="324"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt11(igb2_vlan28)
<13>1 2023-07-20T08:33:16-05:00 opnsense.localdomain opnsense 56759 - [meta sequenceId="325"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt3(igb2_vlan31)
<13>1 2023-07-20T08:33:18-05:00 opnsense.localdomain opnsense 65737 - [meta sequenceId="326"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt12(igb2_vlan90)
<13>1 2023-07-20T08:33:21-05:00 opnsense.localdomain opnsense 95314 - [meta sequenceId="327"] /usr/local/etc/rc.linkup: DEVD: Ethernet detached event for opt14(igb2_vlan30)
<13>1 2023-07-20T08:33:23-05:00 opnsense.localdomain opnsense 4525 - [meta sequenceId="329"] /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for opt1(igb2)
<13>1 2023-07-20T08:33:24-05:00 opnsense.localdomain opnsense 4525 - [meta sequenceId="330"] /usr/local/etc/rc.linkup: ROUTING: entering configure using 'opt1'


This cycle of bringing the interfaces down and then back up repeats a few more times before things finally stabilize around 12 minutes after the reboot of the NUC. In addition to connectivity to the VMs being unstable during that 12 minutes, other services like unbound also seem to be affected (DNS lookups are slow or timeout), which impacts the whole network.

I'm pretty sure that I could power cycle the NUC on older versions of opnsense without this slow startup behavior occurring. I'm curious about the 10 second delay in bringing up each interface, and also why the whole bringup process repeats several times. Does anyone have any suggestions to improve this situation? Thanks!