New PPPoE backend, some feedback
-
thanks for your advise
Reboot sadly didn't solve the problem.
Part of trying the 2.8.0-Beta with the new if_pppoe kernel module would be sharing the problems i encounter during this update. Testing it on/with my personal hardware/isp.
I'm not a computer expert or programmer. I run pfsense on a sophos system. I think that would make me the ideal real life beta-tester :)Michiel
-
@MichielHN
Could you please share the output ofnetstat -rThis shows the routing table. I had same issue, but after setting default route for IPv6 all fine now.
BR
-
it rather a long list; the items concerning pppoe are:
Shell Uitvoer - netstat -r | grep pppoe
default 195-XXX-XXX-121.fi UG pppoe0
195-XXX-XXX-121.fi link#22 UH pppoe0
default fe80::XXXX:XXXX:fe UG pppoe0
fe80::%pppoe0/64 link#22 U pppoe0 -
@MichielHN
Ok, there is no default route for IPv6.
Either you set the IPv6 GW fix, or build a static IPv6 route like this:
::/1 link#16 US pppoe1 -
@MichielHN
Show your pppoe wan config -
@MichielHN said in New PPPoE backend, some feedback:
@RobbieTT
Testing it on/with my personal hardware/isp.
I'm not a computer expert or programmer. I run pfsense on a sophos system. I think that would make me the ideal real life beta-tester :)It does indeed. I have a Netgate 6100 but I run the beta-testing on a modern bare-metal server to give real-world feedback, as Netgate have all the 6100's they need. Although they have been known to ask me to run stuff on my 6100 on occasion but I leave those decisions to them.
️ -
@bananajoe
setting IPv6 GW manually works fine, but i wonder what would happen if the isp decides to assign a different ipv6 range. -
@MichielHN
Different IPv6 range should be no problem, as the route is bound to the interface itself, not to the IPv6 address.
Should be dynamic. At least in my seatup it works great.PPPoE and 24h reset by ISP
-
@stephenw10 said in New PPPoE backend, some feedback:
I think the connection status you see is actually an artifact of the new interface type. I can sort of replicate what you see but in fact it does connect it's just not instant. You can see what the actual state is using the new
pppcfgcommand.
...
The actual time taken depends how fast the server responds. For be that be almost instant or it can be several retries and 20-30s.@stephenw10 commented on one of my (presumed) 'successful' connection attempts that I sent along with other pcaps. From the GUI it seemed to connect ok, within normal timeframes but looking in detail the PADI, PADO, PADR and PADS were all completed in around 6 ms (effectively instant). What then followed was repeated 'Configuration Requests' and the associated 'Ack' in response, stuck in a loop (in this case) for 20 sec.
In worst case examples this loop carries on for minutes and if or until it is resolved the dashboard shows the interface as 'Up' (but without details) and the Gateways show as 'Pending'. In this condition no WAN traffic is passed.
The redacted screenshot of the pcap is filtered on PPPoE activity alone:
️ -
Yeah that config delay seems odd. I'd expect that to be close to instant really. Though I guess some part of he upstream server might be delayed at the backend.
But the important part there would be whether or not it does eventually connect.
The old mpd5/netgraph pppoe client also shows as up if it's parent NIC is linked but if_pppoe, currently, shows as 'up' at all times one the interface is created. That's confusing the status page. It does seem like we could improve that relatively easily by including the connection state info there.
-
Try setting
Start DHCP6 client in debug modein System > Advanced > Networking.It's not clear from your dhcp logs whether or not it's actually running on pppoe0.
Also you can filter that log by the dhcp6c process. Everything else shown there isn't relevant.
-
@stephenw10 said in New PPPoE backend, some feedback:
Yeah that config delay seems odd. I'd expect that to be close to instant really. Though I guess some part of he upstream server might be delayed at the backend.
I did ponder that but pfSense asks the question and the upstream responds immediately with the correct Ack. There is nothing different in the multiple upstream server responses, even at the final time where pfSense stops asking, seemingly satisfied with the last repeated Ack.
Is there any chance the almost-paired PPP IPCP and PPP IPV6CP Requests are stepping on or resetting each other's almost-paired Acks?
In effect:
Request, Request, Ack, Ack = not good, loop continues
Request, Ack, Request, Ack = goodOnly the sequencing changes for the final accepted Acks, not the response Ack data. I know it shouldn't matter but it is the only difference I can find:
️ -
in the end there seems to be a response from pppoe but the gateway DHCP6 is still 'waiting'
the full 'grep dhcp6c /var/log/dhcpd.log' is too long to post
Apr 29 15:53:55 sofie dhcp6c[51825]: removing an event on pppoe0, state=INIT
Apr 29 15:53:55 sofie dhcp6c[51825]: executes /var/etc/dhcp6c_opt6_script.sh
Apr 29 15:53:55 sofie dhcp6c[53992]: lstat failed: No such file or directory
Apr 29 15:53:55 sofie dhcp6c[53992]: script "/var/etc/dhcp6c_opt6_script.sh" cannot be executed safely
Apr 29 15:53:55 sofie dhcp6c[51825]: script "/var/etc/dhcp6c_opt6_script.sh" terminated
Apr 29 15:53:55 sofie dhcp6c[51825]: exiting
Apr 29 15:54:05 sofie dhcp6c[18129]: extracted an existing DUID from /var/db/dhcp6c_duid: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:05 sofie dhcp6c[18129]: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
Apr 29 15:54:05 sofie dhcp6c[18129]: failed initialize control message authentication
Apr 29 15:54:05 sofie dhcp6c[18129]: skip opening control port
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[interface] (9)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[pppoe0] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[send] (4)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[ia-pd] (5)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>comment [# request prefix delegation] (27)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[request] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[domain-name-servers] (19)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[request] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[domain-name] (11)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[script] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>["/var/etc/dhcp6c_opt6_script.sh"] (32)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>comment [# we'd like some nameservers please] (35)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[id-assoc] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>[pd] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <13>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[::] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[/] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[48] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[infinity] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[igb0] (4)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[0] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[lagg0] (5)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[2] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[prefix-interface] (16)
Apr 29 15:54:05 sofie dhcp6c[18129]: <5>[lagg0.20] (8)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>begin of closure [{] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-id] (6)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[32] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[sla-len] (7)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>[16] (2)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of closure [}] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: <3>end of sentence [;] (1)
Apr 29 15:54:05 sofie dhcp6c[18129]: called
Apr 29 15:54:05 sofie dhcp6c[18129]: called
Apr 29 15:54:05 sofie dhcp6c[18258]: reset a timer on pppoe0, state=INIT, timeo=0, retrans=891
Apr 29 15:54:06 sofie dhcp6c[18258]: Sending Solicit
Apr 29 15:54:06 sofie dhcp6c[18258]: a new XID (6c1ff3) is generated
Apr 29 15:54:06 sofie dhcp6c[18258]: set client ID (len 14)
Apr 29 15:54:06 sofie dhcp6c[18258]: set elapsed time (len 2)
Apr 29 15:54:06 sofie dhcp6c[18258]: set option request (len 4)
Apr 29 15:54:06 sofie dhcp6c[18258]: set IA_PD prefix
Apr 29 15:54:06 sofie dhcp6c[18258]: set IA_PD
Apr 29 15:54:06 sofie dhcp6c[18258]: send solicit to ff02::1:2%pppoe0
Apr 29 15:54:06 sofie dhcp6c[18258]: reset a timer on pppoe0, state=SOLICIT, timeo=0, retrans=1091
Apr 29 15:54:06 sofie dhcp6c[18258]: receive advertise from fe80::9217:3fff:fe22:6263%pppoe0 on pppoe0
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option client ID, len 14
Apr 29 15:54:06 sofie dhcp6c[18258]: DUID: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option server ID, len 14
Apr 29 15:54:06 sofie dhcp6c[18258]: DUID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option preference, len 1
Apr 29 15:54:06 sofie dhcp6c[18258]: preference: 0
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option IA_PD, len 54
Apr 29 15:54:06 sofie dhcp6c[18258]: IA_PD: ID=0, T1=86400, T2=138240
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option IA_PD prefix, len 25
Apr 29 15:54:06 sofie dhcp6c[18258]: IA_PD prefix: 2a02:a45b:e304::/48 pltime=172800 vltime=2292014193773376640
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option status code, len 9
Apr 29 15:54:06 sofie dhcp6c[18258]: status code: success
Apr 29 15:54:06 sofie dhcp6c[18258]: get DHCP option DNS, len 32
Apr 29 15:54:06 sofie dhcp6c[18258]: server ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd, pref=0
Apr 29 15:54:06 sofie dhcp6c[18258]: reset timer for pppoe0 to 0.985017
Apr 29 15:54:07 sofie dhcp6c[18258]: picked a server (ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd)
Apr 29 15:54:07 sofie dhcp6c[18258]: Sending Request
Apr 29 15:54:07 sofie dhcp6c[18258]: a new XID (f46830) is generated
Apr 29 15:54:07 sofie dhcp6c[18258]: set client ID (len 14)
Apr 29 15:54:07 sofie dhcp6c[18258]: set server ID (len 14)
Apr 29 15:54:07 sofie dhcp6c[18258]: set elapsed time (len 2)
Apr 29 15:54:07 sofie dhcp6c[18258]: set option request (len 4)
Apr 29 15:54:07 sofie dhcp6c[18258]: set IA_PD prefix
Apr 29 15:54:07 sofie dhcp6c[18258]: set status code
Apr 29 15:54:07 sofie dhcp6c[18258]: set IA_PD
Apr 29 15:54:07 sofie dhcp6c[18258]: send request to ff02::1:2%pppoe0
Apr 29 15:54:07 sofie dhcp6c[18258]: reset a timer on pppoe0, state=REQUEST, timeo=0, retrans=909
Apr 29 15:54:07 sofie dhcp6c[18258]: receive reply from fe80::9217:3fff:fe22:6263%pppoe0 on pppoe0
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option client ID, len 14
Apr 29 15:54:07 sofie dhcp6c[18258]: DUID: 00:01:00:01:2c:6d:3a:28:7c:5a:1c:54:33:00
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option server ID, len 14
Apr 29 15:54:07 sofie dhcp6c[18258]: DUID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option IA_PD, len 54
Apr 29 15:54:07 sofie dhcp6c[18258]: IA_PD: ID=0, T1=86400, T2=138240
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option IA_PD prefix, len 25
Apr 29 15:54:07 sofie dhcp6c[18258]: IA_PD prefix: 2a02:a45b:e304::/48 pltime=172800 vltime=2292014193773376640
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option status code, len 9
Apr 29 15:54:07 sofie dhcp6c[18258]: status code: success
Apr 29 15:54:07 sofie dhcp6c[18258]: get DHCP option DNS, len 32
Apr 29 15:54:07 sofie dhcp6c[18258]: dhcp6c Received REQUEST
Apr 29 15:54:07 sofie dhcp6c[18258]: nameserver[0] 2a02:a47f:e000::53
Apr 29 15:54:07 sofie dhcp6c[18258]: nameserver[1] 2a02:a47f:e000::54
Apr 29 15:54:07 sofie dhcp6c[18258]: make an IA: PD-0
Apr 29 15:54:07 sofie dhcp6c[18258]: create a prefix 2a02:XXXX:XXXX::/48 pltime=172800, vltime=259200
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:0:7e5a:1cff:fe54:3300/64 on igb0
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:2:7e5a:1cff:fe54:3303/64 on lagg0
Apr 29 15:54:07 sofie dhcp6c[18258]: add an address 2a02:XXXX:XXXX:20:7e5a:1cff:fe54:3303/64 on lagg0.20
Apr 29 15:54:07 sofie dhcp6c[18258]: status code for PD-0: success
Apr 29 15:54:07 sofie dhcp6c[18258]: executes /var/etc/dhcp6c_opt6_script.sh
Apr 29 15:54:07 sofie dhcp6c[58580]: dhcp6c RELEASE, REQUEST or EXIT on pppoe0 running rc.newwanipv6
Apr 29 15:54:07 sofie dhcp6c[18258]: script "/var/etc/dhcp6c_opt6_script.sh" terminated
Apr 29 15:54:07 sofie dhcp6c[18258]: removing an event on pppoe0, state=REQUEST
Apr 29 15:54:07 sofie dhcp6c[18258]: removing server (ID: 00:01:00:06:00:73:e3:ad:90:17:ac:bf:97:dd)
Apr 29 15:54:07 sofie dhcp6c[18258]: got an expected reply, sleeping. -
Hmm, interesting!
I note that in that last request it asks for a different IPaddress. But then connects and stars using the IP the server had been passing it in the previous request/acks.
-
That looks like it's completing as expected. You see the prefixes added to the internal interfaces?
Do you see the gateway in the NDP table?
Does that exact same config work when not using if_pppoe?
-
@MichielHN
oops sorry, I mean this one
-
@stephenw10 said in New PPPoE backend, some feedback:
Hmm, interesting!
I note that in that last request it asks for a different IPaddress. But then connects and stars using the IP the server had been passing it in the previous request/acks.
Apart from the very first request (where it uses 0.0.0.0.) it uses my static IPv4 address, which is obtained via DHCP. The oddball IP you see at the end of the PCAP is the IPv4 of the upstream PPPoE server (it picks from a list of 5 or 6 possible addresses).
️ -
@w0w
like image posted above
link text
WANix1 is the WAN interface (ix1 for intel 10g sfp+ nic1, nic0 is internal)@stephenw10
while the gateway says its 'waiting' the local computers get ipv6 connection now, and probably before as well. NDP table looks fine. I concluded 'it's not working' based on the status/gateways overview.so the real question should be, why doesn't the gateway show as active?
-
@RobbieTT said in New PPPoE backend, some feedback:
it uses my static IPv4 address, which is obtained via DHCP.
Like, when it's not using PPPoE?
-
@MichielHN said in New PPPoE backend, some feedback:
like image posted above
Ahh looks OK, just missed that...
