"Timeout waiting for PADO packets" until reboot

"Timeout waiting for PADO packets" until reboot

[David Gyimesi]

Hello

My parents have an FTTH connection with an Asus DSL-AC68U router which
runs linux and pppd version 2.4.7. The network devices are connected
to a UPS for stable power.

Options configured:
lcp-echo-interval 10
lcp-echo-failure 15
lcp-echo-adaptive

If there is a short, let's say only 10 minutes, outage between the
home and the ISP, the router prints
"pppd[17084]: Timeout waiting for PADO packets"
messages but it is able to re-establish the connection automatically
when the outage is resolved.

However if the outage is relatively longer the router just keeps printing
"pppd[17084]: Timeout waiting for PADO packets"
messages and even if the outage has been resolved the router is not
able to re-establish the PPPoE connection. However after a reboot the
router is able to establish the PPPoE connection without problem.

Because I am remote I am not able to access the router for
troubleshooting during outage.

Others have the same problem for example with OpenWrt where I also see
ppp version 2.4.7 is used
https://github.com/openwrt/openwrt/issues/7826


Would you please help what can be the issue and how to fix it?

Thank you!
Best regards
David

Re: "Timeout waiting for PADO packets" until reboot

[Michael Richardson]

[-- Attachment #1: Type: text/plain, Size: 1598 bytes --]


David Gyimesi <david6670@gmail.com> wrote:
    > If there is a short, let's say only 10 minutes, outage between the home
    > and the ISP, the router prints "pppd[17084]: Timeout waiting for PADO
    > packets" messages but it is able to re-establish the connection
    > automatically when the outage is resolved.

    > However if the outage is relatively longer the router just keeps
    > printing "pppd[17084]: Timeout waiting for PADO packets" messages and
    > even if the outage has been resolved the router is not able to
    > re-establish the PPPoE connection. However after a reboot the router is
    > able to establish the PPPoE connection without problem.

I experience the same thing.

What I think is that the DSL/PPPoE network simply forgets what your router's
MAC address is, and the router reboot sends something else that makes it all
work again.  Maybe because the virtual (L2) circuit is reastablished. That's
for the VDSL situation that I have.

FTTH has many implementations, some have overlays on top of the GPON.
The fact that you have PPPoE at all suggests that is the case.
Not everyone has GPON, even.

I don't have a solution, but I've looked for some clear indication.
My friendly third-party ISP has looked at their end as well, and when the
connection is in the bad state, they see nothing.  In between are the
completely incompetent incumbent telco.
(I live in Ottawa, Canada)

--
Michael Richardson <mcr+IETF@sandelman.ca>   . o O ( IPv6 IøT consulting )
           Sandelman Software Works Inc, Ottawa and Worldwide





[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 511 bytes --]

Re: "Timeout waiting for PADO packets" until reboot

[David Gyimesi]

Thanks Michael
Correct it is GPON. I also think the PPP server forgets the PPP client
after a while and doesn't send PADO packets anymore. But interestingly
a FreeBSD is able to re-establish the connection in the same
situation.

Previously I had the same issue with FreeBSD's MPD PPP client, after a
long outage I had to restart the system. After many failed attempts to
reproduce an outage and troubleshoot the issue, I contacted
developers. First they gave a workaround then later implemented a fix
in the MPD PPP client.
https://sourceforge.net/p/mpd/discussion/44693/thread/7a19aeb247/
Since then I had multiple long outages, but the MPD has been always
able to re-establish the connection, no system restart required
anymore. Just checked the uptime which is almost 400 days on the BSD
router.

My BSD router is having the same GPON and ISP as the Linux router,
therefore the recent multi hour outage affected both boxes at the same
time. While the Linux kept printing the "Timeout waiting for PADO
packets" messages the BSD router was able to recover after 943
recovery attempts, please find logs below.

I believe that if the FreeBSD MPD PPP client is able to solve the
situation and re-establish the connection without reboot, the Linux
pppd could definitely do the same.
Would you please help me with what logs I can collect or test I can do
which help developers to identify the gap in the pppd and fix it?

Thank you!
David

FreeBSD PPP client recovery log after multi hour outage:
Aug 6 02:03:47 ppp 31322 [wan_link0] Link: reconnection attempt 941
Aug 6 02:03:47 ppp 31322 [wan_link0] PPPoE: Connecting to ''
Aug 6 02:03:56 ppp 31322 [wan_link0] PPPoE connection timeout after 9 seconds
Aug 6 02:03:56 ppp 31322 [wan_link0] Link: DOWN event
Aug 6 02:03:56 ppp 31322 [wan_link0] LCP: Down event
Aug 6 02:03:56 ppp 31322 [wan_link0] Link: reconnection attempt 942 in 4 seconds
Aug 6 02:04:00 ppp 31322 [wan_link0] Link: reconnection attempt 942
Aug 6 02:04:00 ppp 31322 [wan_link0] PPPoE: Connecting to ''
Aug 6 02:04:09 ppp 31322 [wan_link0] PPPoE connection timeout after 9 seconds
Aug 6 02:04:09 ppp 31322 [wan_link0] Link: DOWN event
Aug 6 02:04:09 ppp 31322 [wan_link0] LCP: Down event
Aug 6 02:04:09 ppp 31322 [wan_link0] Link: reconnection attempt 943 in 4 seconds
Aug 6 02:04:13 ppp 31322 [wan_link0] Link: reconnection attempt 943
Aug 6 02:04:13 ppp 31322 [wan_link0] PPPoE: Connecting to ''
Aug 6 02:04:19 ppp 31322 PPPoE: rec'd ACNAME "bng2.eqxsy4.fl"
Aug 6 02:04:19 ppp 31322 [wan_link0] PPPoE: connection successful
Aug 6 02:04:19 ppp 31322 [wan_link0] Link: UP event
Aug 6 02:04:19 ppp 31322 [wan_link0] LCP: Up event
Aug 6 02:04:19 ppp 31322 [wan_link0] LCP: state change Starting --> Req-Sent
Aug 6 02:04:19 ppp 31322 [wan_link0] LCP: SendConfigReq #115
Aug 6 02:04:19 ppp 31322 [wan_link0] PROTOCOMP
Aug 6 02:04:19 ppp 31322 [wan_link0] MRU 1492
Aug 6 02:04:19 ppp 31322 [wan_link0] MAGICNUM 0x01f16262
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: rec'd Configure Request #43 (Req-Sent)
Aug 6 02:04:20 ppp 31322 [wan_link0] MRU 1492
Aug 6 02:04:20 ppp 31322 [wan_link0] AUTHPROTO PAP
Aug 6 02:04:20 ppp 31322 [wan_link0] MAGICNUM 0x52b45814
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: SendConfigAck #43
Aug 6 02:04:20 ppp 31322 [wan_link0] MRU 1492
Aug 6 02:04:20 ppp 31322 [wan_link0] AUTHPROTO PAP
Aug 6 02:04:20 ppp 31322 [wan_link0] MAGICNUM 0x52b45814
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: state change Req-Sent --> Ack-Sent
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: rec'd Configure Ack #115 (Ack-Sent)
Aug 6 02:04:20 ppp 31322 [wan_link0] PROTOCOMP
Aug 6 02:04:20 ppp 31322 [wan_link0] MRU 1492
Aug 6 02:04:20 ppp 31322 [wan_link0] MAGICNUM 0x01f16262
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: state change Ack-Sent --> Opened
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: auth: peer wants PAP, I want nothing
Aug 6 02:04:20 ppp 31322 [wan_link0] PAP: using authname "fgjo844gfh9@ox.com"
Aug 6 02:04:20 ppp 31322 [wan_link0] PAP: sending REQUEST #1 len: 46
Aug 6 02:04:20 ppp 31322 [wan_link0] LCP: LayerUp
Aug 6 02:04:21 ppp 31322 [wan_link0] PAP: rec'd ACK #1 len: 5
Aug 6 02:04:21 ppp 31322 [wan_link0] LCP: authorization successful
Aug 6 02:04:21 ppp 31322 [wan_link0] Link: Matched action 'bundle "wan" ""'
Aug 6 02:04:21 ppp 31322 [wan_link0] Link: Join bundle "wan"
Aug 6 02:04:21 ppp 31322 [wan] Bundle: Status update: up 1 link, total
bandwidth 64000 bps
Aug 6 02:04:21 ppp 31322 [wan] IPCP: Open event
Aug 6 02:04:21 ppp 31322 [wan] IPCP: state change Initial --> Starting
Aug 6 02:04:21 ppp 31322 [wan] IPCP: LayerStart
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: Open event
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: state change Initial --> Starting
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: LayerStart
Aug 6 02:04:21 ppp 31322 [wan] IPCP: Up event
Aug 6 02:04:21 ppp 31322 [wan] IPCP: state change Starting --> Req-Sent
Aug 6 02:04:21 ppp 31322 [wan] IPCP: SendConfigReq #146
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 6 02:04:21 ppp 31322 [wan] PRIDNS 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan] SECDNS 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: Up event
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: state change Starting --> Req-Sent
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: SendConfigReq #215
Aug 6 02:04:21 ppp 31322 [wan] IPCP: rec'd Configure Request #166 (Req-Sent)
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 220.158.188.4
Aug 6 02:04:21 ppp 31322 [wan] 220.158.188.4 is OK
Aug 6 02:04:21 ppp 31322 [wan] IPCP: SendConfigAck #166
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 220.158.188.4
Aug 6 02:04:21 ppp 31322 [wan] IPCP: state change Req-Sent --> Ack-Sent
Aug 6 02:04:21 ppp 31322 [wan] IPCP: rec'd Configure Reject #146 (Ack-Sent)
Aug 6 02:04:21 ppp 31322 [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 6 02:04:21 ppp 31322 [wan] IPCP: SendConfigReq #147
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan] PRIDNS 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan] SECDNS 0.0.0.0
Aug 6 02:04:21 ppp 31322 [wan_link0] LCP: rec'd Protocol Reject #44 (Opened)
Aug 6 02:04:21 ppp 31322 [wan_link0] LCP: protocol IPV6CP was rejected
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: protocol was rejected by peer
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: state change Req-Sent --> Stopped
Aug 6 02:04:21 ppp 31322 [wan] IPV6CP: LayerFinish
Aug 6 02:04:21 ppp 31322 [wan] IPCP: rec'd Configure Nak #147 (Ack-Sent)
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 160.202.143.224
Aug 6 02:04:21 ppp 31322 [wan] 160.202.143.224 is OK
Aug 6 02:04:21 ppp 31322 [wan] PRIDNS 1.1.1.1
Aug 6 02:04:21 ppp 31322 [wan] SECDNS 8.8.8.8
Aug 6 02:04:21 ppp 31322 [wan] IPCP: SendConfigReq #148
Aug 6 02:04:21 ppp 31322 [wan] IPADDR 160.202.143.224
Aug 6 02:04:21 ppp 31322 [wan] PRIDNS 1.1.1.1
Aug 6 02:04:21 ppp 31322 [wan] SECDNS 8.8.8.8
Aug 6 02:04:22 ppp 31322 [wan] IPCP: rec'd Configure Ack #148 (Ack-Sent)
Aug 6 02:04:22 ppp 31322 [wan] IPADDR 160.202.143.224
Aug 6 02:04:22 ppp 31322 [wan] PRIDNS 1.1.1.1
Aug 6 02:04:22 ppp 31322 [wan] SECDNS 8.8.8.8
Aug 6 02:04:22 ppp 31322 [wan] IPCP: state change Ack-Sent --> Opened
Aug 6 02:04:22 ppp 31322 [wan] IPCP: LayerUp
Aug 6 02:04:22 ppp 31322 [wan] 160.202.143.224 -> 220.158.188.4
Aug 6 02:04:23 ppp 31322 [wan] IFACE: Up event
Aug 6 02:04:23 ppp 31322 [wan] IFACE: Rename interface ng0 to pppoe0
Aug 6 02:04:23 ppp 31322 [wan] IFACE: Add description "WAN"

