PPPoE disconnects every few hours

The logs were filled with

daemon.err odhcp6c[32048]: Failed to send DHCPV6 message to ff02::1:2 (Permission denied)

(every 120 seconds)
so I removed it from /etc/config/network

Hi!

It lasted longer (2685 minutes, almost 45 hours), but then disconnected again. The logs (with more context this time):

Sun Apr 26 02:06:34 2020 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 10:XX:XX:XX:XX:aa
Sun Apr 26 02:06:34 2020 daemon.info hostapd: wlan0: STA 10:XX:XX:XX:XX:aa IEEE 802.11: disassociated due to inactivity
Sun Apr 26 02:06:35 2020 daemon.info hostapd: wlan0: STA 10:XX:XX:XX:XX:aa IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Sun Apr 26 02:08:23 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.197 14:XX:XX:XX:XX:43
Sun Apr 26 02:08:23 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.197 14:XX:XX:XX:XX:43 XXXXX-tablet
Sun Apr 26 04:48:39 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.193 58:XX:XX:XX:XX:b9
Sun Apr 26 04:48:39 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.193 58:XX:XX:XX:XX:b9 StarJupiter
Sun Apr 26 05:24:22 2020 daemon.info dnsmasq[1565]: read /etc/hosts - 4 addresses
Sun Apr 26 05:24:22 2020 daemon.info dnsmasq[1565]: read /tmp/hosts/odhcpd - 1 addresses
Sun Apr 26 05:24:22 2020 daemon.info dnsmasq[1565]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sun Apr 26 05:24:22 2020 daemon.info dnsmasq-dhcp[1565]: read /etc/ethers - 0 addresses
Sun Apr 26 06:28:56 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.111 b4:XX:XX:XX:XX:63
Sun Apr 26 06:28:56 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.111 b4:XX:XX:XX:XX:63 HUAWEI_XXXXXXXXb6
Sun Apr 26 06:49:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.225 80:XX:XX:XX:XX:ac
Sun Apr 26 06:49:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.225 80:XX:XX:XX:XX:ac NPXXXXXXAC
Sun Apr 26 07:27:47 2020 daemon.notice pppd[13073]: Modem hangup
Sun Apr 26 07:27:47 2020 daemon.info pppd[13073]: Connect time 2685.2 minutes.
Sun Apr 26 07:27:47 2020 daemon.info pppd[13073]: Sent 729073864 bytes, received 3334049944 bytes.
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]: Script /lib/netifd/ppp-down started (pid 12229)
Sun Apr 26 07:27:47 2020 daemon.notice pppd[13073]: Connection terminated.
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]: Send PPPOE Discovery V1T1 PADT session 0x1 length 28
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]:  dst a4:XX:XX:XX:XX:44  src c4:XX:XX:XX:XX:ed
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]:  [host-uniq  00 00 33 11] [AC-cookie  ed XY XY XY XY XY XY XY XY XY XY XY XY XY XY 75]
Sun Apr 26 07:27:47 2020 daemon.info pppd[13073]: Sent PADT
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]: Waiting for 1 child processes...
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]:   script /lib/netifd/ppp-down, pid 12229
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Interface 'wan' has lost the connection
Sun Apr 26 07:27:47 2020 daemon.warn dnsmasq[1565]: no servers found in /tmp/resolv.conf.auto, will retry
Sun Apr 26 07:27:47 2020 daemon.debug pppd[13073]: Script /lib/netifd/ppp-down finished (pid 12229), status = 0x1
Sun Apr 26 07:27:47 2020 daemon.info pppd[13073]: Exit.
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Interface 'wan' is now down
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.315207] device eth1 left promiscuous mode
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.336744] device eth1.3902 left promiscuous mode
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.357548] eth1: link down
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Interface 'wan' is disabled
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.382817] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.390113] eth1: link up (1000Mbps/Full duplex)
Sun Apr 26 07:27:47 2020 kern.info kernel: [568664.434812] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Interface 'wan' is enabled
Sun Apr 26 07:27:47 2020 daemon.notice netifd: Interface 'wan' is setting up now
Sun Apr 26 07:27:47 2020 daemon.err insmod: module is already loaded - slhc
Sun Apr 26 07:27:47 2020 daemon.err insmod: module is already loaded - ppp_generic
Sun Apr 26 07:27:47 2020 daemon.err insmod: module is already loaded - pppox
Sun Apr 26 07:27:47 2020 daemon.err insmod: module is already loaded - pppoe
Sun Apr 26 07:27:48 2020 daemon.info pppd[12291]: Plugin rp-pppoe.so loaded.
Sun Apr 26 07:27:48 2020 daemon.info pppd[12291]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sun Apr 26 07:27:48 2020 daemon.notice pppd[12291]: pppd 2.4.7 started by root, uid 0
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  dst ff:ff:ff:ff:ff:ff  src c4:XX:XX:XX:XX:ed
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  [service-name] [host-uniq  00 00 30 03]
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 51
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  dst c4:XX:XX:XX:XX:ed  src a4:XX:XX:XX:XX:44
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  [service-name] [AC-name SIMB_TABOR_BNG1] [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 07:27:48 2020 daemon.debug pppd[12291]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  dst a4:XX:XX:XX:XX:44  src c4:XX:XX:XX:XX:ed
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  [service-name] [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 07:27:48 2020 daemon.debug pppd[12291]: Recv PPPOE Discovery V1T1 PADS session 0x1 length 12
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  dst c4:XX:XX:XX:XX:ed  src a4:XX:XX:XX:XX:44
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]:  [service-name] [host-uniq  00 00 30 03]
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: PADS: Service-Name: ''
Sun Apr 26 07:27:48 2020 daemon.info pppd[12291]: PPP session is 1
Sun Apr 26 07:27:48 2020 daemon.warn pppd[12291]: Connected to a4:XX:XX:XX:XX:44 via interface eth1.3902
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: using channel 13
Sun Apr 26 07:27:48 2020 kern.info kernel: [568664.916849] pppoe-wan: renamed from ppp0
Sun Apr 26 07:27:48 2020 daemon.info pppd[12291]: Renamed interface ppp0 to pppoe-wan
Sun Apr 26 07:27:48 2020 daemon.info pppd[12291]: Using interface pppoe-wan
Sun Apr 26 07:27:48 2020 daemon.notice pppd[12291]: Connect: pppoe-wan <--> eth1.3902
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x899f5a8a>]
Sun Apr 26 07:27:48 2020 daemon.debug pppd[12291]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x899f5a8a>]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x899f5a8a>]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x899f5a8a>]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: rcvd [LCP ConfReq id=0x5 <mru 1492> <auth chap MD5> <magic 0x51d7b53f>]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: sent [LCP ConfAck id=0x5 <mru 1492> <auth chap MD5> <magic 0x51d7b53f>]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: sent [LCP EchoReq id=0x0 magic=0x899f5a8a]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: rcvd [CHAP Challenge id=0x1 <e8****************************************************************************************************************fd>, name = "SIMB_TABOR_BNG1"]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: sent [CHAP Response id=0x1 <3a****************************52>, name = "username"]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: rcvd [LCP EchoRep id=0x0 magic=0x51d7b53f]
Sun Apr 26 07:27:51 2020 daemon.debug pppd[12291]: rcvd [CHAP Success id=0x1 "CHAP authentication success"]
Sun Apr 26 07:27:51 2020 daemon.info pppd[12291]: CHAP authentication succeeded: CHAP authentication success
Sun Apr 26 07:27:51 2020 daemon.notice pppd[12291]: CHAP authentication succeeded
Sun Apr 26 07:27:51 2020 daemon.notice pppd[12291]: peer from calling number A4:XX:XX:XX:XX:44 authorized
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: 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 07:27:52 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::****:****:****:618d>]
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: rcvd [IPCP ConfReq id=0xa8 <addr 94.XX.YY.0>]
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: sent [IPCP ConfAck id=0xa8 <addr 94.XX.YY.0>]
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: rcvd [IPCP ConfNak id=0x1 <addr 46.XX.YY.17> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: sent [IPCP ConfReq id=0x2 <addr 46.XX.YY.17> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: rcvd [IPCP ConfAck id=0x2 <addr 46.XX.YY.17> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Sun Apr 26 07:27:52 2020 daemon.notice pppd[12291]: local  IP address 46.XX.YY.17
Sun Apr 26 07:27:52 2020 daemon.notice pppd[12291]: remote IP address 94.XX.YY.0
Sun Apr 26 07:27:52 2020 daemon.notice pppd[12291]: primary   DNS address 212.18.32.10
Sun Apr 26 07:27:52 2020 daemon.notice pppd[12291]: secondary DNS address 212.18.32.12
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: Script /lib/netifd/ppp-up started (pid 12357)
Sun Apr 26 07:27:52 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Sun Apr 26 07:27:52 2020 daemon.notice netifd: Interface 'wan' is now up
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: reading /tmp/resolv.conf.auto
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain test
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain onion
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain localhost
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain local
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain invalid
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain bind
Sun Apr 26 07:27:52 2020 daemon.debug pppd[12291]: Script /lib/netifd/ppp-up finished (pid 12357), status = 0x1
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using local addresses only for domain lan
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using nameserver 212.18.32.10#53
Sun Apr 26 07:27:52 2020 daemon.info dnsmasq[1565]: using nameserver 212.18.32.12#53
Sun Apr 26 07:27:52 2020 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Sun Apr 26 07:27:55 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:27:58 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:01 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:04 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:07 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:10 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:13 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:16 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:19 2020 daemon.debug pppd[12291]: sent [IPV6CP ConfReq id=0x1 <addr fe80::2c4c:f4e9:11dd:618d>]
Sun Apr 26 07:28:22 2020 daemon.warn pppd[12291]: IPV6CP: timeout sending Config-Requests
Sun Apr 26 07:39:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.197 14:XX:XX:XX:XX:43
Sun Apr 26 07:39:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.197 14:XX:XX:XX:XX:43 XXXXX-tablet

Two more details:

  • I run a ping job in background (one ping every second). The last successful ping was at 07:27:46, the next 5 gave "ping: sendto: Network unreachable" and then on 07:27:52 and later it was OK again.
    So the connection worked fine up to the moment it dropped. There were no lost packets or timeouts.

  • the ISP stated that removing (and replacing with own) their router is not a supported configuration

Another 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

Please double-check that the interface is not in promiscuous mode without tcpdump.

Currently it is, but, according to logs, it wasn't when two disconnects happened:

logread  | grep romisc
Sun Apr 26 17:34:35 2020 kern.info kernel: [605071.645168] device eth1 left promiscuous mode
Sun Apr 26 22:17:59 2020 kern.info kernel: [622075.896599] device eth1 entered promiscuous mode

I had two disconnects between those two. The last line is because I run tcpdump again.

As per https://dianne.skoll.ca/pipermail/rp-pppoe/2020q2/000573.html
can someone please check if OpenWRT uses the "correct" code?

I'm lost in all those ppp components.

Also:
on the linux-ppp mail list they suggested I monitor the network with rtmon which seems to be part of the
iproute2 package. Neither is installed and I don't see where I could get them. Help?

OK, the ip command is in the ip-full package and rtmon is not really needed, so this part is solved.

Next disconnect (at 06:40:31):

NOTE: c4:XX:XX:XX:XX:ed is my wan interfaces MAC address

tcpdump -e -v -i eth1 vlan 3902 and pppoed

tcpdump: listening on eth1, link-type EN10MB (Ethernet), capture size 262144 bytes
** several PADO and PADS packet sent from server/AC to 44:4e:6d:fd:c7:39 before this, during the day **
05:03:44.348738 a4:7b:2c:9e:c7:44 (oui Unknown) > 00:0f:94:ef:64:e0 (oui Unknown), ethertype 802.1Q (0x8100), length 75: vlan 3902, p 1, ethertype PPPoE D, PPPoE PADO [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq 0x960B0000] [AC-Cookie 0xDCC3248D61A5D76C7C1DD4138431B17C]
06:40:27.668095 a4:7b:2c:9e:c7:44 (oui Unknown) > 44:4e:6d:fd:c7:39 (oui Unknown), ethertype 802.1Q (0x8100), length 101: vlan 3902, p 1, ethertype PPPoE D, PPPoE PADO [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq 0x444E6DFDC739AAAAAAAA92000000AAAAAAAA4621426F78202020AAAAAAAA] [AC-Cookie ".5b.u...~.F.mlKv"]
06:40:27.674078 a4:7b:2c:9e:c7:44 (oui Unknown) > 44:4e:6d:fd:c7:39 (oui Unknown), ethertype 802.1Q (0x8100), length 62: vlan 3902, p 1, ethertype PPPoE D, PPPoE PADS [ses 0x1] [Service-Name] [Host-Uniq 0x444E6DFDC739AAAAAAAA92000000AAAAAAAA4621426F78202020AAAAAAAA]
06:40:30.552119 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]
06:40:31.158067 c4:XX:XX:XX:XX: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 0x000057CF] [AC-Cookie 0xED891159D8A73577F9B098A2E3E36875]
tcpdump: pcap_loop: The interface went down
12 packets captured
12 packets received by filter
0 packets dropped by kernel

ip monitor link


[2020-04-29 06:40:30] 47: pppoe-wan: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc fq_codel state DOWN group default
[2020-04-29 06:40:30]     link/ppp
[2020-04-29 06:40:31] Deleted 47: pppoe-wan: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default
[2020-04-29 06:40:31]     link/ppp
[2020-04-29 06:40:31] 46: eth1.3902@eth1: <BROADCAST,MULTICAST> mtu 1500 qdisc noqueue state DOWN group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] Deleted 46: eth1.3902@eth1: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST> mtu 1500 qdisc fq_codel state DOWN group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 48: eth1.3902@eth1: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 48: eth1.3902@eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 06:40:31]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:31] 49: ppp0: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN group default
[2020-04-29 06:40:31]     link/ppp
[2020-04-29 06:40:31] 49: pppoe-wan: <POINTOPOINT,MULTICAST,NOARP> mtu 1500 qdisc noop state DOWN group default
[2020-04-29 06:40:31]     link/ppp
[2020-04-29 06:40:32] 48: eth1.3902@eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default
[2020-04-29 06:40:32]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 06:40:34] 49: pppoe-wan: <POINTOPOINT,MULTICAST,NOARP> mtu 1492 qdisc noop state DOWN group default
[2020-04-29 06:40:34]     link/ppp
[2020-04-29 06:40:35] 49: pppoe-wan: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc fq_codel state UNKNOWN group default
[2020-04-29 06:40:35]     link/ppp

