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

chrcoluk

There was a second later outage, on the second outage it came back up by itself.

chrcoluk

@stephenw10 I didnt try that as I had experiences recently, using that method could leave services down, whilst toggling in interfaces always seems to keep everything running cleanly.

There is a chance of more drops as AAISP havent closed the incident, given CF are refusing to communicate with them on what has gone wrong, if it gets stuck again, I will try a cycle on the interfaces screen.

chrcoluk

@stephenw10 It went down again, didnt auto recover, status interfaces said it was still up (no ip's), I took it down then back up again and it came back right away.

w0w

@chrcoluk
When the PPPoE interface shows 'up', it means it's in the process of connecting. How long did you wait? Next time look what does

pppcfg pppoe0

show.

chrcoluk

@w0w It was already down for 2 hours and I had people moaning at me, no time to sit there watching it I am afraid. I wasnt asked to sit and watch it either, just to restart it on the interfaces page.

But I will try and remember that command. Thank you.

Future testing at more convenient times might be possible via yanking a cable.

What is logged during what seems to be a connection attempt before I intervened, I removed all noise like service restarts etc.

If I remember right things like timeout settings used to be tunable?.

Jul 26 06:11:28 	kernel 	222645 	if_pppoe: pppoe2: LCP keepalive timeout
Jul 26 06:10:40 	kernel 	222596 	if_pppoe: pppoe: GENERIC ERROR (errortag 1)
Jul 26 06:09:46 	kernel 	222542 	pppoe2: link state changed to UP
Jul 26 06:09:46 	kernel 	222542 	pppoe2: link state changed to DOWN
Jul 26 06:09:46 	kernel 	222542 	pppoe2: link state changed to UP
Jul 26 06:09:38 	kernel 	222535 	pppoe2: received unexpected PADO
Jul 26 06:09:38 	kernel 	222535 	pppoe2: received unexpected PADO
Jul 26 06:09:38 	kernel 	222535 	pppoe2: link state changed to DOWN
Jul 26 06:09:38 	kernel 	222535 	if_pppoe: pppoe2: LCP keepalive timeout

chrcoluk

@w0w I am seeing indications in the log it isnt going down as you suggested, as an example dpinger stayed running on static pid, logging almost every second ping failures. Also no switch of gateway, when the switch criteria is "down" state. (my phone was left in all night as a internet uplink).
If its failing to go to a down state, it would make some sense as to why a manual restart works and leaving it alone doesnt. As the obvious question is what is different between me restarting it manually and it trying to restart itself, there must be a difference.

When I intervened dpinger exited on signal 15.

w0w

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

But I will try and remember that command.

~~pppcfg pppoe0 -d~~

~~Will be better as it return debug details .~~

Sorry, @stephenw10 gave the correct answer about the debug option — I somehow mixed it up in my head with something else.

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

If I remember right things like timeout settings used to be tunable?

When the last time I searched I didn't find anything related parameters, but maybe it's changed already, IDK.

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

Jul 26 06:09:46 kernel 222542 pppoe2: link state changed to UP
Jul 26 06:09:46 kernel 222542 pppoe2: link state changed to DOWN
Jul 26 06:09:46 kernel 222542 pppoe2: link state changed to UP
Jul 26 06:09:38 kernel 222535 pppoe2

I don't know is it expected behaviour to switch link state that fast, but it could be a reason for dpinger not going down and all other things happened.

stephenw10

Hmm, if it happens again try checking the status shown in: pppcfg pppoe0

You could also try enabling debug: ifconfig pppoe0 debug. But that will spam the console/logs at lot! Be ready with ifconfig pppoe0 -debug

chrcoluk

A retry delay, might be an idea? With the timing issue on ipv6 as well, I wonder if things just move too fast.
Because I dont understand how the new PPP works, from what I can tell it doesnt even have a config file, the parameters are just supplied directly, its hard for me to try and patch something myself to find a solution, I am hoping netgate are looking into it as its just me and ajtuk from one ISP.
Just in case it might be relevant, the WAN connection does go through a WAN side VLAN, a requirement from CityFibre.

This is also confirmed on the command output here.

# pppcfg pppoe2
        dev: igc1.911 state: session
        sid: 0x44a8 PADI retries: 0 PADR retries: 0 time: 02:13:26
        sppp: phase network authproto auto authname "x@x" peerproto auto 
        dns: 217.x 217.x

I will of course do as you said stephen, the incident is now closed, but if needed I will try to emulate it with a cable pull test, but I have someone relying on the uplink almost around the clock, so might be a little bit of time to get a chance to do it.

I am also prepared to have a conversation with AAISP to see if they can assist from their side, maybe they can notice something wrong in their logs.

stephenw10

Mmm, the VLAN should not have any effect. Many ISPs require that..

Can you replicate this manually by just reconnecting the WAN? That at least would be something we could try to replicate locally.

chrcoluk

@stephenw10 I thought about how I would do the test, I think best way is cutting power to the ONT, s the box will detect the carrier link going down if I pull the ethernet, I will try to do this test as soon as I can, but to try and mimic the conditions, I will probably need to keep at down for at least 15 minutes.

I will do this in about 5 hours or so, I think either killing the ONT power or removing the cable, will make the cable register as disconnected, I am not prepared to remove the fibre cable, as it leaves it exposed to dirt.

AAISP offer a kill switch for the PPP, and the last outage was caused by them doing a "admin reset" it was logged as that on their logs. I guess to kick me of the LNS for rebalancing purposes, so I will get online via my phone and use the PPP kill switch for the test, this leaves the ONT powered up and ethernet cable in a connected state to mimic the failure conditions.

chrcoluk

@stephenw10 Ok here is an update, good news, remote kill of ppp triggers it so easy debug. Bad news cycling the interface removes the debug flag so successful connect lacks debug.

I can confirm the following, interface is "not" going down, no counters reset, checking it often in both cli and interfaces UI shows outbound packets accruing with no other changes.
The UI during this stuck state, shows it online with no ip's.
The CLI during this stuck state shows it online and the ip's still bound.

snapshot of debug log below, is from what I can see just 4 lines repeating, and looking at timestamps, there seems to be no pauses going on. Only thing I censored was what I think is remote mac from ISP, playing safe on that.

Since I can do the test quickly, I am a bit more open to repeating it in future.

I have also snapshotted another bit of logging with it debug enabled whilst I kill PPP, so info before the loop starts, but its a lot to post on this thread, is there somewhere else I can post more privately? If not, I might attach it somewhere.

Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x63 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x63 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x62 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x62 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x61 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x61 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x60 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x60 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5f len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5f len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5e len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5e len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5d len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5d len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5c len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5c len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5b len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5b len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x5a len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x5a len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x59 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x59 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x58 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x58 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x57 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x57 len=22
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp nak opts:
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp input(ack-sent): <conf-nak id=0x56 len=10
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2 (8864) state=3, session=0x580 output -> 9c:<blah>, len=30
Jul 29 07:29:01 	kernel 	486498 	if_pppoe: pppoe2: ipcp output <conf-req id=0x56 len=22
Jul 29 07:29:01 	kern
```el 	486498 	if_pppoe: pppoe2: ipcp nak opts:

chrcoluk

@ajtuk Hi, I reported this to AAISP now, it makes sense to try and get them to work with pfSense dev's, if you can, you can contact them as well. As I mentioned there was another customer affected by the lack of auto reconnection.

ajtuk

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

@ajtuk Hi, I reported this to AAISP now, it makes sense to try and get them to work with pfSense dev's, if you can, you can contact them as well. As I mentioned there was another customer affected by the lack of auto reconnection.

Will do. I can also do some more testing next week and see if I get the same results. It's been "stable" the last few days, but no maintenance or issues on the AAISP end to cause it to drop.

stephenw10

Yup you can upload here: https://nc.netgate.com/nextcloud/s/isZqc6dRLsXfqYg

How exactly are you killing PPP?

chrcoluk

@stephenw10 There should be 2 logs there, I am not sure it worked as it says uploading, but please let me know.

On your question, AAISP on their control panel has a button that you can click which will kill the PPP session from their side, so basically a server side kill, not client side kill. I was logged in with my mobile phone connection to ensure I didnt lose access to the control panel as it happened.

stephenw10

Yup I see the files there, thanks.

ajtuk

@stephenw10 My connection dropped tonight. ISP logged it as a "Planned PPP restart". I uploaded a log to the link here. Maybe it's helpful?

It was only my CityFibre connection which did not reconnect. FTTC reconnected OK. Both use PPPoE and both are with A&A.

Rebooting the appliance brought it back up.