PPP cycling between UP and DOWN

PPP cycling between UP and DOWN

[Patrick Mahan]

PPP v2.3.11
RP-PPPOE v3.12
Linux 2.6.35

I am seeing some issues with respect to how PPP is handling a PPPoE connection.

My PPPoE connection gets established and pppd reports UP via the ip-up script. 
Then at some point (sometimes within a second, sometimes hours) pppd reports down 
via the ip-down script, but does not exit then re-establishes the UP state and 
reports it via ip-up.

I have a script that monitors by this by having a modified ip-up and ip-down 
script write a value to a specific file under /var/run/pppd/ and if it is 
ip-down, then I schedule a restart of pppd to occur once the pppd image exits.  I 
have assumed that ip-down being triggered is and indication that PPPoE connection 
is down and over.

But I am now seeing that this assumption could be incorrect.  I don't claim to 
understand the entire protocol layers involved.  But is it supported that a PPPoE 
connection can shift back from the IPCP layer to the LCP layer?  Then back?

Or is this a ppp protocol issue.  I see in the pppd code that we can moved to a 
down state if we get a request to restart negotiations, so I can see that my 
assumption may be incorrect.

Any help is appreciated.

Thanks,

Patrick

Re: PPP cycling between UP and DOWN

[James Carlson]

On 2020-05-27 15:16, Patrick Mahan wrote:
> I have a script that monitors by this by having a modified ip-up and
> ip-down script write a value to a specific file under /var/run/pppd/ and
> if it is ip-down, then I schedule a restart of pppd to occur once the
> pppd image exits.  I have assumed that ip-down being triggered is and
> indication that PPPoE connection is down and over.

That's the most likely case.  It would help to have _complete_ debug
logs showing what's happening.

(For what it's worth, another person posting to this list recently was
having PPPoE problems that ended up tracking back to a bad Ethernet
driver.  The driver allowed receive of unicast packets with someone
else's address, and the PPPoE kernel code accepted a stray PADT that
caused the link to go down.)  (PPPoE, as a protocol, is pretty nasty stuff.)

> But I am now seeing that this assumption could be incorrect.  I don't
> claim to understand the entire protocol layers involved.  But is it
> supported that a PPPoE connection can shift back from the IPCP layer to
> the LCP layer?  Then back?

IPCP can certainly be taken down without taking down LCP.  And LCP can
be renegotiated (implicitly taking down IPCP as well) at any time.
However, I've yet to find a commercial service provider that actually
supports anything like this.  All of the systems they use are much more
limited implementations.

It sounds like a stretch to me.  A debug log would show for sure, though.

> Or is this a ppp protocol issue.  I see in the pppd code that we can
> moved to a down state if we get a request to restart negotiations, so I
> can see that my assumption may be incorrect.

It can, as described above, but it's not something that's commonly (or
"ever") implemented, at least in my experience.  Renegotiation almost
always leads to complete teardown.  (Depending on the vendor, some will
start doing LCP Protocol-Reject on the NCP protocols like IPCP if you
attempt that.)

This doesn't sound likely to me.  But, again, debug logs are your friend
here.

Use the pppd 'debug' option.  By itself, that'll write the log
information to syslog daemon.debug (be sure to redirect that to a file).
 Or use the "logfile /path/to/file" option to write the messages to a
file.  Then post those logs.

It's important to understand that PPP is just one protocol layer.  PPPoE
itself is distinct, with its own messages and states.  The actions of
PPPoE are seen by PPP as just underlying link up/down states -- very
much like the signals PPP would get from a modem.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: PPP cycling between UP and DOWN

[Patrick Mahan]

On 5/28/20 6:59 AM, James Carlson wrote:
> On 2020-05-27 15:16, Patrick Mahan wrote:
>> I have a script that monitors by this by having a modified ip-up and
>> ip-down script write a value to a specific file under /var/run/pppd/ and
>> if it is ip-down, then I schedule a restart of pppd to occur once the
>> pppd image exits.  I have assumed that ip-down being triggered is and
>> indication that PPPoE connection is down and over.
> 
> That's the most likely case.  It would help to have _complete_ debug
> logs showing what's happening.

I'm working on that, but I probably won't have them until tomorrow.