syslog:


Wed Apr 29 02:36:07 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.197 XX:XX:XX:XX:XX:XX
Wed Apr 29 02:36:07 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.197 XX:XX:XX:XX:XX:XX ffoo
Wed Apr 29 05:21:53 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.111 XX:XX:XX:XX:XX:XX
Wed Apr 29 05:21:53 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.111 XX:XX:XX:XX:XX:XX bar
Wed Apr 29 05:53:34 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.217 XX:XX:XX:XX:XX:XX
Wed Apr 29 05:53:34 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.217 XX:XX:XX:XX:XX:XX baz
Wed Apr 29 06:01:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.225 XX:XX:XX:XX:XX:XX
Wed Apr 29 06:01:46 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.225 XX:XX:XX:XX:XX:XX foobar
Wed Apr 29 06:36:11 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.193 XX:XX:XX:XX:XX:XX
Wed Apr 29 06:36:11 2020 daemon.info dnsmasq-dhcp[1565]: DHCPACK(br-lan) 192.168.1.193 XX:XX:XX:XX:XX:XX barfoo
Wed Apr 29 06:40:30 2020 daemon.notice pppd[22479]: Modem hangup
Wed Apr 29 06:40:30 2020 daemon.info pppd[22479]: Connect time 2351.5 minutes.
Wed Apr 29 06:40:30 2020 daemon.info pppd[22479]: Sent 524878898 bytes, received 2649683636 bytes.
Wed Apr 29 06:40:30 2020 daemon.notice netifd: Network device 'pppoe-wan' link is down
Wed Apr 29 06:40:30 2020 daemon.debug pppd[22479]: Script /lib/netifd/ppp-down started (pid 9434)
Wed Apr 29 06:40:31 2020 daemon.notice pppd[22479]: Connection terminated.
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]: Send PPPOE Discovery V1T1 PADT session 0x1 length 28
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]:  dst a4:7b:2c:9e:c7:44  src c4:XX:XX:XX:XX:ed
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]:  [host-uniq  00 00 57 cf] [AC-cookie  ed 89 11 59 d8 a7 35 77 f9 b0 98 a2 e3 e3 68 75]
Wed Apr 29 06:40:31 2020 daemon.info pppd[22479]: Sent PADT
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]: Waiting for 1 child processes...
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]:   script /lib/netifd/ppp-down, pid 9434
Wed Apr 29 06:40:31 2020 daemon.notice netifd: Interface 'wan' has lost the connection
Wed Apr 29 06:40:31 2020 daemon.warn dnsmasq[1565]: no servers found in /tmp/resolv.conf.auto, will retry
Wed Apr 29 06:40:31 2020 daemon.debug pppd[22479]: Script /lib/netifd/ppp-down finished (pid 9434), status = 0x1
Wed Apr 29 06:40:31 2020 daemon.info pppd[22479]: Exit.
Wed Apr 29 06:40:31 2020 daemon.notice netifd: Interface 'wan' is now down
Wed Apr 29 06:40:31 2020 kern.info kernel: [825025.766137] IPv6: ADDRCONF(NETDEV_UP): eth1.3902: link is not ready
Wed Apr 29 06:40:31 2020 kern.info kernel: [825025.781197] eth1: link down
Wed Apr 29 06:40:31 2020 daemon.notice netifd: Interface 'wan' is disabled
Wed Apr 29 06:40:31 2020 kern.info kernel: [825025.815043] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
Wed Apr 29 06:40:31 2020 kern.info kernel: [825025.822423] eth1: link up (1000Mbps/Full duplex)
Wed Apr 29 06:40:31 2020 kern.info kernel: [825025.844083] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
Wed Apr 29 06:40:31 2020 daemon.notice netifd: Interface 'wan' is enabled
Wed Apr 29 06:40:31 2020 daemon.notice netifd: Interface 'wan' is setting up now
Wed Apr 29 06:40:31 2020 kern.info kernel: [825026.010950] device eth1 left promiscuous mode
Wed Apr 29 06:40:31 2020 daemon.err insmod: module is already loaded - slhc
Wed Apr 29 06:40:31 2020 daemon.err insmod: module is already loaded - ppp_generic
Wed Apr 29 06:40:31 2020 daemon.err insmod: module is already loaded - pppox
Wed Apr 29 06:40:31 2020 daemon.err insmod: module is already loaded - pppoe
Wed Apr 29 06:40:31 2020 daemon.info pppd[9495]: Plugin rp-pppoe.so loaded.
Wed Apr 29 06:40:31 2020 daemon.info pppd[9495]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Wed Apr 29 06:40:31 2020 daemon.notice pppd[9495]: pppd 2.4.7 started by root, uid 0
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  dst ff:ff:ff:ff:ff:ff  src c4:XX:XX:XX:XX:ed
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  [service-name] [host-uniq  00 00 25 17]
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 51
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  dst c4:XX:XX:XX:XX:ed  src a4:7b:2c:9e:c7:44
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  [service-name] [AC-name SIMB_TABOR_BNG1] [host-uniq  00 00 25 17] [AC-cookie  ed 89 11 59 d8 a7 35 77 f9 b0 98 a2 e3 e3 68 75]
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: Send PPPOE Discovery V1T1 PADR session 0x0 length 32
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  dst a4:7b:2c:9e:c7:44  src c4:XX:XX:XX:XX:ed
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  [service-name] [host-uniq  00 00 25 17] [AC-cookie  ed 89 11 59 d8 a7 35 77 f9 b0 98 a2 e3 e3 68 75]
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: Recv PPPOE Discovery V1T1 PADS session 0x1 length 12
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  dst c4:XX:XX:XX:XX:ed  src a4:7b:2c:9e:c7:44
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]:  [service-name] [host-uniq  00 00 25 17]
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: PADS: Service-Name: ''
Wed Apr 29 06:40:31 2020 daemon.info pppd[9495]: PPP session is 1
Wed Apr 29 06:40:31 2020 daemon.warn pppd[9495]: Connected to a4:7b:2c:9e:c7:44 via interface eth1.3902
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: using channel 20
Wed Apr 29 06:40:31 2020 kern.info kernel: [825026.248151] pppoe-wan: renamed from ppp0
Wed Apr 29 06:40:31 2020 daemon.info pppd[9495]: Renamed interface ppp0 to pppoe-wan
Wed Apr 29 06:40:31 2020 daemon.info pppd[9495]: Using interface pppoe-wan
Wed Apr 29 06:40:31 2020 daemon.notice pppd[9495]: Connect: pppoe-wan <--> eth1.3902
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0x5455b2ef>]
Wed Apr 29 06:40:31 2020 daemon.debug pppd[9495]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0x5455b2ef>]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: rcvd [LCP ConfReq id=0x22 <mru 1492> <auth chap MD5> <magic 0x3b0f63c8>]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: sent [LCP ConfAck id=0x22 <mru 1492> <auth chap MD5> <magic 0x3b0f63c8>]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: sent [LCP EchoReq id=0x0 magic=0x5455b2ef]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: rcvd [CHAP Challenge id=0x1 <5f38**********************************************5423>, name = "SIMB_TABOR_BNG1"]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: sent [CHAP Response id=0x1 <c02**********************e9f>, name = "username"]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: rcvd [LCP EchoRep id=0x0 magic=0x3b0f63c8]
Wed Apr 29 06:40:34 2020 daemon.debug pppd[9495]: rcvd [CHAP Success id=0x1 "CHAP authentication success"]
Wed Apr 29 06:40:34 2020 daemon.info pppd[9495]: CHAP authentication succeeded: CHAP authentication success
Wed Apr 29 06:40:34 2020 daemon.notice pppd[9495]: CHAP authentication succeeded
Wed Apr 29 06:40:34 2020 daemon.notice pppd[9495]: peer from calling number A4:7B:2C:9E:C7:44 authorized
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: rcvd [IPCP ConfReq id=0x2d <addr 94.127.30.0>]
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: sent [IPCP ConfAck id=0x2d <addr 94.127.30.0>]
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: rcvd [IPCP ConfNak id=0x1 <addr 146.X.Y.Z> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: sent [IPCP ConfReq id=0x2 <addr 146.X.Y.Z> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: rcvd [IPCP ConfAck id=0x2 <addr 146.X.Y.Z> <ms-dns1 212.18.32.10> <ms-dns2 212.18.32.12>]
Wed Apr 29 06:40:35 2020 daemon.notice pppd[9495]: local  IP address 146.X.Y.Z
Wed Apr 29 06:40:35 2020 daemon.notice pppd[9495]: remote IP address 94.127.30.0
Wed Apr 29 06:40:35 2020 daemon.notice pppd[9495]: primary   DNS address 212.18.32.10
Wed Apr 29 06:40:35 2020 daemon.notice pppd[9495]: secondary DNS address 212.18.32.12
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: Script /lib/netifd/ppp-up started (pid 9560)
Wed Apr 29 06:40:35 2020 daemon.notice netifd: Network device 'pppoe-wan' link is up
Wed Apr 29 06:40:35 2020 daemon.notice netifd: Interface 'wan' is now up
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: reading /tmp/resolv.conf.auto
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain test
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain onion
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain localhost
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain local
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain invalid
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain bind
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using local addresses only for domain lan
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using nameserver 212.18.32.10#53
Wed Apr 29 06:40:35 2020 daemon.info dnsmasq[1565]: using nameserver 212.18.32.12#53
Wed Apr 29 06:40:35 2020 daemon.debug pppd[9495]: Script /lib/netifd/ppp-up finished (pid 9560), status = 0x1
Wed Apr 29 06:40:36 2020 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Wed Apr 29 08:07:42 2020 daemon.info dnsmasq-dhcp[1565]: DHCPREQUEST(br-lan) 192.168.1.197 XX:XX:XX:XX:XX:XX

Regards,David

Help me out, is that a PADT your modem sends to the DSLAM@a4:7b:2c:9e:c7:44, a PADT it receives?
According to https://www.wireshark.org/tools/oui-lookup.html A4:7B:2C indicates Nokia, so that could be a DSLAM/BRAS type of node...

This is a PADT my router (openwrt c4:XX:XX:XX:XX:ed ) sends to the AC/ppp-server ( a4:7b:2c:9e:c7:44 ).

It is probably a response to the PADT sent by AC a second earlier (but not to my router but to someone other: 44:4e:6d:fd:c7:39 )

(I don't think it is a DSLAM, as this is FTTH)

Okay, so this means that your side of the PPPoE tunnel is shutting down, leaving the question, why ;).

Ah thanks, yes this rather looks like GPON, but I had thought that in GPON the downstream packets are encrypted individually for each user, so your neighbourrs PADTs should never ever show up readable on your link.

Mmmh, 44:4E:6D AVM Audiovisuelles Marketing und Computersysteme GmbH, so it seems Nokia wants to talk to a Fritzbox somewhere, you do not happen to use a secondary fritzbox as VoIP-box inside your network? Just asking, probably not...

I think we are looking at a red herring. These bad packets are received and acted upon because the interface is in the promiscuous mode, and this is because you didn't add the "-p" option to tcpdump. On the other hand, the earlier "ifconfig" output says that, without tcpdump, the interface is not in promiscuous mode. This is really confusing. Please always use the "-p" option.

Anyway, we already have a verbose tcpdump log with the "-p" option, and it does not show the PADT message. Perhaps because of the wrong filter? How about:

tcpdump -evpni eth1.3902 '(not ether[0x14:2] = 0x21 and not ether[0x14:2] = 0x57) or pppoed'

1 Like

No.
The original ISP ruter (not connected currently) has 6C:38:xxxx

So nothing like that on my side.

Yes, but this is GPON, and there the downstream should be individually encrypted per subscriber/ONT, so these PADTs for MACs not on his network should never reach him at all I believe?

I'll try that.

Apparently ifconfig does not show if eth1 is in promiscuous mode or not.
Neither does ip link.

I started 'tcpdump -e -v -i eth1.3902 pppoed' for a few seconds to trigger promiscuous mode, and then compared the output of the above commands. There was no difference (except the packet counts).

ip monitor link showed up a line for start and stop, but no details hinting at promiscuous mode:

[2020-04-29 14:43:24] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 14:43:24]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 14:43:24] 48: eth1.3902@eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default
[2020-04-29 14:43:24]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 14:43:38] 3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default
[2020-04-29 14:43:38]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff
[2020-04-29 14:43:38] 48: eth1.3902@eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default
[2020-04-29 14:43:38]     link/ether c4:XX:XX:XX:XX:ed brd ff:ff:ff:ff:ff:ff

