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