> 
> (For what it's worth, another person posting to this list recently was
> having PPPoE problems that ended up tracking back to a bad Ethernet
> driver.  The driver allowed receive of unicast packets with someone
> else's address, and the PPPoE kernel code accepted a stray PADT that
> caused the link to go down.)  (PPPoE, as a protocol, is pretty nasty stuff.)
> 

I am dis-inclined to lean in that direction.  These are standard Intel igb 
devices.  In over 5 years I have yet to have one issue tracked back directly to 
the ethernet driver.

>> But I am now seeing that this assumption could be incorrect.  I don't
>> claim to understand the entire protocol layers involved.  But is it
>> supported that a PPPoE connection can shift back from the IPCP layer to
>> the LCP layer?  Then back?
> 
> IPCP can certainly be taken down without taking down LCP.  And LCP can
> be renegotiated (implicitly taking down IPCP as well) at any time.
> However, I've yet to find a commercial service provider that actually
> supports anything like this.  All of the systems they use are much more
> limited implementations.
> 
> It sounds like a stretch to me.  A debug log would show for sure, though.
> 

Yes, it seems like a stretch to me as well.  This code has been operating for 
almost 5 years with very little change.  This is the first case and it has only 
happened once.

>> Or is this a ppp protocol issue.  I see in the pppd code that we can
>> moved to a down state if we get a request to restart negotiations, so I
>> can see that my assumption may be incorrect.
> 
> It can, as described above, but it's not something that's commonly (or
> "ever") implemented, at least in my experience.  Renegotiation almost
> always leads to complete teardown.  (Depending on the vendor, some will
> start doing LCP Protocol-Reject on the NCP protocols like IPCP if you
> attempt that.)
> 
> This doesn't sound likely to me.  But, again, debug logs are your friend
> here.
> 
> Use the pppd 'debug' option.  By itself, that'll write the log
> information to syslog daemon.debug (be sure to redirect that to a file).
>   Or use the "logfile /path/to/file" option to write the messages to a
> file.  Then post those logs.
> 
> It's important to understand that PPP is just one protocol layer.  PPPoE
> itself is distinct, with its own messages and states.  The actions of
> PPPoE are seen by PPP as just underlying link up/down states -- very
> much like the signals PPP would get from a modem.
> 

I am using rp-pppoe so I will look at their code to see if there might be an 
possible issue.

I am currently hoping this is an one off issue that won't return soon and I can, 
hopefully, wait until we are upgrade to a newer kernel and code.

Thanks,

Patrick

Re: PPP cycling between UP and DOWN

[Patrick Mahan]

On 5/28/20 6:59 AM, James Carlson wrote:
> On 2020-05-27 15:16, Patrick Mahan wrote:
>> I have a script that monitors by this by having a modified ip-up and
>> ip-down script write a value to a specific file under /var/run/pppd/ and
>> if it is ip-down, then I schedule a restart of pppd to occur once the
>> pppd image exits.  I have assumed that ip-down being triggered is and
>> indication that PPPoE connection is down and over.
> 
> That's the most likely case.  It would help to have _complete_ debug
> logs showing what's happening.
> 
> (For what it's worth, another person posting to this list recently was
> having PPPoE problems that ended up tracking back to a bad Ethernet
> driver.  The driver allowed receive of unicast packets with someone
> else's address, and the PPPoE kernel code accepted a stray PADT that
> caused the link to go down.)  (PPPoE, as a protocol, is pretty nasty stuff.)
> 
>> But I am now seeing that this assumption could be incorrect.  I don't
>> claim to understand the entire protocol layers involved.  But is it
>> supported that a PPPoE connection can shift back from the IPCP layer to
>> the LCP layer?  Then back?
> 
> IPCP can certainly be taken down without taking down LCP.  And LCP can
> be renegotiated (implicitly taking down IPCP as well) at any time.
> However, I've yet to find a commercial service provider that actually
> supports anything like this.  All of the systems they use are much more
> limited implementations.
> 
> It sounds like a stretch to me.  A debug log would show for sure, though.
> 
>> Or is this a ppp protocol issue.  I see in the pppd code that we can
>> moved to a down state if we get a request to restart negotiations, so I
>> can see that my assumption may be incorrect.
> 
> It can, as described above, but it's not something that's commonly (or
> "ever") implemented, at least in my experience.  Renegotiation almost
> always leads to complete teardown.  (Depending on the vendor, some will
> start doing LCP Protocol-Reject on the NCP protocols like IPCP if you
> attempt that.)
> 
> This doesn't sound likely to me.  But, again, debug logs are your friend
> here.
> 
> Use the pppd 'debug' option.  By itself, that'll write the log
> information to syslog daemon.debug (be sure to redirect that to a file).
>   Or use the "logfile /path/to/file" option to write the messages to a
> file.  Then post those logs.
> 
> It's important to understand that PPP is just one protocol layer.  PPPoE
> itself is distinct, with its own messages and states.  The actions of
> PPPoE are seen by PPP as just underlying link up/down states -- very
> much like the signals PPP would get from a modem.
> 