only syslog said the promiscuous mode was activated and then deactivated.

Wed Apr 29 14:43:24 2020 kern.info kernel: [853998.131984] device eth1.3902 entered promiscuous mode
Wed Apr 29 14:43:24 2020 kern.info kernel: [853998.137162] device eth1 entered promiscuous mode
Wed Apr 29 14:43:38 2020 kern.info kernel: [854012.994273] device eth1.3902 left promiscuous mode
Wed Apr 29 14:43:38 2020 kern.info kernel: [854012.999393] device eth1 left promiscuous mode

Anyway, the problem happens regardless if I run tcpdump or not.

Also:

There Dianne Skoll says that in their code, the PADT packet is checked to have the correct (our) ethHdr.h_dest

I made a quick look at the kernel pppoe.c and there is no such check (I might have missed it though).

My take under current findings is:

  • ISP sends PADT to another party, but on "my" line; it shouldn't, but that's life...
  • the net if in my router picks it up; it shouldn't, but that's life...
  • the PPPoE code picks it up (it shouldn't, but that's life...) and then terminates the connection

If that is correct, my options are:

  • switch ISP (the previous I had did not use PPPoE, just plain E... sweet memories...)
  • fix kernel pppoe code to ignore PADT packets sent to others
  • fix netif code? netif firmware?
  • filter out the bogus packets (maybe with ebtables)