On Fri, Aug 11, 2023 at 2:40 AM Michael Richardson <mcr@sandelman.ca> wrote:
>
>
> David Gyimesi <david6670@gmail.com> wrote:
>     > If there is a short, let's say only 10 minutes, outage between the home
>     > and the ISP, the router prints "pppd[17084]: Timeout waiting for PADO
>     > packets" messages but it is able to re-establish the connection
>     > automatically when the outage is resolved.
>
>     > However if the outage is relatively longer the router just keeps
>     > printing "pppd[17084]: Timeout waiting for PADO packets" messages and
>     > even if the outage has been resolved the router is not able to
>     > re-establish the PPPoE connection. However after a reboot the router is
>     > able to establish the PPPoE connection without problem.
>
> I experience the same thing.
>
> What I think is that the DSL/PPPoE network simply forgets what your router's
> MAC address is, and the router reboot sends something else that makes it all
> work again.  Maybe because the virtual (L2) circuit is reastablished. That's
> for the VDSL situation that I have.
>
> FTTH has many implementations, some have overlays on top of the GPON.
> The fact that you have PPPoE at all suggests that is the case.
> Not everyone has GPON, even.
>
> I don't have a solution, but I've looked for some clear indication.
> My friendly third-party ISP has looked at their end as well, and when the
> connection is in the bad state, they see nothing.  In between are the
> completely incompetent incumbent telco.
> (I live in Ottawa, Canada)
>
> --
> Michael Richardson <mcr+IETF@sandelman.ca>   . o O ( IPv6 IøT consulting )
>            Sandelman Software Works Inc, Ottawa and Worldwide
>
>
>
>