2.7.0 PPPoE Continually Reconnecting

sanstey

This PPPoE + VIP issue is still present in 2.7.2/23.09.1. Until this issue is resolved, I'm stuck on 22.05 with no security patches. It's really unfortunate this isn't a higher priority issue.

stephenw10

Do you have a system log showing this happening? I though we had one here to reference but I'm not finding it now.

sanstey

@stephenw10 I've attached a redacted version of my system.log file showing this.
"207.[REDACTED]" is the initial IP address my firewall receives before it applies one of my static IPs, which is "168.[REDACTED]."
Let me know if you need anything else!
system.log_redacted.txt

stephenw10

Thanks!

MrPete

@stephenw10 Any progress on this? I just looped back to update from 2.6 to 2.7.0 and have the exact same symptoms.

I now have 2.6 on my carp main and 2.7.0 on carp backup, so pretty easy to run tests if there's something you need. :)
(FWIW, we connect to CenturyLink, so the WAN PPPoE uses VLAN 201 -- thus this is not related to the VLAN=0 issue)

stephenw10

Specifically the PPPoE with a VIP issue?

MrPete

@stephenw10 yep. Continual PPPoE restarts...
I just did a smart diff of a good and bad log. FWIW...
(I've obfuscated private data. All obfuscations begin and end with "|", which is not found in the log.)

A) This part's identical

[wan] Bundle: Interface ng0 created
[wan_link0] Link: OPEN event
[wan_link0] LCP: Open event
[wan_link0] LCP: state change Initial --> Starting
[wan_link0] LCP: LayerStart
[wan_link0] PPPoE: Connecting to ''

B) This part is then seen in 2.6 (good connect) (BAD connect has a ~50 sec delay here)

