Starting dhcpcd terminates the established PPPoE connection

Starting dhcpcd terminates the established PPPoE connection

[Sven Kirmess]

My firewall runs LEAF Bering-uClibc 6.0.0, which comes with pppd 2.4.7
and dhcpcd 6.11.5. Most of the time IPv6 is working, but from time to
time I have the following really strange problem. The PPPoE connection
is established (with +ipv6 in /etc/ppp/options). But whenever I start
the dhcpcd, which should obtain IPv6 adresses through DHCPv6-PD, the
connection gets terminated.

From the logs it looks like the ISP terminates the connection (LCP
terminated by peer) because it wasn't able to serve me an IPv6 range
(DHCPv6 REPLY: NOPREFIX-AVAIL).

Does that make sense?

Is that a problem with my ISP?

Or is that a problem on my side? The problem started after I've
rebooted the firewall, maybe some state file did not survive the
reboot.

Sven


From /var/log/daemon.log:

Dec 25 02:26:55 kaldra dhcpcd[9062]: ppp0: unsupported interface family 00
Dec 25 02:26:55 kaldra dhcpcd[9062]: forked to background, child pid 9083
Dec 25 02:26:55 kaldra dhcpcd[9083]: DUID
00:01:00:01:1e:92:58:a5:00:0d:b9:40:7f:ec
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.100: IAID b9:40:7f:ee
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.100: IAID conflicts with one
assigned to em2.170
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.170: IAID b9:40:7f:ee
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.170: IAID conflicts with one
assigned to em2.100
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.191: IAID b9:40:7f:ee
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.191: IAID conflicts with one
assigned to em2.100
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.192: IAID b9:40:7f:ee
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.192: IAID conflicts with one
assigned to em2.100
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.193: IAID b9:40:7f:ee
Dec 25 02:26:55 kaldra dhcpcd[9083]: em2.193: IAID conflicts with one
assigned to em2.100
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: IAID 70:70:70:30
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: IAID 00:00:00:01
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: soliciting a DHCPv6 lease
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: soliciting an IPv6 router
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: Router Advertisement from
fe80::20e:d6ff:fea6:ec1b
Dec 25 02:26:55 kaldra dhcpcd[9083]: ppp0: adding address
2a02:200:2f00:91d:dd04:a113:6f76:82f4/64
Dec 25 02:26:56 kaldra dhcpcd[9083]: ppp0: DHCPv6 REPLY: NOPREFIX-AVAIL
Dec 25 02:26:56 kaldra dhcpcd[9083]: ppp0: carrier lost
Dec 25 02:26:56 kaldra dhcpcd[9083]: ppp0: deleting address
2a02:200:2f00:91d:dd04:a113:6f76:82f4/64
Dec 25 02:26:57 kaldra dhcpcd[9083]: ppp0: removing interface


From /var/log/ppp.log:

Dec 25 02:26:56 kaldra pppd[8185]: rcvd [LCP TermReq id=0x2]
Dec 25 02:26:56 kaldra pppd[8185]: LCP terminated by peer
Dec 25 02:26:56 kaldra pppd[8185]: Connect time 1.0 minutes.
Dec 25 02:26:56 kaldra pppd[8185]: Sent 470280 bytes, received 513340 bytes.
Dec 25 02:26:56 kaldra pppd[8185]: Script /etc/ppp/ip-down started (pid 9097)
Dec 25 02:26:56 kaldra pppd[8185]: Script /etc/ppp/ipv6-down started (pid 9100)
Dec 25 02:26:56 kaldra pppd[8185]: sent [LCP TermAck id=0x2]
Dec 25 02:26:56 kaldra pppd[8185]: Script /etc/ppp/ip-down finished
(pid 9097), status = 0x1
Dec 25 02:26:56 kaldra pppd[8185]: Script /etc/ppp/ipv6-down finished
(pid 9100), status = 0x1
Dec 25 02:26:57 kaldra pppd[8185]: rcvd [LCP TermReq id=0x8f]
Dec 25 02:26:57 kaldra pppd[8185]: sent [LCP TermAck id=0x8f]
Dec 25 02:26:57 kaldra pppd[8185]: Modem hangup
Dec 25 02:26:57 kaldra pppd[8185]: Connection terminated.
Dec 25 02:26:57 kaldra pppd[8185]: Connect time 1.0 minutes.
Dec 25 02:26:57 kaldra pppd[8185]: Sent 470280 bytes, received 513520 bytes.
Dec 25 02:26:57 kaldra pppd[8185]: Failed to disconnect PPPoE socket:
114 Operation already in progress

Re: Starting dhcpcd terminates the established PPPoE connection

[James Carlson]

On 12/27/2016 6:26 PM, Sven Kirmess wrote:
>>From /var/log/ppp.log:
> 
> Dec 25 02:26:56 kaldra pppd[8185]: rcvd [LCP TermReq id=0x2]
> Dec 25 02:26:56 kaldra pppd[8185]: LCP terminated by peer
> Dec 25 02:26:56 kaldra pppd[8185]: Connect time 1.0 minutes.

It wouldn't be a bad thing to see what led up to this point, but I
suspect there isn't much more information available on this side.  A
good implementation of PPP uses the optional disconnection message in
LCP Terminate-Request to report the reason why the connection is being
dropped.  Unfortunately, the PPP implementation used by your peer isn't
good, and it doesn't do that.

