Re: PPPoE Modem hangup after random time - how to debug?

["David Balažic" <xerces9@gmail.com>]

OK, next round.

First:
> Do you have ebtables?  Could you arrange to filter out packets like that?
> That would point to there being some kernel bug.
They seems to "arrive" only if the interface is put into promiscuous mode.
That is tcpdump  captures them unless I add the -p option.
I will recheck this to be sure.


The current disconnect:

 - output of  tcpdump -e -v -i eth1 vlan 3902 and  pppoed:

tcpdump: listening on eth1, link-type EN10MB (Ethernet), capture size
262144 bytes
17:34:34.805424 a4:7b:2c:9e:c7:44 (oui Unknown) > 44:4e:6d:fd:c7:39
(oui Unknown), ethertype 802.1Q (0x8100), length 60: vlan 3902, p 1,
ethertype PPPoE D, PPPoE PADT [ses 0x1]
17:34:34.815673 c4:3d:c7:90:ce:ed (oui Unknown) > a4:7b:2c:9e:c7:44
(oui Unknown), ethertype 802.1Q (0x8100), length 52: vlan 3902, p 0,
ethertype PPPoE D, PPPoE PADT [ses 0x1] [Host-Uniq 0x00003003]
[AC-Cookie 0xED****************************75]
tcpdump: pcap_loop: The interface went down
2 packets captured
2 packets received by filter
0 packets dropped by kernel

system logs:  logread | grep -v -E '(hostapd|dnsmasq)'


