CARP-based PPPoE failover stops working on 2.7.0
-
I'll do a little more testing tomorrow and see if there are any errors in other logs. I'll also try it without the CARP VIP linkage to try and see if that is related.
-
Here is the system.log for the failed connection with 2.7.0. It looks like something CARP related gets confused and tries to restart ppp just after IPCP LayerUp (timestamp Sep 25 13:38:56) and possibly that disrupts the interface address assignment.
Sep 25 13:38:49 fw2 ppp[27705]: [wan] Bundle: Interface ng0 created Sep 25 13:38:49 fw2 ppp[27705]: [undefined] GetSystemIfaceMTU: SIOCGIFMTU failed: Device not configured Sep 25 13:38:49 fw2 kernel: ng0: changing name to 'pppoe0' Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] Link: OPEN event Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: Open event Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: state change Initial --> Starting Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: LayerStart Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] PPPoE: Set PPP-Max-Payload to '1500' Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] PPPoE: Connecting to '' Sep 25 13:38:55 fw2 ppp[27705]: PPPoE: rec'd ACNAME "acc-aln2.l-bow" Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] PPPoE: rec'd PPP-Max-Payload '1500' Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] PPPoE: connection successful Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] Link: UP event Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: Up event Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: state change Starting --> Req-Sent Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: SendConfigReq #1 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] PROTOCOMP Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MRU 1500 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MAGICNUM 0xa1d771b1 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: rec'd Configure Request #120 (Req-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MRU 1500 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] AUTHPROTO CHAP MD5 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MAGICNUM 0x05723217 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: SendConfigAck #120 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MRU 1500 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] AUTHPROTO CHAP MD5 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MAGICNUM 0x05723217 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] PROTOCOMP Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: SendConfigReq #2 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MRU 1500 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MAGICNUM 0xa1d771b1 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MRU 1500 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MAGICNUM 0xa1d771b1 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: state change Ack-Sent --> Opened Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: LayerUp Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 71 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] Name: "acc-aln2.l-bow" Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] CHAP: Using authname "dr3@a.1" Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] CHAP: sending RESPONSE #1 len: 28 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] CHAP: rec'd SUCCESS #1 len: 33 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] MESG: BBEU05350391 49382000/8935000 Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] LCP: authorization successful Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] Link: Matched action 'bundle "wan" ""' Sep 25 13:38:55 fw2 ppp[27705]: [wan_link0] Link: Join bundle "wan" Sep 25 13:38:55 fw2 ppp[27705]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: Open event Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: state change Initial --> Starting Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: LayerStart Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: Open event Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: state change Initial --> Starting Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: LayerStart Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: Up event Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: state change Starting --> Req-Sent Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: SendConfigReq #1 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 25 13:38:55 fw2 ppp[27705]: [wan] PRIDNS 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] SECDNS 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: Up event Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: state change Starting --> Req-Sent Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: SendConfigReq #1 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: rec'd Configure Request #0 (Req-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 81.187.81.187 Sep 25 13:38:55 fw2 ppp[27705]: [wan] 81.187.81.187 is OK Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: SendConfigAck #0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 81.187.81.187 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: state change Req-Sent --> Ack-Sent Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: SendConfigReq #2 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] PRIDNS 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] SECDNS 0.0.0.0 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 81.187.39.70 Sep 25 13:38:55 fw2 ppp[27705]: [wan] 81.187.39.70 is OK Sep 25 13:38:55 fw2 ppp[27705]: [wan] PRIDNS 217.169.20.21 Sep 25 13:38:55 fw2 ppp[27705]: [wan] SECDNS 217.169.20.20 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: SendConfigReq #3 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 81.187.39.70 Sep 25 13:38:55 fw2 ppp[27705]: [wan] PRIDNS 217.169.20.21 Sep 25 13:38:55 fw2 ppp[27705]: [wan] SECDNS 217.169.20.20 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPADDR 81.187.39.70 Sep 25 13:38:55 fw2 ppp[27705]: [wan] PRIDNS 217.169.20.21 Sep 25 13:38:55 fw2 ppp[27705]: [wan] SECDNS 217.169.20.20 Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: state change Ack-Sent --> Opened Sep 25 13:38:55 fw2 ppp[27705]: [wan] IPCP: LayerUp Sep 25 13:38:55 fw2 ppp[27705]: [wan] 81.187.39.70 -> 81.187.81.187 Sep 25 13:38:56 fw2 php-fpm[43088]: /rc.carpmaster: HA cluster member "(192.168.2.61@vtnet0.101): (PPPOE)" has resumed CARP state "MASTER" for vhid 101 Sep 25 13:38:56 fw2 php-fpm[20502]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:103::1@vtnet0.103): (K8S)" has resumed CARP state "MASTER" for vhid 203 Sep 25 13:38:56 fw2 php-fpm[12868]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:100::1@vtnet0.100): (DMZ)" has resumed CARP state "MASTER" for vhid 200 Sep 25 13:38:57 fw2 php-fpm[53074]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:1::1@vtnet0): (LAN)" has resumed CARP state "MASTER" for vhid 2 Sep 25 13:38:57 fw2 php-fpm[374]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:42::1@vtnet0.42): (HOME)" has resumed CARP state "MASTER" for vhid 142 Sep 25 13:38:58 fw2 php-fpm[25844]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:102::1@vtnet0.102): (IPMI)" has resumed CARP state "MASTER" for vhid 202 Sep 25 13:38:59 fw2 check_reload_status[411]: Rewriting resolv.conf Sep 25 13:38:59 fw2 php-fpm[34140]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:255::1@vtnet0.255): (IOT)" has resumed CARP state "MASTER" for vhid 155 Sep 25 13:38:59 fw2 ppp[65014]: Multi-link PPP daemon for FreeBSD Sep 25 13:38:59 fw2 ppp[65014]: Sep 25 13:38:59 fw2 ppp[65014]: process 65014 started, version 5.9 Sep 25 13:38:59 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:00 fw2 check_reload_status[411]: rc.newwanip starting pppoe0 Sep 25 13:39:00 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:01 fw2 ppp[27705]: [wan] IFACE: Up event Sep 25 13:39:01 fw2 ppp[27705]: [wan] IFACE: Rename interface ng0 to pppoe0 Sep 25 13:39:01 fw2 ppp[27705]: [wan] IFACE: Add description "WAN" Sep 25 13:39:01 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd) Sep 25 13:39:01 fw2 ppp[27705]: [wan] IPV6CP: SendConfigAck #0 Sep 25 13:39:01 fw2 ppp[27705]: [wan] IPV6CP: state change Ack-Rcvd --> Opened Sep 25 13:39:01 fw2 ppp[27705]: [wan] IPV6CP: LayerUp Sep 25 13:39:01 fw2 ppp[27705]: [wan] 5a9c:fcff:fe0a:c5b1 -> 0203:97ff:feba:0800 Sep 25 13:39:01 fw2 php-fpm[20502]: /rc.carpmaster: Starting radvd instance on K8S because of transition to CARP master. Sep 25 13:39:01 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:01 fw2 php-fpm[12868]: /rc.newwanip: rc.newwanip: Info: starting on pppoe0. Sep 25 13:39:02 fw2 php-fpm[53074]: /rc.carpmaster: Starting radvd instance on LAN because of transition to CARP master. Sep 25 13:39:02 fw2 php-fpm[12868]: /rc.newwanip: rc.newwanip: on (IP address: 81.187.39.70) (interface: WAN[wan]) (real interface: pppoe0). Sep 25 13:39:02 fw2 pkg-static[75525]: dhcpleases6-0.1_3 deinstalled Sep 25 13:39:02 fw2 php-fpm[374]: /rc.carpmaster: Starting radvd instance on HOME because of transition to CARP master. Sep 25 13:39:02 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:02 fw2 kernel: done. Sep 25 13:39:03 fw2 php[88915]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 Sep 25 13:39:03 fw2 kernel: done. Sep 25 13:39:03 fw2 php[88915]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode Sep 25 13:39:03 fw2 php[88915]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0) Sep 25 13:39:03 fw2 php-fpm[25844]: /rc.start_packages: Restarting/Starting all packages. Sep 25 13:39:03 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:03 fw2 root[17126]: Bootup complete Sep 25 13:39:04 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:05 fw2 login[43514]: login on ttyu0 as root Sep 25 13:39:05 fw2 sshguard[45316]: Now monitoring attacks. Sep 25 13:39:05 fw2 php-fpm[34140]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Sep 25 13:39:05 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:05 fw2 php-fpm[34140]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:8b0:1111:1111:0:ffff:51bb:2746) (interface: wan) (real interface: pppoe0). Sep 25 13:39:06 fw2 php-fpm[34140]: /rc.newwanipv6: Removing static route for monitor 2001:8b0:0:81::51bb:51bb and adding a new route through fe80::203:97ff:feba:800%pppoe0 Sep 25 13:39:06 fw2 check_reload_status[411]: Rewriting resolv.conf Sep 25 13:39:06 fw2 php-fpm[12868]: /rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default. Sep 25 13:39:06 fw2 rtsold[58316]: Received RA specifying route fe80::203:97ff:feba:800 for interface wan(pppoe0) Sep 25 13:39:06 fw2 rtsold[59374]: RTSOLD Lock in place - sending SIGHUP to dhcp6c Sep 25 13:39:06 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:07 fw2 php-fpm[12868]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Sep 25 13:39:07 fw2 check_reload_status[411]: rc.newwanipv6 starting pppoe0 Sep 25 13:39:07 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Request #0 (Opened) Sep 25 13:39:07 fw2 ppp[27705]: [wan] IPV6CP: LayerDown Sep 25 13:39:07 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:08 fw2 php-fpm[375]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Sep 25 13:39:08 fw2 php-fpm[375]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:8b0:1111:1111:0:ffff:51bb:2746) (interface: wan) (real interface: pppoe0). Sep 25 13:39:08 fw2 php-fpm[375]: /rc.newwanipv6: Removing static route for monitor 2001:8b0:0:81::51bb:51bb and adding a new route through fe80::203:97ff:feba:800%pppoe0 Sep 25 13:39:08 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:09 fw2 check_reload_status[411]: Reloading filter Sep 25 13:39:09 fw2 php-fpm[34140]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Sep 25 13:39:09 fw2 check_reload_status[411]: Reloading filter Sep 25 13:39:09 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:09 fw2 php-fpm[375]: /rc.newwanipv6: The command '/usr/local/bin/dpinger -S -r 0 -i WAN_DHCP6 -B 2001:8b0:1111:1111:0:ffff:51bb:2746 -p /var/run/dpinger_WAN_DHCP6~2001:8b0:1111:1111:0:ffff:51bb:2746~2001:8b0:0:81::51bb:51bb.pid -u /var/run/dpinger_WAN_DHCP6~2001:8b0:1111:1111:0:ffff:51bb:2746~2001:8b0:0:81::51bb:51bb.sock -C "/etc/rc.gateway_alarm" -d 1 -s 500 -l 2000 -t 60000 -A 1000 -D 500 -L 20 2001:8b0:0:81::51bb:51bb >/dev/null' returned exit code '1', the output was '' Sep 25 13:39:09 fw2 php-fpm[375]: /rc.newwanipv6: Error starting gateway monitor for WAN_DHCP6 Sep 25 13:39:10 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:10 fw2 check_reload_status[411]: Reloading filter Sep 25 13:39:10 fw2 php-fpm[375]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Sep 25 13:39:11 fw2 php-fpm[12868]: OpenVPN terminate old pid: 60552 Sep 25 13:39:11 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:12 fw2 ppp[65014]: waiting for process 27705 to die... Sep 25 13:39:13 fw2 kernel: ovpns1: link state changed to DOWN Sep 25 13:39:13 fw2 check_reload_status[411]: Rewriting resolv.conf Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: SendConfigReq #2 Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: SendConfigAck #0 Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: state change Opened --> Ack-Sent Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Sent) Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: SendConfigAck #0 Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Sent) Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: SendConfigAck #0 Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Sent) Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: SendConfigAck #0 Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: rec'd Configure Ack #2 (Ack-Sent) Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: state change Ack-Sent --> Opened Sep 25 13:39:13 fw2 ppp[27705]: [wan] IPV6CP: LayerUp Sep 25 13:39:13 fw2 ppp[27705]: [wan] 5a9c:fcff:fe0a:c5b1 -> 0203:97ff:feba:0800 Sep 25 13:39:13 fw2 php[3958]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 Sep 25 13:39:13 fw2 php[3958]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode Sep 25 13:39:13 fw2 php[3958]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0) Sep 25 13:39:13 fw2 ppp[65014]: waiting for process 27705 to die... -
Hmm, yeah something is out of order there.
With the PPPoE link using the CARP VIP as it's parent I don't expect it to be able to connect at all until the node becomes master for that VIP. Do you see that in the logs?
It's also odd that the new process is spawned when it does become master but for some reason it fails to kill the existing process.
-
I snipped out that part of the log, Here is the section before the PPP link starts to come up. It seems to show a little confusion on whether or not we are backup or master?
Sep 25 13:38:42 fw2 php-cgi[428]: rc.bootup: Creating rrd update script Sep 25 13:38:42 fw2 syslogd: exiting on signal 15 Sep 25 13:38:42 fw2 syslogd: kernel boot file is /boot/kernel/kernel Sep 25 13:38:42 fw2 kernel: done. Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 kernel: carp: 2@vtnet0: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 2880 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 200@vtnet0.100: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 2640 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 100@vtnet0.100: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 2400 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 142@vtnet0.42: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 2160 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 42@vtnet0.42: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 1920 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 101@vtnet0.101: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 1680 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 202@vtnet0.102: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 1440 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 102@vtnet0.102: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 1200 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 155@vtnet0.255: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 960 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 255@vtnet0.255: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 720 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 1@vtnet0: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 480 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 103@vtnet0.103: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 240 (interface up) Sep 25 13:38:42 fw2 kernel: carp: 203@vtnet0.103: INIT -> BACKUP (initialization complete) Sep 25 13:38:42 fw2 kernel: carp: demoted by -240 to 0 (interface up) Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Carp backup event Sep 25 13:38:42 fw2 check_reload_status[411]: Reloading filter Sep 25 13:38:43 fw2 kernel: done. Sep 25 13:38:43 fw2 php-fpm[374]: /rc.carpbackup: HA cluster member "(2001:8b0:ffec:100::1@vtnet0.100): (DMZ)" has resumed CARP state "BACKUP" for vhid 200 Sep 25 13:38:44 fw2 kernel: carp: 100@vtnet0.100: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: arp: 81.2.119.145 moved from 00:00:5e:00:01:64 to 58:9c:fc:00:a2:f7 on vtnet0.100 Sep 25 13:38:44 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:43 fw2 php-fpm[375]: /rc.carpbackup: HA cluster member "(2001:8b0:ffec:1::1@vtnet0): (LAN)" has resumed CARP state "BACKUP" for vhid 2 Sep 25 13:38:44 fw2 php-fpm[375]: /rc.carpbackup: Stopping radvd instance on LAN because of transition to CARP backup. Sep 25 13:38:44 fw2 kernel: carp: 255@vtnet0.255: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 1@vtnet0: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 103@vtnet0.103: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 42@vtnet0.42: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 102@vtnet0.102: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 101@vtnet0.101: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 203@vtnet0.103: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 2@vtnet0: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 200@vtnet0.100: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 142@vtnet0.42: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 202@vtnet0.102: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 kernel: carp: 155@vtnet0.255: BACKUP -> MASTER (preempting a slower master) Sep 25 13:38:44 fw2 php-fpm[12868]: /rc.carpbackup: HA cluster member "(81.2.119.145@vtnet0.100): (DMZ)" has resumed CARP state "BACKUP" for vhid 100 Sep 25 13:38:44 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:44 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:44 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 check_reload_status[411]: Carp master event Sep 25 13:38:45 fw2 php-fpm[374]: /rc.carpbackup: HA cluster member "(2001:8b0:ffec:42::1@vtnet0.42): (HOME)" has resumed CARP state "BACKUP" for vhid 142 Sep 25 13:38:45 fw2 php-fpm[20502]: /rc.carpbackup: HA cluster member "(192.168.2.61@vtnet0.101): (PPPOE)" has resumed CARP state "BACKUP" for vhid 101 Sep 25 13:38:46 fw2 php-fpm[25844]: /rc.carpbackup: HA cluster member "(192.168.42.1@vtnet0.42): (HOME)" has resumed CARP state "BACKUP" for vhid 42 Sep 25 13:38:47 fw2 php-fpm[375]: /rc.carpbackup: HA cluster member "(2001:8b0:ffec:102::1@vtnet0.102): (IPMI)" has resumed CARP state "BACKUP" for vhid 202 Sep 25 13:38:47 fw2 ppp[27705]: Multi-link PPP daemon for FreeBSD Sep 25 13:38:47 fw2 ppp[27705]: Sep 25 13:38:47 fw2 ppp[27705]: process 27705 started, version 5.9 Sep 25 13:38:47 fw2 ppp[25754]: caught fatal signal TERM Sep 25 13:38:47 fw2 ppp[25754]: [wan] IFACE: Close event Sep 25 13:38:47 fw2 ppp[25754]: [wan] IPCP: Close event Sep 25 13:38:47 fw2 ppp[25754]: [wan] IPV6CP: Close event Sep 25 13:38:47 fw2 ppp[27705]: waiting for process 25754 to die... Sep 25 13:38:47 fw2 php-fpm[34140]: /rc.carpbackup: HA cluster member "(2001:8b0:ffec:255::1@vtnet0.255): (IOT)" has resumed CARP state "BACKUP" for vhid 155 Sep 25 13:38:48 fw2 php-fpm[12868]: /rc.carpbackup: HA cluster member "(192.168.102.1@vtnet0.102): (IPMI)" has resumed CARP state "BACKUP" for vhid 102 Sep 25 13:38:48 fw2 ppp[27705]: waiting for process 25754 to die... Sep 25 13:38:48 fw2 php-fpm[43088]: /rc.carpbackup: HA cluster member "(192.168.1.1@vtnet0): (LAN)" has resumed CARP state "BACKUP" for vhid 1 Sep 25 13:38:49 fw2 ppp[25754]: [wan] Bundle: Shutdown Sep 25 13:38:49 fw2 ppp[25754]: process 25754 terminated Sep 25 13:38:49 fw2 php-fpm[374]: /rc.carpbackup: Stopping radvd instance on HOME because of transition to CARP backup. Sep 25 13:38:49 fw2 ppp[27705]: web: web is not running Sep 25 13:38:49 fw2 ppp[27705]: [wan] Bundle: Interface ng0 created Sep 25 13:38:49 fw2 ppp[27705]: [undefined] GetSystemIfaceMTU: SIOCGIFMTU failed: Device not configured Sep 25 13:38:49 fw2 kernel: ng0: changing name to 'pppoe0' Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] Link: OPEN event Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: Open event Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: state change Initial --> Starting Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] LCP: LayerStart Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] PPPoE: Set PPP-Max-Payload to '1500' Sep 25 13:38:49 fw2 ppp[27705]: [wan_link0] PPPoE: Connecting to '' -
Mmm, what exactly happened to trigger that? It looks like it just rebooted?
You can see when it goes master it triggers a new mpd process and the first thing that does is kill the old process which correctly dies.
It looks like that CARP then flaps and a third process is triggered but it fails to kill the second one. Which interface is the PPPoE on?
-
The backup firewall VM is being rebooted after I upgraded it to 2.7.0. The primary firewall was in 'persistent carp maintenance mode' which meant that it took over as master during the reboot but gave it up again as soon as the secondary came out of INIT state - I think this is the 'preempting a slower master' part.
-
The PPPoE link is on vtnet0.101 and is using the 192.168.2.61 VIP as its interface.
-
Hmm, that could be an edge case. Does it do that at a normal failover?
-
I think so but I don't have the logs. I'll repeat the experiment but this time giving the secondary a while to settle after booting before putting the primary into maintenance.
-
That time, the link came up cleanly after the primary went into maintenance mode and the logs don't show any bouncing. This is a lot better than before but still confusing.
Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 kernel: carp: 255@vtnet0.255: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 1@vtnet0: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 kernel: carp: 100@vtnet0.100: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 142@vtnet0.42: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 42@vtnet0.42: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 102@vtnet0.102: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 103@vtnet0.103: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 202@vtnet0.102: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 2@vtnet0: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 203@vtnet0.103: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 155@vtnet0.255: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 kernel: carp: 200@vtnet0.100: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:28 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:29 fw2 kernel: carp: 101@vtnet0.101: BACKUP -> MASTER (preempting a slower master) Sep 26 15:19:29 fw2 php-fpm[17757]: /rc.carpmaster: HA cluster member "(192.168.255.1@vtnet0.255): (IOT)" has resumed CARP state "MASTER" for vhid 255 Sep 26 15:19:29 fw2 check_reload_status[408]: Carp master event Sep 26 15:19:29 fw2 php-fpm[49713]: /rc.carpmaster: HA cluster member "(192.168.1.1@vtnet0): (LAN)" has resumed CARP state "MASTER" for vhid 1 Sep 26 15:19:29 fw2 php-fpm[372]: /rc.carpmaster: HA cluster member "(81.2.119.145@vtnet0.100): (DMZ)" has resumed CARP state "MASTER" for vhid 100 Sep 26 15:19:30 fw2 php-fpm[27026]: /rc.carpmaster: HA cluster member "(192.168.42.1@vtnet0.42): (HOME)" has resumed CARP state "MASTER" for vhid 42 Sep 26 15:19:30 fw2 php-fpm[12314]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:42::1@vtnet0.42): (HOME)" has resumed CARP state "MASTER" for vhid 142 Sep 26 15:19:31 fw2 php-fpm[37486]: /rc.carpmaster: HA cluster member "(192.168.103.1@vtnet0.103): (K8S)" has resumed CARP state "MASTER" for vhid 103 Sep 26 15:19:31 fw2 php-fpm[63034]: /rc.carpmaster: HA cluster member "(192.168.102.1@vtnet0.102): (IPMI)" has resumed CARP state "MASTER" for vhid 102 Sep 26 15:19:31 fw2 php-fpm[20072]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:1::1@vtnet0): (LAN)" has resumed CARP state "MASTER" for vhid 2 Sep 26 15:19:32 fw2 php-fpm[49713]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:102::1@vtnet0.102): (IPMI)" has resumed CARP state "MASTER" for vhid 202 Sep 26 15:19:32 fw2 php-fpm[372]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:103::1@vtnet0.103): (K8S)" has resumed CARP state "MASTER" for vhid 203 Sep 26 15:19:32 fw2 php-fpm[27026]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:100::1@vtnet0.100): (DMZ)" has resumed CARP state "MASTER" for vhid 200 Sep 26 15:19:32 fw2 php-fpm[12314]: /rc.carpmaster: Starting radvd instance on HOME because of transition to CARP master. Sep 26 15:19:32 fw2 php-fpm[63034]: /rc.carpmaster: HA cluster member "(2001:8b0:ffec:255::1@vtnet0.255): (IOT)" has resumed CARP state "MASTER" for vhid 155 Sep 26 15:19:32 fw2 php-fpm[37486]: /rc.carpmaster: HA cluster member "(192.168.2.61@vtnet0.101): (PPPOE)" has resumed CARP state "MASTER" for vhid 101 Sep 26 15:19:36 fw2 ppp[44965]: Multi-link PPP daemon for FreeBSD Sep 26 15:19:36 fw2 ppp[44965]: Sep 26 15:19:36 fw2 ppp[44965]: process 44965 started, version 5.9 Sep 26 15:19:36 fw2 ppp[22264]: caught fatal signal TERM Sep 26 15:19:36 fw2 ppp[22264]: [wan] IFACE: Close event Sep 26 15:19:36 fw2 ppp[22264]: [wan] IPCP: Close event Sep 26 15:19:36 fw2 ppp[22264]: [wan] IPV6CP: Close event Sep 26 15:19:36 fw2 ppp[44965]: waiting for process 22264 to die... Sep 26 15:19:36 fw2 php-fpm[20072]: /rc.carpmaster: Starting radvd instance on LAN because of transition to CARP master. Sep 26 15:19:37 fw2 php-fpm[372]: /rc.carpmaster: Starting radvd instance on K8S because of transition to CARP master. Sep 26 15:19:37 fw2 ppp[44965]: waiting for process 22264 to die... Sep 26 15:19:38 fw2 ppp[22264]: [wan] Bundle: Shutdown Sep 26 15:19:38 fw2 ppp[22264]: process 22264 terminated Sep 26 15:19:38 fw2 ppp[44965]: web: web is not running Sep 26 15:19:38 fw2 ppp[44965]: [wan] Bundle: Interface ng0 created Sep 26 15:19:38 fw2 ppp[44965]: [undefined] GetSystemIfaceMTU: SIOCGIFMTU failed: Device not configured Sep 26 15:19:38 fw2 kernel: ng0: changing name to 'pppoe0' Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] Link: OPEN event Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] LCP: Open event Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] LCP: state change Initial --> Starting Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] LCP: LayerStart Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] PPPoE: Set PPP-Max-Payload to '1500' Sep 26 15:19:38 fw2 ppp[44965]: [wan_link0] PPPoE: Connecting to '' Sep 26 15:19:40 fw2 ppp[44965]: PPPoE: rec'd ACNAME "acc-aln2.l-bow" Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] PPPoE: rec'd PPP-Max-Payload '1500' Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] PPPoE: connection successful Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] Link: UP event Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: Up event Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: state change Starting --> Req-Sent Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: SendConfigReq #1 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] PROTOCOMP Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MRU 1500 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MAGICNUM 0x4afb096d Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: rec'd Configure Request #83 (Req-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MRU 1500 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] AUTHPROTO CHAP MD5 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MAGICNUM 0x1fd59af9 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: SendConfigAck #83 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MRU 1500 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] AUTHPROTO CHAP MD5 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MAGICNUM 0x1fd59af9 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: state change Req-Sent --> Ack-Sent Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] PROTOCOMP Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: SendConfigReq #2 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MRU 1500 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MAGICNUM 0x4afb096d Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MRU 1500 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MAGICNUM 0x4afb096d Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: state change Ack-Sent --> Opened Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: auth: peer wants CHAP, I want nothing Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: LayerUp Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 79 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] Name: "acc-aln2.l-bow" Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] CHAP: Using authname "dr3@a.1" Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] CHAP: sending RESPONSE #1 len: 28 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] CHAP: rec'd SUCCESS #1 len: 33 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] MESG: BBEU05350391 49382000/8935000 Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] LCP: authorization successful Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] Link: Matched action 'bundle "wan" ""' Sep 26 15:19:40 fw2 ppp[44965]: [wan_link0] Link: Join bundle "wan" Sep 26 15:19:40 fw2 ppp[44965]: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: Open event Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: state change Initial --> Starting Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: LayerStart Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: Open event Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: state change Initial --> Starting Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: LayerStart Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: Up event Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: state change Starting --> Req-Sent Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: SendConfigReq #1 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 26 15:19:40 fw2 ppp[44965]: [wan] PRIDNS 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] SECDNS 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: Up event Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: state change Starting --> Req-Sent Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: SendConfigReq #1 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: rec'd Configure Request #0 (Req-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 81.187.81.187 Sep 26 15:19:40 fw2 ppp[44965]: [wan] 81.187.81.187 is OK Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: SendConfigAck #0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 81.187.81.187 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: state change Req-Sent --> Ack-Sent Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: SendConfigReq #2 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] PRIDNS 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] SECDNS 0.0.0.0 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPV6CP: state change Req-Sent --> Ack-Rcvd Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 81.187.39.70 Sep 26 15:19:40 fw2 ppp[44965]: [wan] 81.187.39.70 is OK Sep 26 15:19:40 fw2 ppp[44965]: [wan] PRIDNS 217.169.20.21 Sep 26 15:19:40 fw2 ppp[44965]: [wan] SECDNS 217.169.20.20 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: SendConfigReq #3 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 81.187.39.70 Sep 26 15:19:40 fw2 ppp[44965]: [wan] PRIDNS 217.169.20.21 Sep 26 15:19:40 fw2 ppp[44965]: [wan] SECDNS 217.169.20.20 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent) Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPADDR 81.187.39.70 Sep 26 15:19:40 fw2 ppp[44965]: [wan] PRIDNS 217.169.20.21 Sep 26 15:19:40 fw2 ppp[44965]: [wan] SECDNS 217.169.20.20 Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: state change Ack-Sent --> Opened Sep 26 15:19:40 fw2 ppp[44965]: [wan] IPCP: LayerUp Sep 26 15:19:40 fw2 ppp[44965]: [wan] 81.187.39.70 -> 81.187.81.187 Sep 26 15:19:40 fw2 check_reload_status[408]: Rewriting resolv.conf Sep 26 15:19:41 fw2 check_reload_status[408]: rc.newwanip starting pppoe0 Sep 26 15:19:41 fw2 ppp[44965]: [wan] IFACE: Up event Sep 26 15:19:41 fw2 ppp[44965]: [wan] IFACE: Rename interface ng0 to pppoe0 Sep 26 15:19:41 fw2 ppp[44965]: [wan] IFACE: Add description "WAN" Sep 26 15:19:41 fw2 ppp[44965]: [wan] IPV6CP: rec'd Configure Request #0 (Ack-Rcvd) Sep 26 15:19:41 fw2 ppp[44965]: [wan] IPV6CP: SendConfigAck #0 Sep 26 15:19:41 fw2 ppp[44965]: [wan] IPV6CP: state change Ack-Rcvd --> Opened Sep 26 15:19:41 fw2 ppp[44965]: [wan] IPV6CP: LayerUp Sep 26 15:19:41 fw2 ppp[44965]: [wan] 5a9c:fcff:fe0a:c5b1 -> 0203:97ff:feba:0800 Sep 26 15:19:42 fw2 php[68418]: /usr/local/sbin/ppp-ipv6: Accept router advertisements on interface pppoe0 Sep 26 15:19:42 fw2 php[68418]: /usr/local/sbin/ppp-ipv6: Starting DHCP6 client for interfaces pppoe0 in DHCP6 without RA mode Sep 26 15:19:42 fw2 php[68418]: /usr/local/sbin/ppp-ipv6: Starting rtsold process on wan(pppoe0) Sep 26 15:19:42 fw2 kernel: nd6_dad_timer: called with non-tentative address fe80:f::5a9c:fcff:fe0a:c5b1(pppoe0) Sep 26 15:19:43 fw2 php-fpm[12314]: /rc.newwanip: rc.newwanip: Info: starting on pppoe0. Sep 26 15:19:43 fw2 php-fpm[12314]: /rc.newwanip: rc.newwanip: on (IP address: 81.187.39.70) (interface: WAN[wan]) (real interface: pppoe0). Sep 26 15:19:44 fw2 check_reload_status[408]: Rewriting resolv.conf Sep 26 15:19:44 fw2 php-fpm[17757]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Sep 26 15:19:44 fw2 php-fpm[17757]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:8b0:1111:1111:0:ffff:51bb:2746) (interface: wan) (real interface: pppoe0). Sep 26 15:19:44 fw2 php-fpm[17757]: /rc.newwanipv6: Removing static route for monitor 2001:8b0:0:81::51bb:51bb and adding a new route through fe80::203:97ff:feba:800%pppoe0 Sep 26 15:19:44 fw2 rtsold[9406]: Received RA specifying route fe80::203:97ff:feba:800 for interface wan(pppoe0) Sep 26 15:19:44 fw2 rtsold[9675]: RTSOLD Lock in place - sending SIGHUP to dhcp6c Sep 26 15:19:45 fw2 php-fpm[12314]: /rc.newwanip: Default gateway setting Interface WAN_PPPOE Gateway as default. Sep 26 15:19:45 fw2 php-fpm[12314]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN. Sep 26 15:19:45 fw2 check_reload_status[408]: rc.newwanipv6 starting pppoe0 Sep 26 15:19:45 fw2 php-fpm[12314]: OpenVPN terminate old pid: 58210 Sep 26 15:19:46 fw2 check_reload_status[408]: Reloading filter Sep 26 15:19:46 fw2 php-fpm[17757]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Sep 26 15:19:46 fw2 check_reload_status[408]: Reloading filter Sep 26 15:19:46 fw2 php-fpm[27026]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Sep 26 15:19:46 fw2 php-fpm[27026]: /rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan]. Sep 26 15:19:47 fw2 php-fpm[63034]: /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe0. Sep 26 15:19:47 fw2 php-fpm[63034]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2001:8b0:1111:1111:0:ffff:51bb:2746) (interface: wan) (real interface: pppoe0). Sep 26 15:19:47 fw2 php-fpm[63034]: /rc.newwanipv6: Removing static route for monitor 2001:8b0:0:81::51bb:51bb and adding a new route through fe80::203:97ff:feba:800%pppoe0 -
Hmm, so this could be an edge case that happens after upgrade. It would be interesting to confirm if that happens with the primary in maintenance mode and you reboot the secondary when it's not upgrading. Or if you upgrade without the primary in maintenance mode as would normally be the case. Though that's obviously more difficult to test.
-
I'm wondering if this is related to this comment in the 2.7.0 release nodes:
Fixed: CARP event storm when leaving persistent CARP maintenance mode #12961Perhaps this issue is being triggered from my test having a 2.6.0 peer in the HA setup. I think I need to test with both primary and secondary on 2.7.0 but I'm afraid that will have to wait until week after next.
-
If the other node is not running the same version then config sync will be disabled. But state sync would still be enabled. And the CARP status doesn't care about the version.
It could be related that bug, though I don't see the same flood of CARP events that triggered.
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.