Simple high network load causing CARP switches and timeouts on VMWare VMs

G

gnoma

Hello,

Recently I have migrated 2 firewalls in CARP setup from OpenBSD to FreeBSD 12.1-RELEASE on vmware VMs (ESXi 6.5) with E1000 interfaces. Both hosts are with 10Gbit interfaces connected to on single 10Gbit switch.

The CARP setup is working fine during the day but during the night I got some alerts saying that there's a package loss to the internal CARP IP address, also checking the dmesg I see lots of CARP failovers.
It appears to be caused by high network load during znapzend backups.

Today I have successfully reproduced it by running a simple scp of a larger file between the 2 firewalls.

My setup:
Primary firewall:
Code: 
carp: MASTER vhid 201 advbase 1 advskew 0

Backup firewall:
Code: 
carp: BACKUP vhid 201 advbase 1 advskew 100

Command executed:
Code: 
root@fw1:/usr/home/k_georgiev # scp /home/k_georgiev/test.file me@fw2.deltanews.lan:/usr/home/k_georgiev
Password for k_georgiev@fw2.deltanews.lan:
test.file                                                                                                                       2%  165MB  47.2MB/s   02:37 ETA
root@fw1:/usr/home/k_georgiev #

The result:

Code: 
Jan  1 15:01:54 fw2 su[96881]: k_georgiev to root on /dev/pts/1
Jan  1 15:15:36 fw2 kernel: carp: 203@em3: BACKUP -> MASTER (master timed out)
Jan  1 15:15:36 fw2 kernel: carp: 205@em0: BACKUP -> MASTER (master timed out)
Jan  1 15:15:36 fw2 kernel: carp: 200@em4: BACKUP -> MASTER (master timed out)
Jan  1 15:15:36 fw2 kernel: carp: 201@em1: BACKUP -> MASTER (master timed out)
Jan  1 15:15:36 fw2 kernel: carp: 202@em2: BACKUP -> MASTER (master timed out)
Jan  1 15:15:36 fw2 kernel: carp: 202@em2: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:36 fw2 kernel: em2: deletion failed: 3
Jan  1 15:15:36 fw2 kernel: carp: 201@em1: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:36 fw2 kernel: em1: deletion failed: 3
Jan  1 15:15:36 fw2 syslogd: last message repeated 1 times
Jan  1 15:15:36 fw2 kernel: carp: 205@em0: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:36 fw2 kernel: em0: deletion failed: 3
Jan  1 15:15:36 fw2 kernel: carp: 200@em4: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:36 fw2 kernel: em4: deletion failed: 3
Jan  1 15:15:36 fw2 syslogd: last message repeated 1 times
Jan  1 15:15:36 fw2 kernel: carp: 203@em3: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:36 fw2 kernel: em3: deletion failed: 3
Jan  1 15:15:39 fw2 kernel: carp: 201@em1: BACKUP -> MASTER (master timed out)
Jan  1 15:15:39 fw2 kernel: carp: 202@em2: BACKUP -> MASTER (master timed out)
Jan  1 15:15:39 fw2 kernel: carp: 203@em3: BACKUP -> MASTER (master timed out)
Jan  1 15:15:39 fw2 kernel: carp: 200@em4: BACKUP -> MASTER (master timed out)
Jan  1 15:15:39 fw2 kernel: carp: 205@em0: BACKUP -> MASTER (master timed out)
Jan  1 15:15:40 fw2 kernel: carp: 200@em4: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:40 fw2 kernel: em4: deletion failed: 3
Jan  1 15:15:40 fw2 syslogd: last message repeated 1 times
Jan  1 15:15:40 fw2 kernel: carp: 203@em3: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:40 fw2 kernel: em3: deletion failed: 3
Jan  1 15:15:40 fw2 kernel: carp: 202@em2: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:40 fw2 kernel: em2: deletion failed: 3
Jan  1 15:15:40 fw2 kernel: carp: 205@em0: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:40 fw2 kernel: em0: deletion failed: 3
Jan  1 15:15:40 fw2 kernel: carp: 201@em1: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:40 fw2 kernel: em1: deletion failed: 3
Jan  1 15:15:40 fw2 syslogd: last message repeated 1 times
Jan  1 15:15:43 fw2 kernel: carp: 200@em4: BACKUP -> MASTER (master timed out)
Jan  1 15:15:43 fw2 kernel: carp: 205@em0: BACKUP -> MASTER (master timed out)
Jan  1 15:15:43 fw2 kernel: carp: 202@em2: BACKUP -> MASTER (master timed out)
Jan  1 15:15:43 fw2 kernel: carp: 203@em3: BACKUP -> MASTER (master timed out)
Jan  1 15:15:43 fw2 kernel: carp: 201@em1: BACKUP -> MASTER (master timed out)
Jan  1 15:15:44 fw2 kernel: carp: 202@em2: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:44 fw2 kernel: em2: deletion failed: 3
Jan  1 15:15:44 fw2 kernel: carp: 201@em1: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:44 fw2 kernel: em1: deletion failed: 3
Jan  1 15:15:44 fw2 syslogd: last message repeated 1 times
Jan  1 15:15:44 fw2 kernel: carp: 205@em0: MASTER -> BACKUP (more frequent advertisement received)
Jan  1 15:15:44 fw2 kernel: em0: deletion failed: 3
Jan  1 15:15:44 fw2 kernel: carp: 200@em4: MASTER -> BACKUP (more frequent advertisement received)
..................