As for fresh data:

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

[2020-04-29 12:41:56] tcpdump: listening on eth1, link-type EN10MB (Ethernet), capture size 262144 bytes
[2020-04-29 13:49:13] 13:49:13.163623 a4:7b:2c:9e:c7:44 (oui Unknown) > 44:4e:6d:fd:c7:39 (oui Unknown), ethertype 802.1Q (0x8100), length 101: vlan 3902, p 1, ethertype PPPoE D, PPPoE PADO [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq 0x444E6DFDC739AAAAAAAAB9000000AAAAAAAA4621426F78202020AAAAAAAA] [AC-Cookie ".5b.u...~.F.mlKv"]

and simultaneously running: tcpdump -evpni eth1.3902 (not ether[0x14:2] = 0x21 and not ether[0x14:2] = 0x57) or pppoed

13:49:13.163623 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE D (0x8863), length 97: PPPoE PADO [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq 0x444E6DFDC739AAAAAAAAB9000000AAAAAAAA4621426F78202020AAAAAAAA] [AC-Cookie ".5b.u...~.F.mlKv"]
13:49:13.168608 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE S (0x8864), length 56: PPPoE  [ses 0x1] LCP (0xc021), length 21: LCP, Conf-Request (0x01), id 120, length 21
13:49:13.170601 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE D (0x8863), length 58: PPPoE PADS [ses 0x1] [Service-Name] [Host-Uniq 0x444E6DFDC739AAAAAAAAB9000000AAAAAAAA4621426F78202020AAAAAAAA]
14:10:11.180520 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE D (0x8863), length 97: PPPoE PADO [Service-Name] [AC-Name "SIMB_TABOR_BNG1"] [Host-Uniq 0x444E6DFDC739AAAAAAAABB000000AAAAAAAA4621426F78202020AAAAAAAA] [AC-Cookie ".5b.u...~.F.mlKv"]
14:10:11.182514 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE S (0x8864), length 56: PPPoE  [ses 0x1] LCP (0xc021), length 21: LCP, Conf-Request (0x01), id 75, length 21
14:10:11.184493 a4:7b:2c:9e:c7:44 > 44:4e:6d:fd:c7:39, ethertype PPPoE D (0x8863), length 58: PPPoE PADS [ses 0x1] [Service-Name] [Host-Uniq 0x444E6DFDC739AAAAAAAABB000000AAAAAAAA4621426F78202020AAAAAAAA]

