PPPoE disconnects every few hours

xerces8 · April 24, 2020, 7:32pm

# cat /etc/config/network

config interface 'loopback'
        option ifname 'lo'
        option proto 'static'
        option ipaddr '127.0.0.1'
        option netmask '255.0.0.0'

config globals 'globals'
        option ula_prefix 'fd84:d068:c6a3::/48'

config interface 'lan'
        option type 'bridge'
        option ifname 'eth0'
        option proto 'static'
        option ipaddr '192.168.1.1'
        option netmask '255.255.255.0'
        option ip6assign '60'

config device 'lan_eth0_dev'
        option name 'eth0'
        option macaddr 'c6:**:**:**:**:ec'

config interface 'wan'
        option proto 'pppoe'
        option password '********'
        option ipv6 'auto'
        option username '*********'
        option ifname 'eth1.3902'

config interface 'wan6'
        option ifname 'eth1'
        option proto 'dhcpv6'

config switch
        option name 'switch0'
        option reset '1'
        option enable_vlan '1'
        option blinkrate '2'

config switch_vlan
        option device 'switch0'
        option vlan '1'
        option ports '0 1 2 3 5'

config switch_port
        option device 'switch0'
        option port '1'
        option led '6'

config switch_port
        option device 'switch0'
        option port '2'
        option led '9'

config switch_port
        option device 'switch0'
        option port '5'
        option led '2'

It is a fresh install of OpenWRT 19.07.2, I just set a root password and set up the PPPoE (entering: username, password, net device)

patrakov · April 24, 2020, 7:51pm

wan6 looks wrong, but not sure if it is relevant (i.e. whether the DHCPv6 code can bring the interface down, thus interfering with PPPoE). Still, please edit it as follows:

config interface 'wan6'
	option ifname '@wan'
	option proto 'dhcpv6'

... so that it does the DHCPv6 thingy on pppoe-wan (via the symbolic reference), not on eth1.

Here is my config from a Buffalo WBMR-HP-G300H, where I have to fake the MAC address:

config interface 'dsl0'
	option ifname 'dsl0'
	option proto 'none'
	option macaddr '00:24:a5:bd:40:21'

config interface 'wan'
	option ifname '@dsl0'
	option proto 'pppoe'
	option ipv6 '1'
	option username '....'
	option keepalive '60 5'
	option password '....'

config interface 'wan6'
	option ifname '@wan'
	option proto 'dhcpv6'

Yes, dsl0 is a real interface here (because of the built-in ADSL modem), you'll have to use ifname eth1.3902 in the first block.

xerces8 · April 24, 2020, 8:02pm

is proto dhcpv6 OK?
When it is actually PPPoE? (actually there is no IPv6 service at all)

Anyway, I did as you suggested. Followed by /etc/init.d/network reload

patrakov · April 24, 2020, 8:05pm

Yes, it's OK, and it works here. DHCPv6, when deployed on DSL, is layered upon an existing PPPoE link, where PPP only configured link-local addresses. If you are sure that there is no IPv6, just delete the wan6 interface. You can always recreate it later when your ISP upgrades the infrastructure.

xerces8 · April 24, 2020, 8:35pm

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

xerces8 · April 26, 2020, 12:10pm

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

xerces8 · April 26, 2020, 2:47pm

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

xerces8 · April 26, 2020, 7:06pm

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

patrakov · April 26, 2020, 10:05pm

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

xerces8 · April 26, 2020, 10:45pm

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.

xerces8 · April 27, 2020, 11:12pm

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?

xerces8 · April 28, 2020, 4:36pm

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

xerces8 · April 29, 2020, 12:00pm

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

moeller0 · April 29, 2020, 12:11pm

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...

xerces8 · April 29, 2020, 12:33pm

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)

moeller0 · April 29, 2020, 12:44pm

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...

patrakov · April 29, 2020, 12:50pm

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'

xerces8 · April 29, 2020, 1:22pm

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

So nothing like that on my side.

moeller0 · April 29, 2020, 1:25pm

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?

xerces8 · April 29, 2020, 1:26pm

I'll try that.