It's remotely possible that the disconnection is unrelated to DHCP and
that it's just coincidence.  That's why I suggested posting more of the
logs.  But I think it's just a very remote possibility.

I'm afraid that most likely means that you need to talk with your ISP
and find out if they have logs or error messages to share with you.  My
experience with most of these ISPs, though, is that there's nobody home
at the other end, and the only thing you can really do is quit and find
a better one.

Your mileage may vary.

> Dec 25 02:26:57 kaldra pppd[8185]: Failed to disconnect PPPoE socket:
> 114 Operation already in progress

Besides this apparently spurious error message, did the PPPoE client log
any sort of message about the disconnection?

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

Re: Starting dhcpcd terminates the established PPPoE connection

[Sven Kirmess]

Hi James,

Thanks for looking into this.

On Wed, Dec 28, 2016 at 6:20 PM, James Carlson <carlsonj@workingcode.com> wrote:

> It's remotely possible that the disconnection is unrelated to DHCP and
> that it's just coincidence.  That's why I suggested posting more of the
> logs.  But I think it's just a very remote possibility.

I've added the log files to dropbox. I've rebooted the system at 01:39
and at 01:59.

<https://www.dropbox.com/s/k6s70fzl7ee4o42/daemon.txt?dl=0>
<https://www.dropbox.com/s/1h6mqvcxvstvf4y/debug.txt?dl=0>
<https://www.dropbox.com/s/msg66lt19f95772/kern.txt?dl=0>
<https://www.dropbox.com/s/lnm6aw5fzskq0d4/ppp.txt?dl=0>
<https://www.dropbox.com/s/qxcx7wm4yj7qhr5/syslog.txt?dl=0>

I was able to bring the line back up after I've removed the ip-up
script that starts/stops dhcpcd.

> I'm afraid that most likely means that you need to talk with your ISP
> and find out if they have logs or error messages to share with you.  My
> experience with most of these ISPs, though, is that there's nobody home
> at the other end, and the only thing you can really do is quit and find
> a better one.
>
> Your mileage may vary.
>
>> Dec 25 02:26:57 kaldra pppd[8185]: Failed to disconnect PPPoE socket:
>> 114 Operation already in progress
>
> Besides this apparently spurious error message, did the PPPoE client log
> any sort of message about the disconnection?

I can't see anything.

Sven

Re: Starting dhcpcd terminates the established PPPoE connection

[James Carlson]

On 12/29/16 06:35, Sven Kirmess wrote:
> Hi James,
> 
> Thanks for looking into this.
> 
> On Wed, Dec 28, 2016 at 6:20 PM, James Carlson <carlsonj@workingcode.com> wrote:
> 
>> It's remotely possible that the disconnection is unrelated to DHCP and
>> that it's just coincidence.  That's why I suggested posting more of the
>> logs.  But I think it's just a very remote possibility.
> 
> I've added the log files to dropbox. I've rebooted the system at 01:39
> and at 01:59.
> 
> <https://www.dropbox.com/s/k6s70fzl7ee4o42/daemon.txt?dl=0>
> <https://www.dropbox.com/s/1h6mqvcxvstvf4y/debug.txt?dl=0>
> <https://www.dropbox.com/s/msg66lt19f95772/kern.txt?dl=0>
> <https://www.dropbox.com/s/lnm6aw5fzskq0d4/ppp.txt?dl=0>
> <https://www.dropbox.com/s/qxcx7wm4yj7qhr5/syslog.txt?dl=0>

I don't see much that's special going on there.  I still think the
problem is on the peer's side, not yours.

Does /libexec/dhcpcd-run-hooks do anything crazy, such as pkill?

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

Re: Starting dhcpcd terminates the established PPPoE connection

[Sven Kirmess]

On Thu, Dec 29, 2016 at 9:37 PM, James Carlson <carlsonj@workingcode.com> wrote:

> I don't see much that's special going on there.  I still think the
> problem is on the peer's side, not yours.

That's going to be much more difficult to get fixed.

> Does /libexec/dhcpcd-run-hooks do anything crazy, such as pkill?

I can't find anything.

Besides that, I've restarted dhcpcd and for now know it's working
again. Without a change on my side.

Thanks for your confirmation that it's probably not on my side.

Re: Starting dhcpcd terminates the established PPPoE connection

[James Carlson]

On 12/31/2016 8:45 AM, Sven Kirmess wrote:
> On Thu, Dec 29, 2016 at 9:37 PM, James Carlson <carlsonj@workingcode.com> wrote:
> 
>> I don't see much that's special going on there.  I still think the
>> problem is on the peer's side, not yours.
> 
> That's going to be much more difficult to get fixed.
> 
>> Does /libexec/dhcpcd-run-hooks do anything crazy, such as pkill?
> 
> I can't find anything.
> 
> Besides that, I've restarted dhcpcd and for now know it's working
> again. Without a change on my side.
> 
> Thanks for your confirmation that it's probably not on my side.
> 

One possibly interesting note is that I see LCP being renegotiated after
starting authentication.  That's a dead give-away that the other side
has a front-end device that tunnels the PPP traffic back to back-end
servers.

The reason it works sometimes and not at other times could be that you
sometimes hit a broken (or misconfigured) back-end server, and other
times you hit one that's ok.

It could also be that someone on their side noticed the errors and fixed
something.  You could be just that lucky.  :-/

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