PPPoE: rec'd ACNAME "||local ISP dom.ain||"
[wan_link0] PPPoE: connection successful
[wan_link0] Link: UP event
[wan_link0] LCP: Up event
[wan_link0] LCP: state change Starting --> Req-Sent
[wan_link0] LCP: SendConfigReq #1
[wan_link0]   PROTOCOMP
[wan_link0]   MRU 1492
[wan_link0]   MAGICNUM 0x4c18d9e4
[wan_link0] LCP: rec'd Configure Request #37 (Req-Sent)
[wan_link0]   MRU 1492
[wan_link0]   AUTHPROTO CHAP MD5
[wan_link0]   MAGICNUM 0x48bb2420
[wan_link0] LCP: SendConfigAck #37
[wan_link0]   MRU 1492
[wan_link0]   AUTHPROTO CHAP MD5
[wan_link0]   MAGICNUM 0x48bb2420
[wan_link0] LCP: state change Req-Sent --> Ack-Sent
[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
[wan_link0]   PROTOCOMP
[wan_link0]   MRU 1492
[wan_link0]   MAGICNUM 0x||32 bit hex||
[wan_link0] LCP: state change Ack-Sent --> Opened
[wan_link0] LCP: auth: peer wants CHAP, I want nothing
[wan_link0] LCP: LayerUp
[wan_link0] CHAP: rec'd CHALLENGE #159 len: 41
[wan_link0]   Name: "JUNOS"
[wan_link0] CHAP: Using authname "||user@dom.ain auth||"
[wan_link0] CHAP: sending RESPONSE #159 len: 46
[wan_link0] CHAP: rec'd SUCCESS #159 len: 4
[wan_link0] LCP: authorization successful
[wan_link0] Link: Matched action 'bundle "wan" ""'
[wan_link0] Link: Join bundle "wan"
[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
[wan] IPCP: Open event
[wan] IPCP: state change Initial --> Starting
[wan] IPCP: LayerStart
[wan] IPCP: Up event
[wan] IPCP: state change Starting --> Req-Sent
[wan] IPCP: SendConfigReq #1
[wan]   IPADDR 0.0.0.0
[wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
[wan] IPCP: rec'd Configure Request #177 (Req-Sent)
[wan]   IPADDR ||ip.v.4.addr||
[wan]     ||ip.v.4.addr|| is OK
[wan] IPCP: SendConfigAck #177
[wan]   IPADDR ||ip.v.4.addr||
[wan] IPCP: state change Req-Sent --> Ack-Sent
[wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
[wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid

C) This part is seen in both (next)

[wan] IPCP: SendConfigReq #2
[wan]   IPADDR 0.0.0.0
[wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
[wan]   IPADDR ||my.static.ipv4.wan||
[wan]     ||my.static.ipv4.wan|| is OK
[wan] IPCP: SendConfigReq #3
[wan]   IPADDR ||my.static.ipv4.wan||
[wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
[wan]   IPADDR ||my.static.ipv4.wan||
[wan] IPCP: state change Ack-Sent --> Opened
[wan] IPCP: LayerUp
[wan]   ||my.static.ipv4.wan|| -> ||ip.v.4.addr||
[wan] IFACE: Up event
[wan] IFACE: Rename interface ng0 to pppoe0
[wan] IFACE: Add description "WAN"

D) This final part is only in 2.7 bad...

Multi-link PPP daemon for FreeBSD

process 98989 started, version 5.9
waiting for process 82135 to die...
caught fatal signal TERM
[wan] IFACE: Close event
[wan] IPCP: Close event
[wan] IPCP: state change Opened --> Closing
[wan] IPCP: SendTerminateReq #4
[wan] IPCP: LayerDown
[wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
[wan] IFACE: Down event
[wan] IFACE: Rename interface pppoe0 to pppoe0
[wan] IFACE: Set description "WAN"
[wan] IPCP: rec'd Terminate Ack #4 (Closing)
[wan] IPCP: state change Closing --> Closed
[wan] IPCP: LayerFinish
[wan] Bundle: No NCPs left. Closing links...
[wan] Bundle: closing link "wan_link0"...
[wan_link0] LCP: rec'd Terminate Request #28 (Opened)
[wan_link0] LCP: state change Opened --> Stopping
[wan_link0] Link: Leave bundle "wan"
[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
[wan] IPCP: Close event
[wan] IPCP: Down event
[wan] IPCP: state change Closed --> Initial
[wan_link0] LCP: SendTerminateAck #2
[wan_link0] LCP: LayerDown
[wan_link0] PPPoE: connection closed
[wan_link0] Link: DOWN event
[wan_link0] Link: giving up after 0 reconnection attempts
[wan_link0] LCP: Close event
[wan_link0] LCP: state change Stopping --> Closing
[wan_link0] LCP: Down event
[wan_link0] LCP: LayerFinish
[wan_link0] LCP: state change Closing --> Initial
[wan_link0] Link: CLOSE event
[wan_link0] LCP: Close event
waiting for process 82135 to die...
waiting for process 82135 to die...
[wan] Bundle: Shutdown
[wan_link0] Link: Shutdown
process 82135 terminated
web: web is not running

Then it immediately does another loop.

Perhaps a red herring, but the result of identical config on vtnet0 shows two differences between 2.6 and 2.7:

2.7 has flag LOWER_UP
2.7 has media "Ethernet autoselect"

Good 2.6

vtnet0: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=900b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,VLAN_HWFILTER,LINKSTATE>
        ether ||my:ma:ca:dd:re:ss||
        inet6 ||local fe80 ip6||%vtnet0 prefixlen 64 scopeid 0x1
        media: Ethernet 10Gbase-T <full-duplex>
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>

"Bad" 2.7

vtnet0: flags=1008943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST,LOWER_UP> metric 0 mtu 1500
        options=900b8<VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,VLAN_HWFILTER,LINKSTATE>
        ether ||my:ma:ca:dd:re:ss||
        inet6 ||local fe80 ip6||%vtnet0 prefixlen 64 scopeid 0x1
        media: Ethernet autoselect (10Gbase-T <full-duplex>)
        status: active
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>

stephenw10

Mmm, OK. Nothing I'm aware of. Let me see if anyone has anything internally...

stephenw10

Seems to be fixed in 24.03. At least in my test setup using an IPAlias VIP.

Is anyone here able to confirm that?

MrPete

@stephenw10 Thanks. Running a very nonprofit, we can't afford the Plus upgrade, so I'll look forward to the next CE release. :)

stephenw10

Yup, just looking for confirmation. Though this test setup was hitting it that doesn't mean it's fixed for all cases necessarily. There was a bunch of work went into the gateway/WAN handling in 24.03 though.

If we can confirm the fix we know that will work in CE.