Topics

[NTP not syncing anymore on backup node]

Hi everyone!

I have a HA-Cluster with 2 nodes running on 23.1.11.

I am trying to upgrade but I see 2 issues causing me to hesitate:

• NTP not syncing anymore on backup node
• Weird failover after config-sync (see: https://forum.opnsense.org/index.php?topic=34140.msg181801#msg181801

I noticed time being out of sync on the backup node and network time>Status showing Unreach/Pending for all configured NTP servers.
While troubleshooting this I noticed that the network time service on the backup node uses the VIP of the WAN-interface to send its requests to the ntp servers instead of its own address on WAN. This struck me as stupid, since the replies will go to the master node.
No other service on the backup behaves like this to my knowledge. DNS and other outgoing connections like backup to gitlab/Nextcloud work fine.

If I SSH into the host and use ntpdate it will use its own IP and thus be able to sync time. When I stop the network time service and use ntpdate *ntp-server* I can successfully set the current time.

CARP is running on WAN and on several VLANs on LAN. Additionally there is an alias-IP on WAN used to SNAT some local subnets. I have state-sync and config-sync for network time (and more) configured. Config sync is disabled for static routes, but none are configured.

I can not tell exactly when this started, I just know with certainty that it has not been an issue up until I started upgrading the cluster step-by-step from 21.x onwards.

So far I have tried

• restarting the network time service
• rebooting the node
• outbound SNAT rule to SNAT traffic to ntp-server to its own IP
• searching for similar issues

Can someone tell me what I could look for? It feels like a bug to me but I see no reports of this behaviour from anyone else.

[Environment:]

Hi everyone!

I saw some weird behaviour of a HA-cluster last week on which I would like to consult you guys.

Environment:
Its a 2 node cluster. The main-firewall (IP: .11) ran on 22.7 and the backup-firewall (IP: .12) on 23.1.
In total there are 8 CARP-Instances: 1 on WAN (VIP: .10), 7 on VLANs on LAN.
The VIP of WAN is used for a site-2-site IPsec.
In addition there is an alias (IP: .14) on WAN.
WAN and LAN are connected to a switch stack. The sync-interface is directly connected between the two firewalls.
The ISP gateway (IP: .9) is connected to the same switch and is being monitored by both firewalls as default gateway.
During this saga nothing in terms of link-status events was logged on the switch.

Config:

Code Select Expand

net.inet.carp.preempt: 1
otherwise see screenshots

What happened:
At 17:27:45 (see attached log extract) the backup firewall started swapping between INIT and BACKUP on WAN. After a few seconds it became MASTER. But it only took MASTER role on WAN, all other interfaces stayed BACKUP. Meanwhile the main-firewall still had MASTER status on all interfaces. This stayed this way until I rebooted the backup-firewall. Then everything was back to normal, backup-node had BACKUP state on all interfaces. dmesg on backup-firewall was clean concerning the NICs.
The IPsec tunnel was not affected at all and seemed to be held by main-firewall.

This happened while the ISP or their carrier had some IP-hash based routing issues between 16:57 and 18:32.
This definetely affected the cluster in terms of external availability, but internally all should have been fine. There are no logs indicating loss to the default gateway. (IPs of the cluster were available while others were not. Depending on external source-ip the available/unavailable IPs varied).


Attached are the logs of backup-firewall during the timeframe when it occured. During the state-switching there are logs concerning OpenVPN on backup-firewall even though OpenVPN is not configured on these systems (but installed). It logs the alias-ip (.14) disappearing on WAN - could this cause CARP to "freak-out" in this way? I dont know why it would disappear - it is still configured as it was on both systems.

On the main-firewall only this was logged (apart from filterlogs):

Code Select Expand


May 17 17:27:14 main-firewall configd.py[244]: [6d22285b-e647-45f5-a0a2-b7f33c75f747] system status
...
May 17 17:27:19 main-firewall configd.py[244]: [3636d608-c56b-4e4b-97cd-d4a1f49f07b8] request pfsync info
...
May 17 17:27:20 main-firewall configd.py[244]: [b7530887-f020-441a-9544-2847c8758fe9] system status
...
May 17 17:27:39 main-firewall configd.py[244]: [50cf99f7-c26e-46ed-a62c-a28676368395] system status
...
May 17 17:27:43 main-firewall configd.py[244]: [a86b37a2-e610-4420-9e69-86cc469980da] Syncing firewall
...
May 17 17:27:47 main-firewall opnsense[18207]: /usr/local/etc/rc.filter_synchronize: Filter sync successfully completed with https://192.168.254.2/xmlrpc.php.
...
May 17 17:27:50 sws-tue-gw1 devd[506]: Processing event '!system=DEVFS subsystem=CDEV type=DESTROY cdev=pts/0'



I was doing updates during the last few weeks from 20.x to 23.1 - always putting the backup-firewall one step ahead of the main-firewall. This issue occurred about 2 hrs after the last update.

Right now I can not explain what might have caused the issues with CARP here.
It happened right after a filter sync, but the logs dont show any dropped CARP advertisements. Also in my understanding during the failover all interfaces should be transfered instead of only one. Obviously the main-firewall should not have stayed MASTER given a valid cause for the failover itself. I dont see how the ISP/upstream issues could have caused this, even though it happened during this time.

Do you have an idea what might have caused this issue? I would be very grateful.

If I missed something you need in terms of configuration or description please let me know.

[Setup is as follows:]

Hi everyone!

Just caused a couple unintended failovers on our CARP-Cluster on a client site. Has been running rock solid for a good 500 days. CARP worked fine so the client did not notice the failover at all. Nevertheless I would like to clear up this issue, since I have to do further configurations.

Setup is as follows:

• 2x OPNsense 20.7.8_4-amd64 (I know)
• 4 NICS
• 3 VLANs on LAN (igb0)
• CARP on all VLANs and WAN-Port (igb1)

Scenario:
Client site gets a new wifi setup which requires 4 more VLANs on the LAN interface (igb0). After adding every VLAN I got "logged out" from the webinterface, had to relog and got Cookie related errors. On the fourth occurrence I noticed, that the cluster was actually failing over every time I added a VLAN since I relogged to the secondary node.

Upon checking the logs, I saw that the Interface goes down for about 5 seconds after adding a VLAN to it.

I am not used to anything of the sort on other network hardware when making such changes. I did not find any known issue/bugs/reports of this effect.

I am now hesitant to configure the cluster further (VLANs on Backup-Node, IPs on those new VLANs, CARP on those new VLANs, DHCP on those new VLANs).

Logs (after adding VLAN 903 on LAN (igb0) ):

Code Select Expand

Jun 30 08:53:08 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=vlan4 type=ATTACH'
Jun 30 08:53:08 sws-tue-gw1 devd[98176]: Processing event '!system=ETHERNET subsystem=vlan4 type=IFATTACH'
Jun 30 08:53:08 sws-tue-gw1 devd[98176]: Executing '/usr/libexec/hyperv/hyperv_vfattach $'vlan4' 0'
Jun 30 08:53:08 sws-tue-gw1 dhcpd[62818]: failover peer dhcp_opt2: network down
Jun 30 08:53:08 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0 type=LINK_DOWN'
Jun 30 08:53:08 sws-tue-gw1 charon[37623]: 15[KNL] interface igb0_vlan903 appeared
Jun 30 08:53:08 sws-tue-gw1 charon[37623]: 15[KNL] xxx.xxx.xxx.xxx disappeared from igb1
Jun 30 08:53:08 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup stop $'igb0''
Jun 30 08:53:08 sws-tue-gw1 charon[37623]: 15[KNL] interface igb0_vlan903 activated
Jun 30 08:53:08 sws-tue-gw1 configd.py[96964]: [14c7ff7b-1237-4d5f-ac39-021f62c205ba] Linkup stopping igb0
Jun 30 08:53:09 sws-tue-gw1 opnsense[36836]: /usr/local/etc/rc.linkup: Hotplug event detected for LAN(lan) but ignoring since interface is configured with static IP (0.0.0.0 ::)
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Processing event '!system=CARP subsystem=4@igb0_vlan990 type=INIT'
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0_vlan990 type=LINK_DOWN'
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup stop $'igb0_vlan990''
Jun 30 08:53:09 sws-tue-gw1 configd.py[96964]: [09c46065-3f53-4592-a74f-aa78cc4eac34] Linkup stopping igb0_vlan990
Jun 30 08:53:09 sws-tue-gw1 configctl[28232]: event @ 1656571988.80 msg: Jun 30 08:53:08 sws-tue-gw1.xxxxxxxxxx.xx config[53108]: config-event: new_config /conf/backup/config-1656571988.7957.xml
Jun 30 08:53:09 sws-tue-gw1 configctl[28232]: event @ 1656571988.80 exec: system event config_changed
Jun 30 08:53:09 sws-tue-gw1 configd.py[96964]: [5a25d4db-8863-4201-89a2-14bf1a5d8614] trigger config changed event
Jun 30 08:53:09 sws-tue-gw1 opnsense[17071]: /usr/local/etc/rc.linkup: Hotplug event detected for LAN_990_mgmt(opt6) but ignoring since interface is configured with static IP (10.199.90.252 ::)
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0_vlan903 type=LINK_DOWN'
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup stop $'igb0_vlan903''
Jun 30 08:53:09 sws-tue-gw1 configd.py[96964]: [d15cb733-9914-4d71-8b08-9ddc3b7d4ae7] Linkup stopping igb0_vlan903
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Processing event '!system=CARP subsystem=3@igb0_vlan902 type=INIT'
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0_vlan902 type=LINK_DOWN'
Jun 30 08:53:09 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup stop $'igb0_vlan902''
Jun 30 08:53:09 sws-tue-gw1 configd.py[96964]: [d081e87b-e10b-4f6b-9ae3-2680b0b43e4d] Linkup stopping igb0_vlan902
Jun 30 08:53:09 sws-tue-gw1 filterlog[96237]: 81,,,0,igb0_vlan903,match,pass,out,6,0x00,0x00000,1,ip,0,36,::,ff02::16,HBH,PADN,RTALERT,0x0000,
Jun 30 08:53:09 sws-tue-gw1 filterlog[96237]: 81,,,0,igb0_vlan903,match,pass,out,6,0x00,0x00000,255,ipv6-icmp,58,32,::,ff02::1:ff00:346d,
Jun 30 08:53:09 sws-tue-gw1 opnsense[43024]: /usr/local/etc/rc.linkup: Hotplug event detected for LAN_902_printers(opt4) but ignoring since interface is configured with static IP (10.200.28.252 ::)
Jun 30 08:53:10 sws-tue-gw1 devd[98176]: Processing event '!system=CARP subsystem=1@igb0_vlan901 type=INIT'
Jun 30 08:53:10 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0_vlan901 type=LINK_DOWN'
Jun 30 08:53:10 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup stop $'igb0_vlan901''
Jun 30 08:53:10 sws-tue-gw1 configd.py[96964]: [76e761f3-41d9-4be1-afff-7ad5e66f82d3] Linkup stopping igb0_vlan901
Jun 30 08:53:10 sws-tue-gw1 opnsense[52486]: /usr/local/etc/rc.linkup: Hotplug event detected for LAN_901_intra(opt2) but ignoring since interface is configured with static IP (10.200.32.252 ::)
Jun 30 08:53:10 sws-tue-gw1 devd[98176]: Processing event '!system=CARP subsystem=2@igb1 type=BACKUP'
Jun 30 08:53:10 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface carp $'2@igb1' $'BACKUP''
Jun 30 08:53:10 sws-tue-gw1 configd.py[96964]: [ce3a5ff4-b1a0-423e-b5c3-6e28c29d5021] Carp event on subsystem 2@igb1 for type BACKUP
Jun 30 08:53:10 sws-tue-gw1 opnsense[50023]: /usr/local/etc/rc.syshook.d/carp/20-openvpn: Carp cluster member "xxx.xxx.xxx.xxx - VIP_WAN (2@igb1)" has resumed the state "BACKUP" for vhid 2
Jun 30 08:53:13 sws-tue-gw1 devd[98176]: Processing event '!system=IFNET subsystem=igb0 type=LINK_UP'
Jun 30 08:53:13 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface linkup start $'igb0''
Jun 30 08:53:13 sws-tue-gw1 configd.py[96964]: [3dfd282b-bf24-4d4d-80d0-46a82d86a05f] Linkup starting igb0
Jun 30 08:53:13 sws-tue-gw1 opnsense[5859]: /usr/local/etc/rc.linkup: Hotplug event detected for LAN(lan) but ignoring since interface is configured with static IP (0.0.0.0 ::)
Jun 30 08:53:13 sws-tue-gw1 configd.py[96964]: [2c62e4a1-2680-43be-8746-1f9d64434060] New IPv4 on igb0
Jun 30 08:53:13 sws-tue-gw1 opnsense[51169]: /usr/local/etc/rc.newwanip: IPv4 renewal is starting on 'igb0'
Jun 30 08:53:13 sws-tue-gw1 opnsense[51169]: /usr/local/etc/rc.newwanip: On (IP address: ) (interface: LAN[lan]) (real interface: igb0).
Jun 30 08:53:13 sws-tue-gw1 opnsense[51169]: /usr/local/etc/rc.newwanip: Failed to detect IP for LAN[lan]
Jun 30 08:53:13 sws-tue-gw1 devd[98176]: Processing event '!system=CARP subsystem=4@igb0_vlan990 type=BACKUP'
Jun 30 08:53:13 sws-tue-gw1 devd[98176]: Executing '/usr/local/opnsense/service/configd_ctl.py interface carp $'4@igb0_vlan990' $'BACKUP''