Sun Apr 26 14:40:26 2020 authpriv.info dropbear[22495]: Exit (root):
Disconnect received
Sun Apr 26 17:34:34 2020 daemon.notice pppd[12291]: Modem hangup
Sun Apr 26 17:34:34 2020 daemon.info pppd[12291]: Connect time 606.7 minutes.
Sun Apr 26 17:34:34 2020 daemon.info pppd[12291]: Sent 105754253
bytes, received 999814297 bytes.
Sun Apr 26 17:34:34 2020 daemon.notice netifd: Network device
'pppoe-wan' link is down
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]: Script
/lib/netifd/ppp-down started (pid 20230)
Sun Apr 26 17:34:34 2020 daemon.notice pppd[12291]: Connection terminated.
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]: Send PPPOE
Discovery V1T1 PADT session 0x1 length 28
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]:  dst
a4:XX:XX:XX:XX:44  src c4:XX:XX:XX:XX:ed
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]:  [host-uniq  00 00
30 03] [AC-cookie  ed XY XY XY XY XY XY XY XY XY XY XY XY XY XY 75]
Sun Apr 26 17:34:34 2020 daemon.info pppd[12291]: Sent PADT
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]: Waiting for 1 child
processes...
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]:   script
/lib/netifd/ppp-down, pid 20230
Sun Apr 26 17:34:34 2020 daemon.notice netifd: Interface 'wan' has
lost the connection
Sun Apr 26 17:34:34 2020 daemon.debug pppd[12291]: Script
/lib/netifd/ppp-down finished (pid 20230), status = 0x1
Sun Apr 26 17:34:34 2020 daemon.info pppd[12291]: Exit.
Sun Apr 26 17:34:35 2020 daemon.notice netifd: Interface 'wan' is now down
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.537261] eth1: link down
Sun Apr 26 17:34:35 2020 daemon.notice netifd: Interface 'wan' is disabled
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.567649] IPv6:
ADDRCONF(NETDEV_UP): eth1: link is not ready
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.574985] eth1: link
up (1000Mbps/Full duplex)
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.579700] IPv6:
ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Sun Apr 26 17:34:35 2020 daemon.notice netifd: Interface 'wan' is enabled
Sun Apr 26 17:34:35 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.645168] device eth1
left promiscuous mode
Sun Apr 26 17:34:35 2020 daemon.err insmod: module is already loaded - slhc
Sun Apr 26 17:34:35 2020 daemon.err insmod: module is already loaded -
ppp_generic
Sun Apr 26 17:34:35 2020 daemon.err insmod: module is already loaded - pppox
Sun Apr 26 17:34:35 2020 daemon.err insmod: module is already loaded - pppoe
Sun Apr 26 17:34:35 2020 daemon.info pppd[20289]: Plugin rp-pppoe.so loaded.
Sun Apr 26 17:34:35 2020 daemon.info pppd[20289]: RP-PPPoE plugin
version 3.8p compiled against pppd 2.4.7
Sun Apr 26 17:34:35 2020 daemon.notice pppd[20289]: pppd 2.4.7 started
by root, uid 0
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: Send PPPOE
Discovery V1T1 PADI session 0x0 length 12
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  dst
ff:ff:ff:ff:ff:ff  src c4:XX:XX:XX:XX:ed
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  [service-name]
[host-uniq  00 00 4f 41]
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: Recv PPPOE
Discovery V1T1 PADO session 0x0 length 51
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  dst
c4:XX:XX:XX:XX:ed  src a4:XX:XX:XX:XX:44
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  [service-name]
[AC-name SIMB_TABOR_BNG1] [host-uniq  00 00 4f 41] [AC-cookie  ed XY
XY XY XY XY XY XY XY XY XY XY XY XY XY 75]
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: Send PPPOE
Discovery V1T1 PADR session 0x0 length 32
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  dst
a4:XX:XX:XX:XX:44  src c4:XX:XX:XX:XX:ed
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  [service-name]
[host-uniq  00 00 4f 41] [AC-cookie  ed XY XY XY XY XY XY XY XY XY XY
XY XY XY XY 75]
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: Recv PPPOE
Discovery V1T1 PADS session 0x1 length 12
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  dst
c4:XX:XX:XX:XX:ed  src a4:XX:XX:XX:XX:44
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]:  [service-name]
[host-uniq  00 00 4f 41]
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: PADS: Service-Name: ''
Sun Apr 26 17:34:35 2020 daemon.info pppd[20289]: PPP session is 1
Sun Apr 26 17:34:35 2020 daemon.warn pppd[20289]: Connected to
a4:XX:XX:XX:XX:44 via interface eth1.3902
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: using channel 14
Sun Apr 26 17:34:35 2020 kern.info kernel: [605072.063661] pppoe-wan:
renamed from ppp0
Sun Apr 26 17:34:35 2020 daemon.info pppd[20289]: Renamed interface
ppp0 to pppoe-wan
Sun Apr 26 17:34:35 2020 daemon.info pppd[20289]: Using interface pppoe-wan
Sun Apr 26 17:34:35 2020 daemon.notice pppd[20289]: Connect: pppoe-wan
<--> eth1.3902
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: sent [LCP ConfReq
id=0x1 <mru 1492> <magic 0x5182441e>]
Sun Apr 26 17:34:35 2020 daemon.debug pppd[20289]: rcvd [LCP ConfAck
id=0x1 <mru 1492> <magic 0x5182441e>]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: sent [LCP ConfReq
id=0x1 <mru 1492> <magic 0x5182441e>]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: rcvd [LCP ConfAck
id=0x1 <mru 1492> <magic 0x5182441e>]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: rcvd [LCP ConfReq
id=0xc5 <mru 1492> <auth chap MD5> <magic 0x1ec8e8c8>]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: sent [LCP ConfAck
id=0xc5 <mru 1492> <auth chap MD5> <magic 0x1ec8e8c8>]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: sent [LCP EchoReq
id=0x0 magic=0x5182441e]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: rcvd [CHAP
Challenge id=0x1
<f*********************************************************************50>,
name = "SIMB_TABOR_BNG1"]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: sent [CHAP Response
id=0x1 <83****************************c4>, name = "username"]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: rcvd [LCP EchoRep
id=0x0 magic=0x1ec8e8c8]
Sun Apr 26 17:34:38 2020 daemon.debug pppd[20289]: rcvd [CHAP Success
id=0x1 "CHAP authentication success"]
Sun Apr 26 17:34:38 2020 daemon.info pppd[20289]: CHAP authentication
succeeded: CHAP authentication success
Sun Apr 26 17:34:38 2020 daemon.notice pppd[20289]: CHAP
authentication succeeded
Sun Apr 26 17:34:38 2020 daemon.notice pppd[20289]: peer from calling
number a4:XX:XX:XX:XX:44 authorized
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: sent [IPCP ConfReq
id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: rcvd [IPCP ConfReq
id=0xf4 <addr 94.127.WW.ZZ>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: sent [IPCP ConfAck
id=0xf4 <addr 94.127.WW.ZZ>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: rcvd [IPCP ConfNak
id=0x1 <addr 46.164.XX.YY> <ms-dns1 212.18.32.10> <ms-dns2
212.18.32.12>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: sent [IPCP ConfReq
id=0x2 <addr 46.164.XX.YY> <ms-dns1 212.18.32.10> <ms-dns2
212.18.32.12>]
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: rcvd [IPCP ConfAck
id=0x2 <addr 46.164.XX.YY> <ms-dns1 212.18.32.10> <ms-dns2
212.18.32.12>]
Sun Apr 26 17:34:39 2020 daemon.notice pppd[20289]: local  IP address
46.164.XX.YY
Sun Apr 26 17:34:39 2020 daemon.notice pppd[20289]: remote IP address
94.127.WW.ZZ
Sun Apr 26 17:34:39 2020 daemon.notice pppd[20289]: primary   DNS
address 212.18.32.10
Sun Apr 26 17:34:39 2020 daemon.notice pppd[20289]: secondary DNS
address 212.18.32.12
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: Script
/lib/netifd/ppp-up started (pid 20355)
Sun Apr 26 17:34:39 2020 daemon.notice netifd: Network device
'pppoe-wan' link is up
Sun Apr 26 17:34:39 2020 daemon.notice netifd: Interface 'wan' is now up
Sun Apr 26 17:34:39 2020 daemon.debug pppd[20289]: Script
/lib/netifd/ppp-up finished (pid 20355), status = 0x1
Sun Apr 26 17:34:39 2020 user.notice firewall: Reloading firewall due
to ifup of wan (pppoe-wan)
Sun Apr 26 17:34:42 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:45 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:48 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:51 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:54 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:34:57 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:35:00 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:35:03 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:35:06 2020 daemon.debug pppd[20289]: sent [IPV6CP
ConfReq id=0x1 <addr fe80::d035:60ed:928e:f741>]
Sun Apr 26 17:35:09 2020 daemon.warn pppd[20289]: IPV6CP: timeout
sending Config-Requests


The strange part is in the tcpdump there is a PADT sent to an
"unknown" MAC and my pppd responds. At least that is how I see it.

You think NOT putting the interface into promiscuous mode (done by
tcpdump) would prevent this?
Anyway, now I startted tcpdump with the -p option:  tcpdump -e -v -p
-i eth1 vlan 3902 and pppoed


On Sun, 26 Apr 2020 at 14:48, David Balažic <xerces9@gmail.com> wrote:
>
> On Sun, 26 Apr 2020 at 03:38, Michael Richardson <mcr@sandelman.ca> wrote:
> >
> >
> > David Balažic <xerces9@gmail.com> wrote:
> >     >> OK, more data:
> >     >> I started tcpdump with the -e option as suggested on openwrt forum:
> >     >> tcpdump -e -v -i eth1.3902 pppoed
> >     >>
> >     >> on disconnect, this was logged (times are UTC):
> >     >>
> >     >>
> >     >> tcpdump: listening on eth1.3902, link-type EN10MB (Ethernet), capture
> >     >> size 262144 bytes
> >     >> 18:23:09.204991 a4:7b:2c:9e:c7:44 (oui Unknown) > 44:4e:6d:fd:c7:39
> >     >> (oui Unknown), ethertype PPPoE D (0x8863), length 97: PPPoE PADO
> >     >> [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq
> >     >> 0x44************long_number******************************AA]
> >     >> [AC-Cookie ".5b************v"]
> >
> >     > Isnt this strange? The dst addr is not my router or any other known.
> >     > Also the Host-Uniq value is different.
> >     > As if is traffic meant for someone else.
> >
> > oh, I understand.
> > thank you for noting this.
> > So, it's as if you are getting a PPPoE message for someone else, and when
> > that happens, the interface is dying.
> > Is it always the same ethernet address?
>
> Yes,the same.
>
> > Do you have ebtables?  Could you arrange to filter out packets like that?
> > That would point to there being some kernel bug.
> >
> > Clearly, your ISP has some other bug that they are sending stuff down the
> > wrong pipe, but that could just be hash collisions that they assume are
> > "harmless".
>
> Those packets don't seem to be a problem. In the last connection, I
> received 15 of them and no reconnect.
>
> As suggested on OpenWRT, I removed a IPv6 wan device config that was
> running DHCPv6 on eth1.
>
> Then he connection was up for 45 hours before dropping. Could be a
> coincidence...
>
> I posted the logs at
> https://forum.openwrt.org/t/pppoe-disconnects-every-few-hours/61239/22
> (gmail wraps lines...)
>
> Regards,
> David