I finally obtained the PPPoE logs from my customer.  I have redacted the IP 
addresses.  This is where I think we get the UP-->DOWN-->UP that is causing my 
issue.  Oddly, the customer has not experienced another event of this nature 
since then.

Here is the log with my annotations:

Executing pppd w/plugin(/etc/ppp/plugins/rp-pppoe.so): '/usr/sbin/pppd plugin 
/etc/ppp/plugins/rp-pppoe.so nic-wan0  unit 0 noipdefault noauth default-asyncmap 
defaultroute hide-password nodetach  mtu 1492 mru 1492 noaccomp nodeflate nopcomp 
novj novjccomp user w29ddnjt@bizf.ocn.ne.jp lcp-echo-interval 20 lcp-echo-failure 3 '
PPPd pid is 15175
Plugin /etc/ppp/plugins/rp-pppoe.so loaded.
RP-PPPoE plugin version 3.12 compiled against pppd 2.4.7
Connected to 00:12:e2:c0:0e:94 via interface wan0
Using interface ppp0
Connect: ppp0 <--> wan0
CHAP authentication succeeded
CHAP authentication succeeded
peer from calling number 00:12:E2:C0:0E:94 authorized
kernel does not support PPP filtering
sifdefaultroute(unit=0, ouraddr=XX.XX.XX.XX, gateway=YY.YY.YY.YY)
local  IP address XX.XX.XX.XX
remote IP address YY.YY.YY.YY

NOTE: This is where the first ip-up callout was triggered.

Connect time 0.1 minutes.
Sent 0 bytes, received 10 bytes.

NOTE: This is where I think the ip-down callout was triggered.

sifdefaultroute(unit=0, ouraddr=XX.XX.XX.XX, gateway=YY.YY.YY.YY)
local  IP address XX.XX.XX.XX
remote IP address YY.YY.YY.YY

NOTE: This is where I think the second ip-up callout was triggered.

Modem hangup
Connect time 1629.1 minutes.
Sent 572 bytes, received 452067 bytes.
Connection terminated.
PPPoE shutdown on interface 'ppp0', exit status is '16'

Thanks,

Patrick

Re: PPP cycling between UP and DOWN

[James Carlson]

On 2020-06-08 13:04, Patrick Mahan wrote:
> On 5/28/20 6:59 AM, James Carlson wrote:
>> That's the most likely case.  It would help to have _complete_ debug
>> logs showing what's happening.
[...]
>> It sounds like a stretch to me.  A debug log would show for sure, though.
[...]
>> This doesn't sound likely to me.  But, again, debug logs are your friend
>> here.
>>
>> Use the pppd 'debug' option.  By itself, that'll write the log
>> information to syslog daemon.debug (be sure to redirect that to a file).
>>   Or use the "logfile /path/to/file" option to write the messages to a
>> file.  Then post those logs.
[...]
> I finally obtained the PPPoE logs from my customer.  I have redacted the
> IP addresses.  This is where I think we get the UP-->DOWN-->UP that is
> causing my issue.  Oddly, the customer has not experienced another event
> of this nature since then.
> 
> Here is the log with my annotations:
> 
> Executing pppd w/plugin(/etc/ppp/plugins/rp-pppoe.so): '/usr/sbin/pppd
> plugin /etc/ppp/plugins/rp-pppoe.so nic-wan0  unit 0 noipdefault noauth
> default-asyncmap defaultroute hide-password nodetach  mtu 1492 mru 1492
> noaccomp nodeflate nopcomp novj novjccomp user w29ddnjt@bizf.ocn.ne.jp
> lcp-echo-interval 20 lcp-echo-failure 3 '

The one option that's not included in the list above is "debug".

> local  IP address XX.XX.XX.XX
> remote IP address YY.YY.YY.YY
> 
> NOTE: This is where the first ip-up callout was triggered.

