Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    CARP-based PPPoE failover stops working on 2.7.0

    Scheduled Pinned Locked Moved General pfSense Questions
    18 Posts 2 Posters 1.8k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • stephenw10S
      stephenw10 Netgate Administrator
      last edited by

      Hmm, interesting. No errors in the system, routing or gateway logs when it does that?

      I can only imagine an ifconfig command failing and I'd expect to see an error from that.

      1 Reply Last reply Reply Quote 0
      • D
        dougrabson
        last edited by

        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.

        1 Reply Last reply Reply Quote 1
        • D
          dougrabson
          last edited by

          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...
          1 Reply Last reply Reply Quote 0
          • stephenw10S
            stephenw10 Netgate Administrator
            last edited by

            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.

            1 Reply Last reply Reply Quote 0
            • D
              dougrabson
              last edited by

              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 ''
              1 Reply Last reply Reply Quote 0
              • stephenw10S
                stephenw10 Netgate Administrator
                last edited by

                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?

                1 Reply Last reply Reply Quote 0
                • D
                  dougrabson
                  last edited by

                  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.

                  1 Reply Last reply Reply Quote 0
                  • D
                    dougrabson
                    last edited by

                    The PPPoE link is on vtnet0.101 and is using the 192.168.2.61 VIP as its interface.

                    1 Reply Last reply Reply Quote 0
                    • stephenw10S
                      stephenw10 Netgate Administrator
                      last edited by

                      Hmm, that could be an edge case. Does it do that at a normal failover?

                      1 Reply Last reply Reply Quote 0
                      • D
                        dougrabson
                        last edited by

                        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.

                        1 Reply Last reply Reply Quote 1
                        • D
                          dougrabson
                          last edited by

                          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
                          1 Reply Last reply Reply Quote 0
                          • stephenw10S
                            stephenw10 Netgate Administrator
                            last edited by

                            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.

                            1 Reply Last reply Reply Quote 0
                            • D
                              dougrabson
                              last edited by

                              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 #12961

                              Perhaps 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.

                              1 Reply Last reply Reply Quote 0
                              • stephenw10S
                                stephenw10 Netgate Administrator
                                last edited by

                                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.

                                1 Reply Last reply Reply Quote 0
                                • First post
                                  Last post
                                Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.