2.7.0 PPPoE Continually Reconnecting

stephenw10

To be clear this happens when you have a VIP that's in the same subnet as the WAN when it comes up?
Haven't managed to replicate that here yet.

threadhead

@stephenw10 Yes, gateway via PPPoE was able to pull a valid IP. The gateway (WAN) showed as active and I could see how long the IP address was obtained. The gateway on the Dashboard was green up-arrow.

No, I was never able to route traffic from any of the LANs to the WAN.

To add:

I did the pfSense update via browser, did not remove packages (probably should have)
Also, did a full wipe and reinstall of pfSense via usb stick to 2.7.0, nothing worked even with a full config restore
Did a full wipe and reinstall of pfSense 2.6.0, did a full config reinstall, everything worked

IanJanus

@stephenw10 Well the VIPs are in a /29 public IPs block that gets routed through the WAN, the PPPoE IP is usually completely different /32, so they aren't really in the same subnet as the WAN - since the WAN covers everything that isnt in a local subnet. However, they are defined in pfsense as associated with the WAN interface, though rather than define the /29 block, I have defined each VIP as a individual /32 IP.

stephenw10

@threadhead If you can replicate it you should check you have a default route applied via the PPPoE gateway. Also make sure you have outbound NAT rules being created for it.

RobbieTT

@stephenw10

This may be related to an issue I have on v23.05.1. The PPPoE handshake process now takes over 20 seconds. It used to take a maximum of 4 seconds, typically just 2 or 3 seconds.

My last connection - 22 seconds to complete the PPPoE:

Jul 15 17:07:29 Router-8 ppp[17990]: Multi-link PPP daemon for FreeBSD
Jul 15 17:07:51 Router-8 ppp[17990]: [wan] [redacted IPs]

️

RobbieTT

@RobbieTT said in 2.7.0 PPPoE Continually Reconnecting:

@stephenw10

This may be related to an issue I have on v23.05.1. The PPPoE handshake process now takes over 20 seconds. It used to take a maximum of 4 seconds, typically just 2 or 3 seconds.

My last connection - 22 seconds to complete the PPPoE:
Jul 15 17:07:29 Router-8 ppp[17990]: Multi-link PPP daemon for FreeBSD
Jul 15 17:07:51 Router-8 ppp[17990]: [wan] [redacted IPs]

@stephenw10

As of v23.09d 20230921-1219:

PPPoE handshake log now looks totally normal and completes in 3 seconds:

Sep 21 18:55:32	ppp	25088	Multi-link PPP daemon for FreeBSD
Sep 21 18:55:35	ppp	25088	[wan] IPCP: LayerUp
Sep 21 18:55:35	ppp	25088	[wan] [redacted IPs]

The extended PPPoE handshake issue appears to be resolved.

️

stephenw10

Hmm, that's interesting. I don't think we did anything specifically for that so I'd have to guess either some fix was pulled in from upstream or something changed at the server end.

RobbieTT

@stephenw10

It was an unexpected surprise but perhaps tied to a fix for something completely different. I skipped the last couple of dev loads so not sure which one had the desired effect but the issue remains with 23.09.a.20230907.0600.

It's not / was not a server-end PPPoE issue or change; as soon as I switched-out pfSense to a different router (EdgeRouter-4) the PPPoE handshakes reverted to normal.

Anyway, accidental fixes can be good, even if they leave questions.

Probably.

️

stephenw10

Hmm, interesting.

dougrabson

I came across this issue yesterday when I upgraded the backup of an HA pair to 2.7.0. My setup uses carp to handle the switchover from primary to backup, linking the pppoe interface to the carp VIP. When I tested failover, the backup enabled the pppoe interface and brought up the link but did not assign IPv4 local and remote addresses to the interface which meant that IPv4 was not routed and no IPv4 default route was installed. Sadly, I forgot to preserve the logs before downgrading back to 2.6.0.

Any ideas on workarounds for this?

stephenw10

That's not the same issue. The issue discussed in this thread is for VIPs on the PPPoE interface. It sounds like what you have is a PPPoE interface on a VIP.

You should start a new thread for that but I will say that what you're doing is an unsupported configuration. We have seen a few reports of it though.

Steve

dougrabson

@stephenw10 Thanks for the response - is there a recommended way of managing pppoe failover? I think I discovered my current approach from this thread: https://forum.netgate.com/topic/135904/configure-an-pppoe-on-an-carp-if/18.

stephenw10

Not really. HA requires static IPs for a supported setup.

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>