This looks like normal start-up.

> Connect time 0.1 minutes.
> Sent 0 bytes, received 10 bytes.
> 
> NOTE: This is where I think the ip-down callout was triggered.

This looks like it could be a normal tear-down of some sort.  Without
debug information, we're not going to be able to say a whole lot more
about this.  (Crucially, a debug log would likely show which side
initiated the tear-down.)

> sifdefaultroute(unit=0, ouraddr=XX.XX.XX.XX, gateway=YY.YY.YY.YY)
> local  IP address XX.XX.XX.XX
> remote IP address YY.YY.YY.YY
> 
> NOTE: This is where I think the second ip-up callout was triggered.
> 
> Modem hangup
> Connect time 1629.1 minutes.
> Sent 572 bytes, received 452067 bytes.
> Connection terminated.
> PPPoE shutdown on interface 'ppp0', exit status is '16'

"Modem hangup" means that PPPoE, not PPP, shut down this link.  It would
be a completely wild guess -- I know the pppd code fairly well, but I
don't know the separate rp-pppoe code too well at all -- but it's
possible that this user was bit by the same stray PADT problem that
someone reported earlier on this list.  Or maybe not.

Assuming that "Modem hangup" is the problem we're worried about here
(I'm not 100% sure at this point), the next thing to do would be to
debug the PPPoE stuff.  The Roaring Penguin guys would probably know
more about that, but, personally, my first action would be to use
something like wireshark to capture the traffic on the Ethernet itself,
and use that to find out what happens to shut down the link.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>

Re: PPP cycling between UP and DOWN

[David Balažic]

On Mon, 8 Jun 2020 at 19:16, James Carlson <carlsonj@workingcode.com> wrote:
> "Modem hangup" means that PPPoE, not PPP, shut down this link.  It would
> be a completely wild guess -- I know the pppd code fairly well, but I
> don't know the separate rp-pppoe code too well at all -- but it's
> possible that this user was bit by the same stray PADT problem that
> someone reported earlier on this list.  Or maybe not.

RP-PPPOE has that bug fixed for quite a while.

(I reported that PADT problem)

Regards,
David

Re: PPP cycling between UP and DOWN

[Patrick Mahan]

On 6/8/20 10:15 AM, James Carlson wrote:
> On 2020-06-08 13:04, Patrick Mahan wrote:
>> On 5/28/20 6:59 AM, James Carlson wrote:
>>> That's the most likely case.  It would help to have _complete_ debug
>>> logs showing what's happening.
> [...]
>>> It sounds like a stretch to me.  A debug log would show for sure, though.
> [...]
>>> This doesn't sound likely to me.  But, again, debug logs are your friend
>>> here.
>>>
>>> Use the pppd 'debug' option.  By itself, that'll write the log
>>> information to syslog daemon.debug (be sure to redirect that to a file).
>>>    Or use the "logfile /path/to/file" option to write the messages to a
>>> file.  Then post those logs.
> [...]
>> I finally obtained the PPPoE logs from my customer.  I have redacted the
>> IP addresses.  This is where I think we get the UP-->DOWN-->UP that is
>> causing my issue.  Oddly, the customer has not experienced another event
>> of this nature since then.
>>
>> Here is the log with my annotations:
>>
>> Executing pppd w/plugin(/etc/ppp/plugins/rp-pppoe.so): '/usr/sbin/pppd
>> plugin /etc/ppp/plugins/rp-pppoe.so nic-wan0  unit 0 noipdefault noauth
>> default-asyncmap defaultroute hide-password nodetach  mtu 1492 mru 1492
>> noaccomp nodeflate nopcomp novj novjccomp user w29ddnjt@bizf.ocn.ne.jp
>> lcp-echo-interval 20 lcp-echo-failure 3 '
> 
> The one option that's not included in the list above is "debug".

Yes, I had requested that the debug option be added, but since we added it, there 
has not been another incident.

> 
>> local  IP address XX.XX.XX.XX
>> remote IP address YY.YY.YY.YY
>>
>> NOTE: This is where the first ip-up callout was triggered.
> 
> This looks like normal start-up.
> 
>> Connect time 0.1 minutes.
>> Sent 0 bytes, received 10 bytes.
>>
>> NOTE: This is where I think the ip-down callout was triggered.
> 
> This looks like it could be a normal tear-down of some sort.  Without
> debug information, we're not going to be able to say a whole lot more
> about this.  (Crucially, a debug log would likely show which side
> initiated the tear-down.)
> 

Understood.  And if we ever get this problem to occur again, I should have those 
logs.

>> sifdefaultroute(unit=0, ouraddr=XX.XX.XX.XX, gateway=YY.YY.YY.YY)
>> local  IP address XX.XX.XX.XX
>> remote IP address YY.YY.YY.YY
>>
>> NOTE: This is where I think the second ip-up callout was triggered.
>>
>> Modem hangup
>> Connect time 1629.1 minutes.
>> Sent 572 bytes, received 452067 bytes.
>> Connection terminated.
>> PPPoE shutdown on interface 'ppp0', exit status is '16'
> 
> "Modem hangup" means that PPPoE, not PPP, shut down this link.  It would
> be a completely wild guess -- I know the pppd code fairly well, but I
> don't know the separate rp-pppoe code too well at all -- but it's
> possible that this user was bit by the same stray PADT problem that
> someone reported earlier on this list.  Or maybe not.
> 
> Assuming that "Modem hangup" is the problem we're worried about here
> (I'm not 100% sure at this point), the next thing to do would be to
> debug the PPPoE stuff.  The Roaring Penguin guys would probably know
> more about that, but, personally, my first action would be to use
> something like wireshark to capture the traffic on the Ethernet itself,
> and use that to find out what happens to shut down the link.
> 

Sorry, no the "Modem hangup" here is expected.  Out tech support generally has a 
list of "try this" for these issues.  One of them was to IFDOWN the physical 
interface, wait 10s then IFUP.  We correctly caught the modem down and restarted.

No the issue I need to deal with is the UP-->DOWN-->UP cycle.  I am currently 
modifying the code to handle this issue a little more leniently, but I haven't 
figured out a way to validate my changes short of modifying the pppd to inject a 
rogue PADT packet.

Thanks,

Patrick

Re: PPP cycling between UP and DOWN

[Patrick Mahan]

On 6/8/20 2:32 PM, David Balažic wrote:
> On Mon, 8 Jun 2020 at 19:16, James Carlson <carlsonj@workingcode.com> wrote:
>> "Modem hangup" means that PPPoE, not PPP, shut down this link.  It would
>> be a completely wild guess -- I know the pppd code fairly well, but I
>> don't know the separate rp-pppoe code too well at all -- but it's
>> possible that this user was bit by the same stray PADT problem that
>> someone reported earlier on this list.  Or maybe not.
> 
> RP-PPPOE has that bug fixed for quite a while.
> 
> (I reported that PADT problem)

Okay, well we are moving to the latest RP-PPPOE and PPP versions on our new 
platform which uses the 4.14 kernel.  So that fix will at least be there in the 
future.

Thanks,

Patrick

Re: PPP cycling between UP and DOWN

[James Carlson]

On 6/8/20 6:51 PM, Patrick Mahan wrote:
> On 6/8/20 10:15 AM, James Carlson wrote:
>> On 2020-06-08 13:04, Patrick Mahan wrote:
>>> Connect time 0.1 minutes.
>>> Sent 0 bytes, received 10 bytes.
>>>
>>> NOTE: This is where I think the ip-down callout was triggered.
>>
>> This looks like it could be a normal tear-down of some sort.  Without
>> debug information, we're not going to be able to say a whole lot more
>> about this.  (Crucially, a debug log would likely show which side
>> initiated the tear-down.)
>>
> 
> Understood.  And if we ever get this problem to occur again, I should 
> have those logs.

If this were due to IPCP Terminate-Request from the peer, there should 
have been an "IPCP terminated by peer" message emitted.  (That's done at 
'info' severity level, just like "Connect time," so if you see one, 
you'll see the other.)

If LCP terminated, you should have seen "Connection terminated."

If it were a local signal, then you would have seen "Terminating on signal."

And, of course, lower layer shutdown can be indicated by "Hangup 
(SIGHUP)" or "Modem hangup," depending on whether we find out about the 
issue via a UNIX signal or through EOF on the file descriptor.

The fact that none of these appear is a bit puzzling.  It *could* be 
something the plug-in is doing, but I'm not at all sure at this point. 
(If we do find out what it is, and if it's something in pppd that's 
doing this, we should definitely add a log message for this case.)

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>