[SOLVED] Buffalo WBMR-HP-G300H ppp problem

t0t3m · January 5, 2018, 5:01pm

Hi, i have problems getting internet connection when i start the router / restart network on my router Buffalo WBMR-HP-G300H Annex A. The issue is related to the dsl0 interface. Actually the wan interface is linked to ethernet adapter dsl0 in LuCi, this seems to break the start of pppd or something like that (dsl connection is ok). If I modify the binding and change it to "nas0" I can get an ip through ppp and internet works ok.
My current firmware is OpenWrt SNAPSHOT r5679-d726187367. I can confirm i had a similar issue with my previous firware version (LEDE Reboot SNAPSHOT r5447-e23ff063d3) but i mistakenly thought it was a provider issue. With that version restarting the router / network a couple of times solved the problem (i don't remember exactly how I fixed). Before r5447-e23ff063d3 i used firmware version r5122-f7a6fd3153 (23/10/2017 build) with no problems. Taking a look at LEDE git history i think this commit could be the cause of the problem. Maybe this could be useful to @mkresin

https://github.com/lede-project/source/commit/b02b7004f8d1a946cfd71d2458d5bc3c5946dae7#diff-08b636e6e6542985fd3a8e97f13a7a76

Below you can find two partial log (with dsl0 and nas0 binding) and my led configuration

Thanks in advance

dsl0

Fri Jan  5 17:26:06 2018 user.info kernel: [   17.823995] kmodloader: done loading kernel modules from /etc/modules.d/*
Fri Jan  5 17:26:09 2018 kern.info kernel: [   23.471119] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Fri Jan  5 17:26:09 2018 daemon.notice procd: /etc/rc.d/S20network: Failed to connect to the switch. Use the "list" command to see which switches are available.
Fri Jan  5 17:26:10 2018 kern.info kernel: [   24.481650] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: tunnel
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: Network device
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: bridge
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: veth
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: macvlan
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: 8021ad
Fri Jan  5 17:26:10 2018 user.notice : Added device handler type: 8021q
Fri Jan  5 17:26:13 2018 daemon.err block: /dev/mtdblock4 is already mounted on /rom
Fri Jan  5 17:26:13 2018 daemon.err block: /dev/mtdblock5 is already mounted on /overlay
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.253774] br-lan: port 1(eth0) entered blocking state
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.257627] br-lan: port 1(eth0) entered disabled state
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.263488] device eth0 entered promiscuous mode
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.293283] br-lan: port 1(eth0) entered blocking state
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.297138] br-lan: port 1(eth0) entered forwarding state
Fri Jan  5 17:26:19 2018 kern.info kernel: [   33.302767] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'lan' is enabled
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'lan' is setting up now
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'lan' is now up
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'loopback' is enabled
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'loopback' is setting up now
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'loopback' is now up
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Network device 'eth0' link is up
Fri Jan  5 17:26:19 2018 daemon.notice netifd: bridge 'br-lan' link is up
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'lan' has link connectivity
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Network device 'lo' link is up
Fri Jan  5 17:26:19 2018 daemon.notice netifd: Interface 'loopback' has link connectivity
Fri Jan  5 17:26:20 2018 kern.info kernel: [   34.273535] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Fri Jan  5 17:26:22 2018 authpriv.info dropbear[1171]: Not backgrounding
Fri Jan  5 17:26:24 2018 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Fri Jan  5 17:26:29 2018 daemon.err hostapd: Configuration file: /var/run/hostapd-phy0.conf
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.480198] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.716936] br-lan: port 2(wlan0) entered blocking state
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.720885] br-lan: port 2(wlan0) entered disabled state
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.726827] device wlan0 entered promiscuous mode
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.730961] br-lan: port 2(wlan0) entered blocking state
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.736057] br-lan: port 2(wlan0) entered forwarding state
Fri Jan  5 17:26:29 2018 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Jan  5 17:26:29 2018 daemon.err hostapd: Using interface wlan0 with hwaddr xx:xx:xx:xx:xx:xx and ssid "xxxxxx"
Fri Jan  5 17:26:29 2018 kern.info kernel: [   43.805489] br-lan: port 2(wlan0) entered disabled state
Fri Jan  5 17:26:34 2018 daemon.notice dsl-notify: Switching to TC-Layer ATM
Fri Jan  5 17:26:34 2018 kern.info kernel: [   48.657594] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Fri Jan  5 17:26:34 2018 kern.info kernel: [   48.662829] br-lan: port 2(wlan0) entered blocking state
Fri Jan  5 17:26:34 2018 kern.info kernel: [   48.667875] br-lan: port 2(wlan0) entered forwarding state
Fri Jan  5 17:26:34 2018 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->ENABLED
Fri Jan  5 17:26:34 2018 daemon.notice hostapd: wlan0: AP-ENABLED
Fri Jan  5 17:26:35 2018 kern.info kernel: [   49.026622] ATM1.0.26    ATM (A1) firmware version 0.16
Fri Jan  5 17:26:35 2018 kern.warn kernel: [   49.030466] ifxmips_atm: ATM init succeed
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: started, version 2.78 cachesize 150
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC no-ID loop-detect inotify
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq-dhcp[1522]: DHCP, IP range 192.168.1.100 -- 192.168.1.249, lease time 12h
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain test
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain onion
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain localhost
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain local
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain invalid
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain example.net
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain example.org
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using local addresses only for domain example.com
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: using 3 more local addresses
Fri Jan  5 17:26:35 2018 daemon.warn dnsmasq[1522]: no servers found in /tmp/resolv.conf.auto, will retry
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: read /etc/hosts - 1 addresses
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq[1522]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Fri Jan  5 17:26:35 2018 daemon.info dnsmasq-dhcp[1522]: read /etc/ethers - 0 addresses
Fri Jan  5 17:26:36 2018 kern.notice kernel: [   50.063894] random: crng init done
Fri Jan  5 17:26:36 2018 daemon.notice netifd: Network device 'wlan0' link is up
Fri Jan  5 17:26:37 2018 daemon.err modprobe: xt_multiport is already loaded
Fri Jan  5 17:26:37 2018 daemon.err modprobe: xt_connmark is already loaded
Fri Jan  5 17:26:37 2018 daemon.err modprobe: xt_length is already loaded
Fri Jan  5 17:26:38 2018 daemon.info ocserv[1363]: main: initialized ocserv 0.11.9
Fri Jan  5 17:26:38 2018 daemon.info ocserv[1691]: sec-mod: reading supplemental config from files
Fri Jan  5 17:26:38 2018 daemon.info ocserv[1691]: sec-mod: sec-mod initialized (socket: /var/lib/ocserv/ocserv-socket.1363)
Fri Jan  5 17:26:38 2018 local2.notice br2684ctl[1667]: Interface "nas0" created sucessfully
Fri Jan  5 17:26:38 2018 local2.notice br2684ctl[1667]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 17:26:38 2018 kern.info kernel: [   52.500275] dsl0: renamed from nas0
Fri Jan  5 17:26:38 2018 daemon.notice netifd: Interface 'wan' is enabled
Fri Jan  5 17:26:38 2018 kern.err kernel: [   52.532105] br2684:br2684_regvcc: tried to attach to non-existent device
Fri Jan  5 17:26:38 2018 local2.err br2684ctl[1667]: Could not configure interface:No such device or address
Fri Jan  5 17:26:40 2018 local2.notice br2684ctl[1771]: Interface "nas0" created sucessfully
Fri Jan  5 17:26:40 2018 local2.notice br2684ctl[1771]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 17:26:41 2018 local2.info br2684ctl[1771]: Interface configured
Fri Jan  5 17:26:42 2018 local2.info br2684ctl[1771]: RFC 1483/2684 bridge daemon started
Fri Jan  5 17:26:45 2018 daemon.err modprobe: xt_multiport is already loaded
Fri Jan  5 17:26:45 2018 daemon.err modprobe: xt_connmark is already loaded
Fri Jan  5 17:26:45 2018 daemon.err modprobe: xt_length is already loaded
Fri Jan  5 17:27:02 2018 kern.err kernel: [   76.345789] [DSL_BSP_Showtime 914]: Datarate US intl = 351818, fast = 0
Fri Jan  5 17:27:02 2018 kern.warn kernel: [   76.351072] enter showtime, cell rate: 0 - 829, 1 - 829, xdata addr: 0x82f90000
Fri Jan  5 17:28:08 2018 daemon.err uhttpd[2141]: sh: write error: Broken pipe
Fri Jan  5 17:28:08 2018 daemon.err uhttpd[2141]: sh: write error: Broken pipe

nas0

Fri Jan  5 16:36:27 2018 kern.info kernel: [   23.556115] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Fri Jan  5 16:36:27 2018 daemon.notice procd: /etc/rc.d/S20network: Failed to connect to the switch. Use the "list" command to see which switches are available.
Fri Jan  5 16:36:28 2018 kern.info kernel: [   24.577686] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: tunnel
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: Network device
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: bridge
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: veth
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: macvlan
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: 8021ad
Fri Jan  5 16:36:28 2018 user.notice : Added device handler type: 8021q
Fri Jan  5 16:36:31 2018 daemon.err block: /dev/mtdblock4 is already mounted on /rom
Fri Jan  5 16:36:31 2018 daemon.err block: /dev/mtdblock5 is already mounted on /overlay
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.253609] br-lan: port 1(eth0) entered blocking state
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.257456] br-lan: port 1(eth0) entered disabled state
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.263323] device eth0 entered promiscuous mode
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.289589] br-lan: port 1(eth0) entered blocking state
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.293363] br-lan: port 1(eth0) entered forwarding state
Fri Jan  5 16:36:37 2018 kern.info kernel: [   33.299046] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'lan' is enabled
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'lan' is setting up now
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'lan' is now up
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'loopback' is enabled
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'loopback' is setting up now
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'loopback' is now up
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Network device 'eth0' link is up
Fri Jan  5 16:36:37 2018 daemon.notice netifd: bridge 'br-lan' link is up
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'lan' has link connectivity
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Network device 'lo' link is up
Fri Jan  5 16:36:37 2018 daemon.notice netifd: Interface 'loopback' has link connectivity
Fri Jan  5 16:36:38 2018 kern.info kernel: [   34.273534] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Fri Jan  5 16:36:40 2018 authpriv.info dropbear[1174]: Not backgrounding
Fri Jan  5 16:36:42 2018 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Fri Jan  5 16:36:47 2018 daemon.err hostapd: Configuration file: /var/run/hostapd-phy0.conf
Fri Jan  5 16:36:47 2018 kern.info kernel: [   43.158457] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Fri Jan  5 16:36:47 2018 kern.info kernel: [   43.397665] br-lan: port 2(wlan0) entered blocking state
Fri Jan  5 16:36:47 2018 kern.info kernel: [   43.401601] br-lan: port 2(wlan0) entered disabled state
Fri Jan  5 16:36:47 2018 kern.info kernel: [   43.407556] device wlan0 entered promiscuous mode
Fri Jan  5 16:36:47 2018 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Jan  5 16:36:47 2018 daemon.err hostapd: Using interface wlan0 with hwaddr xx:xx:xx:xx:xx:xx and ssid "xxxxxx"
Fri Jan  5 16:36:51 2018 daemon.notice dsl-notify: Switching to TC-Layer ATM
Fri Jan  5 16:36:51 2018 kern.info kernel: [   47.960743] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Fri Jan  5 16:36:51 2018 kern.info kernel: [   47.966020] br-lan: port 2(wlan0) entered blocking state
Fri Jan  5 16:36:51 2018 kern.info kernel: [   47.970990] br-lan: port 2(wlan0) entered forwarding state
Fri Jan  5 16:36:52 2018 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->ENABLED
Fri Jan  5 16:36:52 2018 daemon.notice hostapd: wlan0: AP-ENABLED
Fri Jan  5 16:36:52 2018 kern.info kernel: [   48.426441] ATM1.0.26    ATM (A1) firmware version 0.16
Fri Jan  5 16:36:52 2018 kern.warn kernel: [   48.430345] ifxmips_atm: ATM init succeed
Fri Jan  5 16:36:53 2018 daemon.notice netifd: Network device 'wlan0' link is up
Fri Jan  5 16:36:53 2018 kern.notice kernel: [   49.945550] random: crng init done
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: started, version 2.78 cachesize 150
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC no-ID loop-detect inotify
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq-dhcp[1577]: DHCP, IP range 192.168.1.100 -- 192.168.1.249, lease time 12h
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain test
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain onion
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain localhost
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain local
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain invalid
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.net
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.org
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.com
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: using 3 more local addresses
Fri Jan  5 16:36:54 2018 daemon.warn dnsmasq[1577]: no servers found in /tmp/resolv.conf.auto, will retry
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: read /etc/hosts - 1 addresses
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq[1577]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Fri Jan  5 16:36:54 2018 daemon.info dnsmasq-dhcp[1577]: read /etc/ethers - 0 addresses
Fri Jan  5 16:36:54 2018 daemon.err modprobe: xt_multiport is already loaded
Fri Jan  5 16:36:55 2018 daemon.err modprobe: xt_connmark is already loaded
Fri Jan  5 16:36:55 2018 daemon.err modprobe: xt_length is already loaded
Fri Jan  5 16:36:55 2018 local2.notice br2684ctl[1664]: Interface "nas0" created sucessfully
Fri Jan  5 16:36:55 2018 local2.notice br2684ctl[1664]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 16:36:56 2018 kern.info kernel: [   52.119669] dsl0: renamed from nas0
Fri Jan  5 16:36:56 2018 kern.err kernel: [   52.130126] br2684:br2684_regvcc: tried to attach to non-existent device
Fri Jan  5 16:36:56 2018 local2.err br2684ctl[1664]: Could not configure interface:No such device or address
Fri Jan  5 16:36:56 2018 daemon.info ocserv[1725]: sec-mod: reading supplemental config from files
Fri Jan  5 16:36:56 2018 daemon.info ocserv[1373]: main: initialized ocserv 0.11.9
Fri Jan  5 16:36:56 2018 daemon.info ocserv[1725]: sec-mod: sec-mod initialized (socket: /var/lib/ocserv/ocserv-socket.1373)
Fri Jan  5 16:36:58 2018 local2.notice br2684ctl[1753]: Interface "nas0" created sucessfully
Fri Jan  5 16:36:58 2018 local2.notice br2684ctl[1753]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 16:36:58 2018 local2.info br2684ctl[1753]: Interface configured
Fri Jan  5 16:36:59 2018 daemon.notice netifd: Interface 'wan' is enabled
Fri Jan  5 16:36:59 2018 local2.info br2684ctl[1753]: RFC 1483/2684 bridge daemon started
Fri Jan  5 16:37:03 2018 daemon.err modprobe: xt_multiport is already loaded
Fri Jan  5 16:37:03 2018 daemon.err modprobe: xt_connmark is already loaded
Fri Jan  5 16:37:03 2018 daemon.err modprobe: xt_length is already loaded
Fri Jan  5 16:37:20 2018 kern.err kernel: [   76.890135] [DSL_BSP_Showtime 914]: Datarate US intl = 351818, fast = 0
Fri Jan  5 16:37:20 2018 kern.warn kernel: [   76.895409] enter showtime, cell rate: 0 - 829, 1 - 829, xdata addr: 0x82f90000
Fri Jan  5 16:37:20 2018 daemon.notice netifd: Network device 'nas0' link is up
Fri Jan  5 16:37:20 2018 daemon.notice netifd: Interface 'wan' has link connectivity
Fri Jan  5 16:37:20 2018 daemon.notice netifd: Interface 'wan' is setting up now
Fri Jan  5 16:37:21 2018 daemon.err insmod: module is already loaded - slhc
Fri Jan  5 16:37:21 2018 daemon.err insmod: module is already loaded - ppp_generic
Fri Jan  5 16:37:21 2018 daemon.err insmod: module is already loaded - pppox
Fri Jan  5 16:37:21 2018 daemon.err insmod: module is already loaded - pppoe
Fri Jan  5 16:37:22 2018 daemon.info pppd[2356]: Plugin rp-pppoe.so loaded.
Fri Jan  5 16:37:22 2018 daemon.info pppd[2356]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri Jan  5 16:37:22 2018 daemon.notice pppd[2356]: pppd 2.4.7 started by root, uid 0
Fri Jan  5 16:37:22 2018 daemon.info pppd[2356]: PPP session is 1
Fri Jan  5 16:37:22 2018 daemon.warn pppd[2356]: Connected to xx:xx:xx:xx:xx:xx via interface nas0
Fri Jan  5 16:37:22 2018 kern.info kernel: [   78.121586] pppoe-wan: renamed from ppp0
Fri Jan  5 16:37:22 2018 daemon.info pppd[2356]: Using interface pppoe-wan
Fri Jan  5 16:37:22 2018 daemon.notice pppd[2356]: Connect: pppoe-wan <--> nas0
Fri Jan  5 16:37:24 2018 daemon.info pppd[2356]: CHAP authentication succeeded: CHAP authentication success
Fri Jan  5 16:37:24 2018 daemon.notice pppd[2356]: CHAP authentication succeeded
Fri Jan  5 16:37:24 2018 daemon.notice pppd[2356]: peer from calling number xx:xx:xx:xx:xx:xx authorized
Fri Jan  5 16:37:25 2018 daemon.notice pppd[2356]: local  IP address xx.xx.xx.xx
Fri Jan  5 16:37:25 2018 daemon.notice pppd[2356]: remote IP address xx.xx.xx.xx
Fri Jan  5 16:37:25 2018 daemon.notice pppd[2356]: primary   DNS address xx.xx.xx.xx
Fri Jan  5 16:37:25 2018 daemon.notice pppd[2356]: secondary DNS address xx.xx.xx.xx
Fri Jan  5 16:37:25 2018 daemon.notice netifd: Network device 'pppoe-wan' link is up
Fri Jan  5 16:37:25 2018 daemon.notice netifd: Interface 'wan' is now up
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: reading /tmp/resolv.conf.auto
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain test
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain onion
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain localhost
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain local
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain invalid
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.net
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.org
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using local addresses only for domain example.com
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using nameserver 8.8.8.8#53
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using nameserver 8.8.4.4#53
Fri Jan  5 16:37:25 2018 daemon.info dnsmasq[1577]: using 3 more local addresses
Fri Jan  5 16:37:27 2018 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri Jan  5 16:37:28 2018 user.notice root: starting ntpclient
Fri Jan  5 17:25:00 2018 daemon.info pppd[2356]: System time change detected.

led config

config led 'led_wifi'
        option name 'wifi'
        option sysfs 'wbmr:green:wireless'
        option default '0'
        option trigger 'phy0tpt'

config led 'led_dsl'
        option name 'dsl'
        option trigger 'netdev'
        option dev 'pppoe-wan'
        option sysfs 'wbmr:green:dsl'
        option default '0'
        option mode 'link'

config led 'led_online'
        option name 'online'
        option default '0'
        option sysfs 'wbmr:green:internet'
        option trigger 'netdev'
        option dev 'pppoe-wan'
        option mode 'link tx rx'

config led
        option sysfs 'wbmr:yellow:security'
        option name 'security'
        option default '0'
        option trigger 'phy0radio'

config led
        option name 'wan_down'
        option sysfs 'wbmr:blue:movie'
        option default '0'
        option trigger 'none'

mkresin · January 6, 2018, 10:51am

Great, we a have another br2684ctl related race condition. These are the relevant lines.

Fri Jan  5 17:26:34 2018 daemon.notice dsl-notify: Switching to TC-Layer ATM
Fri Jan  5 17:26:35 2018 kern.info kernel: [   49.026622] ATM1.0.26    ATM (A1) firmware version 0.16
Fri Jan  5 17:26:35 2018 kern.warn kernel: [   49.030466] ifxmips_atm: ATM init succeed
Fri Jan  5 17:26:38 2018 local2.notice br2684ctl[1667]: Interface "nas0" created sucessfully
Fri Jan  5 17:26:38 2018 local2.notice br2684ctl[1667]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 17:26:38 2018 kern.info kernel: [   52.500275] dsl0: renamed from nas0
Fri Jan  5 17:26:38 2018 kern.err kernel: [   52.532105] br2684:br2684_regvcc: tried to attach to non-existent device
Fri Jan  5 17:26:38 2018 local2.err br2684ctl[1667]: Could not configure interface:No such device or address

Fri Jan  5 17:26:40 2018 local2.notice br2684ctl[1771]: Interface "nas0" created sucessfully
Fri Jan  5 17:26:40 2018 local2.notice br2684ctl[1771]: Communicating over ATM 0.8.35, encapsulation: LLC
Fri Jan  5 17:26:41 2018 local2.info br2684ctl[1771]: Interface configured
Fri Jan  5 17:26:42 2018 local2.info br2684ctl[1771]: RFC 1483/2684 bridge daemon started

Fri Jan  5 17:27:02 2018 kern.err kernel: [   76.345789] [DSL_BSP_Showtime 914]: Datarate US intl = 351818, fast = 0
Fri Jan  5 17:27:02 2018 kern.warn kernel: [   76.351072] enter showtime, cell rate: 0 - 829, 1 - 829, xdata addr: 0x82f90000

We can see two br2684ctl processes here. The first one with pid 1667 fails to configure the atm ethernet bridge. It looks like the nas0 => dsl0 rename is happening while br2684 subsystem still configures the atm bridge.

Due to the first failure a second br2684ctl processes is spawned later with pid 1771 and creates the nas0 interface again.

I'm quite sure we brought back one more race condition.

Are you able to build your own image to test a patch?

t0t3m · January 6, 2018, 3:10pm

No problem, send me the patch info and i will build another image.

t0t3m · January 7, 2018, 4:08pm

Hi @mkresin,

i've build another image with your patches, the problem seems fixed, using dsl0 interface i get internet connection everytime i reboot the router. Many thanks for your time

Sun Jan  7 16:51:20 2018 daemon.notice dsl-notify: Switching to TC-Layer ATM
Sun Jan  7 16:51:20 2018 kern.info kernel: [   57.732781] ATM1.0.26    ATM (A1) firmware version 0.16
Sun Jan  7 16:51:20 2018 kern.warn kernel: [   57.736673] ifxmips_atm: ATM init succeed
Sun Jan  7 16:51:21 2018 daemon.err modprobe: xt_multiport is already loaded
Sun Jan  7 16:51:21 2018 daemon.err modprobe: xt_connmark is already loaded
Sun Jan  7 16:51:21 2018 daemon.err modprobe: xt_length is already loaded
Sun Jan  7 16:51:24 2018 daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Sun Jan  7 16:51:24 2018 daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Sun Jan  7 16:51:24 2018 daemon.notice hostapd: wlan0: AP-STA-CONNECTED xx:xx:xx:xx:xx:xx
Sun Jan  7 16:51:24 2018 daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Sun Jan  7 16:51:25 2018 local2.notice br2684ctl[2059]: Interface "dsl0" created sucessfully
Sun Jan  7 16:51:25 2018 local2.notice br2684ctl[2059]: Communicating over ATM 0.8.35, encapsulation: LLC
Sun Jan  7 16:51:25 2018 local2.info br2684ctl[2059]: Interface configured
Sun Jan  7 16:51:26 2018 daemon.notice netifd: Interface 'wan' is enabled
Sun Jan  7 16:51:26 2018 local2.info br2684ctl[2059]: RFC 1483/2684 bridge daemon started
Sun Jan  7 16:51:51 2018 kern.err kernel: [   88.985715] [DSL_BSP_Showtime 914]: Datarate US intl = 351818, fast = 0
Sun Jan  7 16:51:51 2018 kern.warn kernel: [   88.990988] enter showtime, cell rate: 0 - 829, 1 - 829, xdata addr: 0x82f80000
Sun Jan  7 16:51:51 2018 daemon.notice netifd: Network device 'dsl0' link is up
Sun Jan  7 16:51:51 2018 daemon.notice netifd: Interface 'wan' has link connectivity
Sun Jan  7 16:51:51 2018 daemon.notice netifd: Interface 'wan' is setting up now
Sun Jan  7 16:51:52 2018 daemon.err insmod: module is already loaded - slhc
Sun Jan  7 16:51:52 2018 daemon.err insmod: module is already loaded - ppp_generic
Sun Jan  7 16:51:52 2018 daemon.err insmod: module is already loaded - pppox
Sun Jan  7 16:51:52 2018 daemon.err insmod: module is already loaded - pppoe
Sun Jan  7 16:51:53 2018 daemon.info pppd[2327]: Plugin rp-pppoe.so loaded.
Sun Jan  7 16:51:53 2018 daemon.info pppd[2327]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Sun Jan  7 16:51:53 2018 daemon.notice pppd[2327]: pppd 2.4.7 started by root, uid 0
Sun Jan  7 16:51:53 2018 daemon.info pppd[2327]: PPP session is 1
Sun Jan  7 16:51:53 2018 daemon.warn pppd[2327]: Connected to xx:xx:xx:xx:xx:xx via interface dsl0
Sun Jan  7 16:51:53 2018 kern.info kernel: [   90.600132] pppoe-wan: renamed from ppp0
Sun Jan  7 16:51:53 2018 daemon.info pppd[2327]: Using interface pppoe-wan
Sun Jan  7 16:51:53 2018 daemon.notice pppd[2327]: Connect: pppoe-wan <--> dsl0
Sun Jan  7 16:51:56 2018 daemon.info pppd[2327]: CHAP authentication succeeded: CHAP authentication success
Sun Jan  7 16:51:56 2018 daemon.notice pppd[2327]: CHAP authentication succeeded
Sun Jan  7 16:51:56 2018 daemon.notice pppd[2327]: peer from calling number xx:xx:xx:xx:xx:xx authorized
Sun Jan  7 16:51:56 2018 daemon.notice pppd[2327]: local  IP address xx.xx.xx.xx
Sun Jan  7 16:51:56 2018 daemon.notice pppd[2327]: remote IP address xx.xx.xx.xx

mkresin · January 7, 2018, 4:57pm

Would you please send me the output of 'dmesg' as well as logread after a boot. I saw the error message already the last time, but was focused on getting the dsl working first. This error message shouldn't be there.

Feel free to switch to mail communication. I'm usually not using the forum.