Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    if_pppoe serious problems with php-fpm causing loops.

    Scheduled Pinned Locked Moved General pfSense Questions
    33 Posts 3 Posters 517 Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • C
      chrcoluk @stephenw10
      last edited by chrcoluk

      @stephenw10 Yeah, bear in mind I am no expert on dhcp6c, but what I am seeing suggests, its managing to pull something, it then runs ' /var/etc/dhcp6c_wan_script.sh ' which seems to fail, I posted these logs on the redmine, I will snippets here as well for you.

      Sorry also forgot to mention I have now also tried the do not wait for RA option as well.

      Here is end of it

      "Jul 4 13:46:23 dhcp6c 21264 exiting
      Jul 4 13:46:23 dhcp6c 21264 script "/var/etc/dhcp6c_wan_script.sh" terminated
      Jul 4 13:46:23 dhcp6c 22610 script "/var/etc/dhcp6c_wan_script.sh" cannot be executed safely
      Jul 4 13:46:23 dhcp6c 22610 lstat failed: No such file or directory
      Jul 4 13:46:23 dhcp6c 21264 executes /var/etc/dhcp6c_wan_script.sh
      Jul 4 13:46:23 dhcp6c 21264 removing an event on pppoe2, state=INIT
      Jul 4 13:46:23 dhcp6c 21264 exit without release "

      Here is all of it, I just noticed it there is an error at the start as well, whether that also happens when it succeeds on mpd I dont know as I wasnt looking.

      Jul 4 13:46:23 dhcp6c 21264 exiting
      Jul 4 13:46:23 dhcp6c 21264 script "/var/etc/dhcp6c_wan_script.sh" terminated
      Jul 4 13:46:23 dhcp6c 22610 script "/var/etc/dhcp6c_wan_script.sh" cannot be executed safely
      Jul 4 13:46:23 dhcp6c 22610 lstat failed: No such file or directory
      Jul 4 13:46:23 dhcp6c 21264 executes /var/etc/dhcp6c_wan_script.sh
      Jul 4 13:46:23 dhcp6c 21264 removing an event on pppoe2, state=INIT
      Jul 4 13:46:23 dhcp6c 21264 exit without release
      Jul 4 13:46:22 dhcp6c 21264 reset a timer on pppoe2, state=INIT, timeo=0, retrans=891
      Jul 4 13:46:22 dhcp6c 21004 called
      Jul 4 13:46:22 dhcp6c 21004 called
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of closure [}] (1)
      Jul 4 13:46:22 dhcp6c 21004 <13>begin of closure [{] (1)
      Jul 4 13:46:22 dhcp6c 21004 <13>[0] (1)
      Jul 4 13:46:22 dhcp6c 21004 <13>[na] (2)
      Jul 4 13:46:22 dhcp6c 21004 <3>[id-assoc] (8)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of closure [}] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>comment [# we'd like some nameservers please] (35)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>["/var/etc/dhcp6c_wan_script.sh"] (31)
      Jul 4 13:46:22 dhcp6c 21004 <3>[script] (6)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>[domain-name] (11)
      Jul 4 13:46:22 dhcp6c 21004 <3>[request] (7)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>[domain-name-servers] (19)
      Jul 4 13:46:22 dhcp6c 21004 <3>[request] (7)
      Jul 4 13:46:22 dhcp6c 21004 <3>comment [# request stateful address] (26)
      Jul 4 13:46:22 dhcp6c 21004 <3>end of sentence [;] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>[0] (1)
      Jul 4 13:46:22 dhcp6c 21004 <3>[ia-na] (5)
      Jul 4 13:46:22 dhcp6c 21004 <3>[send] (4)
      Jul 4 13:46:22 dhcp6c 21004 <3>begin of closure [{] (1)
      Jul 4 13:46:22 dhcp6c 21004 <5>[pppoe2] (6)
      Jul 4 13:46:22 dhcp6c 21004 <3>[interface] (9)
      Jul 4 13:46:22 dhcp6c 21004 skip opening control port
      Jul 4 13:46:22 dhcp6c 21004 failed initialize control message authentication
      Jul 4 13:46:22 dhcp6c 21004 failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
      Jul 4 13:46:22 dhcp6c 21004 extracted an existing DUID from /var/db/dhcp6c_duid: <censored>

      pfSense CE 2.8.0

      1 Reply Last reply Reply Quote 0
      • stephenw10S
        stephenw10 Netgate Administrator
        last edited by

        Both logs are reverse order I assume?

        C 1 Reply Last reply Reply Quote 0
        • C
          chrcoluk @stephenw10
          last edited by

          @stephenw10 yes, newest at the top.

          pfSense CE 2.8.0

          1 Reply Last reply Reply Quote 1
          • C
            chrcoluk
            last edited by chrcoluk

            Ok I have a done a little more testing, so the dhcp6c client was not staying in a running state, it is supposed to stay running.

            I first tried to just manually start it after pppoe2 is online, but it just says sending solicit every 2 seconds with not much else happening, also the '/var/etc/dhcp6c.conf' is unpopulated.

            I then rebooted into legacy mode, and '/var/etc/dhcp6c.conf' is populated with dhcpc6c running as a daemon.

            The contents as below.

            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 { };

            I then rebooted back into if_pppoe mode, let the ipv4 come online, manually populated the above file to match, and then started dhcpc6c from command line with same syntax as is done automatically and its now working.

            I think its a timing issue, dhcp6c is called too early on if_pppoe, I will update the redmine post.

            pfSense CE 2.8.0

            w0wW 1 Reply Last reply Reply Quote 0
            • w0wW
              w0w @chrcoluk
              last edited by

              @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?

              C 2 Replies Last reply Reply Quote 0
              • C
                chrcoluk @w0w
                last edited by

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

                pfSense CE 2.8.0

                1 Reply Last reply Reply Quote 1
                • stephenw10S
                  stephenw10 Netgate Administrator
                  last edited by

                  @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?

                  C 1 Reply Last reply Reply Quote 0
                  • C
                    chrcoluk @stephenw10
                    last edited by chrcoluk

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

                    pfSense CE 2.8.0

                    stephenw10S 1 Reply Last reply Reply Quote 0
                    • C
                      chrcoluk @w0w
                      last edited by chrcoluk

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

                      pfSense CE 2.8.0

                      1 Reply Last reply Reply Quote 0
                      • stephenw10S
                        stephenw10 Netgate Administrator @chrcoluk
                        last edited by

                        @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?

                        C 1 Reply Last reply Reply Quote 0
                        • C
                          chrcoluk @stephenw10
                          last edited by chrcoluk

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

                          I 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 packages

                          pfSense CE 2.8.0

                          w0wW 1 Reply Last reply Reply Quote 0
                          • stephenw10S
                            stephenw10 Netgate Administrator
                            last edited by

                            Can you see what's triggering that? Anything else logged at the time?

                            C 2 Replies Last reply Reply Quote 0
                            • C
                              chrcoluk @stephenw10
                              last edited by chrcoluk

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

                              pfSense CE 2.8.0

                              1 Reply Last reply Reply Quote 0
                              • C
                                chrcoluk @stephenw10
                                last edited by chrcoluk

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

                                pfSense CE 2.8.0

                                1 Reply Last reply Reply Quote 0
                                • w0wW
                                  w0w @chrcoluk
                                  last edited by

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

                                  1 Reply Last reply Reply Quote 1
                                  • stephenw10S
                                    stephenw10 Netgate Administrator
                                    last edited by

                                    Hmm, interesting.

                                    Does it still show the newwanip log every hour?

                                    Nothing in the dhcp log at that time?

                                    C 1 Reply Last reply Reply Quote 0
                                    • C
                                      chrcoluk @stephenw10
                                      last edited by 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

                                      pfSense CE 2.8.0

                                      1 Reply Last reply Reply Quote 0
                                      • stephenw10S
                                        stephenw10 Netgate Administrator
                                        last edited by

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

                                        C 1 Reply Last reply Reply Quote 0
                                        • C
                                          chrcoluk @stephenw10
                                          last edited by 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.

                                          pfSense CE 2.8.0

                                          1 Reply Last reply Reply Quote 0
                                          • stephenw10S
                                            stephenw10 Netgate Administrator
                                            last edited by

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

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

                                            C 1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post
                                            Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.