if_pppoe problems with php-fpm causing loops. (resolved)

stephenw10

Hmm, interesting.

Does it still show the newwanip log every hour?

Nothing in the dhcp log at that time?

chrcoluk

@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

stephenw10

Ok, yup that does look normal. It does log the received RAs which is what I expected.

chrcoluk

@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}"
esac

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

stephenw10

Nice debugging. Now why would that be required for your connection....

Can you show the new patch you've ended up using?

chrcoluk

@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

chrcoluk

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.

stephenw10

Hmm did I miss something about timestamps? What did you discover that required that?

w0w

So, are we talking about RFC 1323 and a modification to /etc/inc/filter.inc?

chrcoluk

I noticed pfSense code if mss clamp is enabled just does the basic 40 bytes (IPv4) 60 bytes (IPv6) so e.g. a 1460 bytes MSS clamp on IPv4 with a 1500 byte MTU, I think it should be 1448 in such a scenario, so I changed the 40 bytes to 52, currently I have only patched the IPv4 code. Timestamps now days is on by default in operating systems and important on high bandwidth.

I did notice youtube videos had a stall before playing, as soon as I made this adjustment that has been fixed, and there is a wider improvement I am noticing as well.

It is a very basic patch as well. Modifying the firewall generation script, scrub rules.

w0w yes to both.

                /* set up MSS clamping */
                if ($mss) {
                        /* different size of IPv4/IPv6 header, https://redmine.pfsense.org/issues/11409 */
-                        $mssclamp4 = "max-mss " . ($mss - 40);
+                        $mssclamp4 = "max-mss " . ($mss - 52);

mssclamp6 is right under that as well.

w0w

@chrcoluk said in if_pppoe problems with php-fpm causing loops. (resolved):

I have only patched the IPv4 code

Why not both stacks?

chrcoluk

@w0w I will do both stacks, it was something I did very quickly and I want to check if its still 12 bytes for ipv6 as well.

Patched it now. So on my 1500 bytes MTU, 1448 MSS for IPV4, 1428 MSS for IPv6.

w0w

@chrcoluk
I did the same and even captured WAN packets to confirm. Looks like it's working — we'll see. By the way, I'm using gigabit PPPoE.

stephenw10

Hmm, interesting. I can't say I've noticed that. But also I wasn't looking for it specifically.