(note: I filtered out packets sent to or from my MAC)

So I get packets sent to someone else, even if not having eth1 in promiscuous mode.

ebtables could work, but then you should create a bridge and add eth1.3902 to it, and specify that bridge as the physical wan interface.

One more thing about promiscuous mode:

# cat /sys/class/net/eth1/flags
0x1003
# tcpdump -i eth1.3902 &
# cat /sys/class/net/eth1/flags
0x1103
# kill tcpdump
# cat /sys/class/net/eth1/flags
0x1003

So it is recorded internally, just the ifconfig and ip commands don't show it

1 Like

Mystery solved.

I added a debug output to kernel pppoe.c function pppoe_disc_rcv:

pr_info("pppoe: pppoe_disc_rcv /my patch/  PADT received, sid=%d, SRC: %02x:%02x:%02x:%02x:%02x:%02x, DST: %02x:%02x:%02x:%02x:%02x:%02x\n",
ph->sid,
eth_hdr(skb)->h_source[0],
eth_hdr(skb)->h_source[1],
eth_hdr(skb)->h_source[2],
eth_hdr(skb)->h_source[3],
eth_hdr(skb)->h_source[4],
eth_hdr(skb)->h_source[5],

eth_hdr(skb)->h_dest[0],
eth_hdr(skb)->h_dest[1],
eth_hdr(skb)->h_dest[2],
eth_hdr(skb)->h_dest[3],
eth_hdr(skb)->h_dest[4],
eth_hdr(skb)->h_dest[5]

);

When the problem happens, it prints:

pppoe: pppoe_disc_rcv /my patch/  PADT received, sid=1, SRC: a4:7b:2c:9e:c7:44, DST: 44:4e:6d:fd:c7:39

My HWaddr is c4:xxxxxx:ed

After that, the pppoe module closes the connection.

So the problem was as already suspected, that pppoe does not properly check if the received PADT packet belongs to its ppp session.

I'll patch it up soon (if someone does not beat me to it).