if_pppoe problems with php-fpm causing loops. (resolved)
-
@chrcoluk said in if_pppoe serious problems with php-fpm causing loops.:
I think its a timing issue, dhcp6c is called too early on if_pppoe
I just want to clarify — you're not using a multi-WAN configuration, right? And no CARP?
-
@w0w There is only one active pppoe, I think its pppoe2, because of an old WAN config that was disabled ages ago.
Not using CARP.
-
@chrcoluk said in if_pppoe serious problems with php-fpm causing loops.:
/var/etc/dhcp6c_wan_script.sh
What's in that script in each pppoe mode?
-
@stephenw10 I already know the contents in if_pppoe mode, I dont know when I can next reboot as I have been annoying people with all the stuff I am doing, but will check it on mpd as soon as possible. I think this one is without debug activated.
#!/bin/sh This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=${new_domain_name_servers} dmnames=${new_domain_name} case $REASON in REBIND) /usr/bin/logger -t dhcp6c "dhcp6c rebind on pppoe2" ;; REQUEST|RELEASE) /usr/bin/logger -t dhcp6c "dhcp6c RELEASE, REQUEST or EXIT on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" ;; RENEW|INFO) /usr/bin/logger -t dhcp6c "dhcp6c RENEW on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" esacpfSense CE 2.8.0
-
@w0w I have now deleted the old dormant pppoe0, there is no pppoe1, so now pppoe2 is the only PPP listed in the PPPs section and is assigned to WAN. This is just me tidying up though. I doubt its related as its been sitting there for probably 2 years unused (not assigned to any interfaces) since I stopped using that service.
-
@chrcoluk said in if_pppoe serious problems with php-fpm causing loops.:
This shell script launches /etc/rc.newwanipv6 with a interface argument.
That line should be commented:
# This shell script launches /etc/rc.newwanipv6 with a interface argument.Is that just a typo?
-
@stephenw10 It is commented in the actual file.
# cat /var/etc/dhcp6c_wan_script.sh #!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=${new_domain_name_servers} dmnames=${new_domain_name} case $REASON in REBIND) /usr/bin/logger -t dhcp6c "dhcp6c rebind on pppoe2" ;; REQUEST|RELEASE) /usr/bin/logger -t dhcp6c "dhcp6c RELEASE, REQUEST or EXIT on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" ;; RENEW|INFO) /usr/bin/logger -t dhcp6c "dhcp6c RENEW on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" esacI have just noticed this is repeating every hour in the general log.
php-fpm <pid> /rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe2.So even with the IPv6 online after my manual intervention, its unhappy about something, maybe because it never worked with the automatic attempt.
This from earlier when I ran dhcp6c manually.
rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 2001:8b0:<blah> - Restarting packagespfSense CE 2.8.0
-
Can you see what's triggering that? Anything else logged at the time?
-
@stephenw10 I got no idea what actually calls the script, it is isolated in the log, nothing else getting logged at the same moment.
It is isolated in the general log, but is coinciding with dhcp6 renew stuff which seems to happen every hour in the dhcp log.
I dont think this used to generate an rc.newwanipv6 log entry on the old pppoe though. Maybe this change is 2.8.0 specific, from what I can tell this is just log noise the dhcp6 looks like its renewing error free, and rc.newwanipv6 now seems to announce to the log when it starts.
-
@stephenw10 Ok I just made this patch and now it comes up automatically.
--- /etc/inc/interfaces.inc 2025-05-20 15:25:19.000000000 +0100 +++ /etc/inc/interfaces.inc 2025-07-07 19:48:09.639482000 +0100 @@ -4028,6 +4028,7 @@ kill_dhcp6client_process(true); /* Lock it to avoid multiple runs */ touch("/tmp/dhcp6c_lock"); + mwexec("/bin/sleep 6"); mwexec("/usr/local/sbin/dhcp6c {$debugOption} " . "{$noreleaseOption} " . "-c {$g['varetc_path']}/dhcp6c.conf " .I dont mind doing what you requested for the script contents on the old pppoe, but thats extended down time with the reboot, so will try it tomorrow morning when everyone asleep.
-
@chrcoluk said in if_pppoe serious problems with php-fpm causing loops.:
So even with the IPv6 online after my manual intervention, its unhappy about something
Receiving RA packets can trigger this, which is normal.
-
Hmm, interesting.
Does it still show the newwanip log every hour?
Nothing in the dhcp log at that time?
-
@stephenw10 It does but it seems that might be normal behaviour now. w0w's reply suggests that as well.
I have 2 dhcp6c clients running, which might be down to my manual intervention earlier, so I will reboot tomorrow morning to get the contents of that script for you and then check if is only one clent after I boot back into if_pppoe again and with it starting on that 6 second delay.
Jul 7 21:50:18 dhcp6c 38871 got an expected reply, sleeping. Jul 7 21:50:18 dhcp6c 38871 removing an event on pppoe2, state=RENEW Jul 7 21:50:18 dhcp6c 38871 script "/var/etc/dhcp6c_wan_script.sh" terminated Jul 7 21:50:18 dhcp6c 1126 dhcp6c RENEW on pppoe2 running rc.newwanipv6 Jul 7 21:50:18 dhcp6c 38871 executes /var/etc/dhcp6c_wan_script.sh Jul 7 21:50:18 dhcp6c 38871 add an address 2001:<blah> on pppoe2 Jul 7 21:50:18 dhcp6c 38871 update an address 2001:<blah> pltime=3600, vltime=31104153164832 Jul 7 21:50:18 dhcp6c 38871 update an IA: NA-0 Jul 7 21:50:18 dhcp6c 38871 dhcp6c Received INFO Jul 7 21:50:18 dhcp6c 38871 IA_NA address: 2001:<blah> pltime=3600 vltime=7200 Jul 7 21:50:18 dhcp6c 38871 get DHCP option IA address, len 24 Jul 7 21:50:18 dhcp6c 38871 IA_NA: ID=0, T1=3600, T2=5760 Jul 7 21:50:18 dhcp6c 38871 get DHCP option identity association, len 40 Jul 7 21:50:18 dhcp6c 38871 DUID: <blah> Jul 7 21:50:18 dhcp6c 38871 get DHCP option server ID, len 10 Jul 7 21:50:18 dhcp6c 38871 DUID: <blah> Jul 7 21:50:18 dhcp6c 38871 get DHCP option client ID, len 14 Jul 7 21:50:18 dhcp6c 38871 receive reply from <blah>%pppoe2 on pppoe2 Jul 7 21:50:18 dhcp6c 38871 send renew to ff02::1:2%pppoe2 Jul 7 21:50:18 dhcp6c 38871 set option request (len 4) Jul 7 21:50:18 dhcp6c 38871 set elapsed time (len 2) Jul 7 21:50:18 dhcp6c 38871 set identity association Jul 7 21:50:18 dhcp6c 38871 set IA address Jul 7 21:50:18 dhcp6c 38871 set server ID (len 10) Jul 7 21:50:18 dhcp6c 38871 set client ID (len 14) Jul 7 21:50:18 dhcp6c 38871 a new XID (e1ca48) is generated Jul 7 21:50:18 dhcp6c 38871 Sending Renew Jul 7 21:50:18 dhcp6c 38871 reset a timer on pppoe2, state=RENEW, timeo=0, retrans=9042 Jul 7 21:50:18 dhcp6c 38871 IA timeout for NA-0, state=ACTIVE Jul 7 21:50:00 dhcp6c 38871 XID mismatch Jul 7 21:50:00 dhcp6c 38871 IA_NA address: 2001:<blah> pltime=3600 vltime=7200 Jul 7 21:50:00 dhcp6c 38871 get DHCP option IA address, len 24 Jul 7 21:50:00 dhcp6c 38871 IA_NA: ID=0, T1=3600, T2=5760 Jul 7 21:50:00 dhcp6c 38871 get DHCP option identity association, len 40 Jul 7 21:50:00 dhcp6c 38871 DUID: <blah> Jul 7 21:50:00 dhcp6c 38871 get DHCP option server ID, len 10 Jul 7 21:50:00 dhcp6c 38871 DUID: <blah> Jul 7 21:50:00 dhcp6c 38871 get DHCP option client ID, len 14 Jul 7 21:50:00 dhcp6c 38871 receive advertise from <blah>:0%pppoe2 on pppoe2 -
Ok, yup that does look normal. It does log the received RAs which is what I expected.
-
@stephenw10 Ok as promised, here is the contents of the dhcp6c wan script from mpd.
#!/bin/sh # This shell script launches /etc/rc.newwanipv6 with a interface argument. dmips=${new_domain_name_servers} dmnames=${new_domain_name} case $REASON in REBIND) /usr/bin/logger -t dhcp6c "dhcp6c rebind on pppoe2" ;; REQUEST|RELEASE) /usr/bin/logger -t dhcp6c "dhcp6c RELEASE, REQUEST or EXIT on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" ;; RENEW|INFO) /usr/bin/logger -t dhcp6c "dhcp6c RENEW on pppoe2 running rc.newwanipv6" /usr/local/sbin/fcgicli -f /etc/rc.newwanipv6 -d "interface=pppoe2&dmnames=${dmnames}&dmips=${dmips}&reason=${REASON}" esacdhcp6c.conf for good measure
interface pppoe2 { send ia-na 0; # request stateful address request domain-name-servers; request domain-name; script "/var/etc/dhcp6c_wan_script.sh"; # we'd like some nameservers please }; id-assoc na 0 { };On booting back up again in if_pppoe, there is now no obvious operational issues, no looping and IPv6 is assigned locally on the firewall WAN interface via DHCP6.
This is with combined use of the patch made to stop the looping, and my own patch to delay execution of dhcp6c by 6 seconds.
However I do have 3 instances of dhcp6c running. It was zero with the dhcp6 failing before I added the delay, but the delay may have added a side effect. I will look at interfaces.inc again to see if I can tidy this up and remove the duplication issue.
--update
I moved the sleep command prior to the lock check, also reduced it to 3 seconds, as I think 6 was excessive, I now have only one process, the pid file matches the actual pid, and everything looks clean now.
Also looks like disabling dhcp6c debug, stops the hourly log noise. Explains why I didnt notice it before.
-
Nice debugging. Now why would that be required for your connection....
Can you show the new patch you've ended up using?
-
@stephenw10 Yeah sure.
--- /etc/inc/interfaces.inc 2025-05-20 15:25:19.000000000 +0100 +++ /etc/inc/interfaces.inc 2025-07-07 19:48:09.639482000 +0100 @@ -4024,6 +4024,7 @@ * lock deleted. */ + mwexec("/bin/sleep 3"); if (!file_exists("/tmp/dhcp6c_lock")) { kill_dhcp6client_process(true); /* Lock it to avoid multiple runs */Also
# ps ax | grep dhcp6 88258 - Is 0:00.01 /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c.conf -p /var/run/dhcp6c.pid pppoe2 99730 1 S+ 0:00.00 grep --color dhcp6# cat /var/run/dhcp6c.pid 88258 -
ISP is doing LNS maintenance over the upcoming week, so will see how that reconnection goes.
Also I patched mss clamping in the scrub code to make it 52 bytes instead of 40 for timestamps overhead, and wow things have never performed so good, so that combined with this driver is working really well for me now.
-
Hmm did I miss something about timestamps? What did you discover that required that?
-
So, are we talking about RFC 1323 and a modification to /etc/inc/filter.inc?