This time I've noticed only CARP switches on the backup firewall however during the night I have also seen such behavior on the primary one too.

The most strange thing is that failovers and timeouts continue 10-15 minutes after the scp has been stopped.
This is very very very strange behavior, it's hard for me to believe that a simple scp can cause firewall failovers.

Have anybody seen this behavior before? Could it be a configuration issue?
I would appreciate any idea what may be causing it.

Thanks in advance
 
Hello,

Thank you for the suggestion. Tried it yesterday, switched all interfaces to vmx3 and the issue still repeats.

tcpdump says that the multicast vrrp heartbeat is being delayed. Advbase is 1 second, but for some reason the delay is 3-4 seconds and then I see several hartbeat packages being received at the same time. May be some queueing and buffering is happening.

Sniffer on a side physical system connected to the same 10Gbit switch also is receiving packages with few seconds delay and then burst several packages.
Also did experiment with migrating both firewalls on the same ESXi host. This time there was no heartbeat delay at all and during scp the issue did not reproduce.

So my assumption now is that this is somehow related to exiting the ESXi host and going to the physical switch. Or may be related to physical switch configuration. Checked all the configuration and didn't find anything about queueing.
I'm starting to wonder if I should apply some kind of QoS for the multicast traffic.
 
If I recall correctly you need to allow 'promiscuous' mode on the ESXi VM configuration for CARP. Is that enabled too?
 
Yes, it's done on vmware virtual switches - promiscuous mode and tolerate mac address changes.

Also have done this according to this articule because in the past I had issues with duplicated heartbeat packages received:
Code: 
esxcli system settings advanced set -o /Net/ReversePathFwdCheckPromisc -i 1

I had OpenBSD CARP firewalls running for almost a decade on these ESXi hosts with the same configuration and only now since I have migrated to FreeBSD I have these issues.
I know that FreeBSD uses different implementation of CARP than OpenBSD but I had imagine it will be the same protocol from network perspective and just different software implementation.

Later today I will try to disable the flow control on the physical switch as it may be buffering the some traffic.


Edit: Disabled flow control on the 10G switch and got the same result - vrrp packages are getting delayed and then bulk sent.
Check the bold seconds - before file transfer starts there's one heartbeat per second as it's configured - advbase 1.
After the file transfer starts there's a complete mess like skipped seconds and several heartbeats received in the same second.

Code: 
root@fw2:~ # tcpdump -tttt -nni vmx2 proto 112
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on vmx2, link-type EN10MB (Ethernet), capture size 262144 bytes
2020-01-03 10:08:04.766243 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:05.765492 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:06.785927 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:07.786202 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:08.800125 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:09.805299 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:10.823528 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:11.825236 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:12.996672 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:13.844760 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:14.863653 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:15.865945 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:16.880828 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36

#### Few seconds after file transfer starts ####

2020-01-03 10:08:17.884945 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:18.905646 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:20.483309 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:23.798447 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:27.206711 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:27.561834 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:30.966804 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:31.546755 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:34.955966 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:35.367085 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:38.773477 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:42.176571 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:42.466293 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:45.876800 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:46.584314 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:48.391096 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:51.796611 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:53.205881 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:08:53.264616 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:54.783247 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:56.293623 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:57.822585 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:08:59.356932 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:00.068289 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:00.487417 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:03.896605 IP 192.168.10.34 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 100, authtype none, intvl 1s, length 36
2020-01-03 10:09:04.651697 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:04.829863 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:04.942738 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.086878 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.226714 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.332497 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.426059 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.574263 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.653844 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.769504 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:05.882871 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.019708 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.084540 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.164018 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.253936 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.355379 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:06.419226 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:07.390507 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36

#### File transfer end ####

2020-01-03 10:09:08.385399 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:09.402252 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:10.405416 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:11.423105 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:12.425609 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
2020-01-03 10:09:13.445735 IP 192.168.10.33 > 224.0.0.18: VRRPv2, Advertisement, vrid 201, prio 0, authtype none, intvl 1s, length 36
^C
63 packets captured
2352638 packets received by filter

I wonder if this may be caused by other 1Gbit switches connected to the 10G one and possibly flow control enabled there causing pause frames sent to the 10Gbit one.
Looks exactly like a flow control behaviour but it's still a guess.

I don't have the balls to disable flow control everywhere because there's also iSCSI traffic running on these switches. In order to avoid packet loss a flow control is strongly recommended for iSCSI however if flow control is causing CARP issues then what is the right answer? Should we have flow control enabled or not?
 
You must log in or register to reply here.
Back
Top