[FS#665] Lede 17.01.0-r3205-59508e3 on Nucom 5010UN v2 acting as Wifi Client Router lose connection with AP

Wed Mar 29 10:34:09 PDT 2017

The following task has a new comment added:

FS#665 - Lede 17.01.0-r3205-59508e3 on Nucom 5010UN v2 acting as Wifi Client Router lose connection with AP
User who did this - sibok (sibok)

----------
It just failed again, so i'm attaching system and kernel log files. Also available on the following URLs:

  * system.log: https://gist.github.com/anonymous/b4d83aa6833a89bfae3a14714be456e7

  * kernel.log: https://gist.github.com/anonymous/6c76e2c810d2c5573da3936c7dc00730

Next is the relevant system.log data since boot to connectivity failure:

Tue Mar 28 17:45:19 2017 daemon.info procd: - init complete -
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.525816] bcm63xx_enetsw bcm63xx_enetsw.0: link UP on Port 2, 100Mbps, full-duplex
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.534011] bcm63xx_enetsw bcm63xx_enetsw.0: link UP on Port 3, 100Mbps, full-duplex
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.552133] device eth0.1 entered promiscuous mode
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.557107] device eth0 entered promiscuous mode
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.565151] br-lan: port 1(eth0.1) entered forwarding state
Tue Mar 28 17:45:21 2017 kern.info kernel: [   26.570997] br-lan: port 1(eth0.1) entered forwarding state
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'lan' is enabled
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'lan' is setting up now
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'lan' is now up
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'loopback' is enabled
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'loopback' is setting up now
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'loopback' is now up
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Network device 'eth0' link is up
Tue Mar 28 17:45:21 2017 daemon.notice netifd: bridge 'br-lan' link is up
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'lan' has link connectivity
Tue Mar 28 17:45:21 2017 daemon.notice netifd: VLAN 'eth0.1' link is up
Tue Mar 28 17:45:21 2017 daemon.info odhcpd[643]: Raising SIGUSR1 due to address change on br-lan
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Network device 'lo' link is up
Tue Mar 28 17:45:21 2017 daemon.notice netifd: Interface 'loopback' has link connectivity
Tue Mar 28 17:45:22 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 17:45:22 2017 daemon.notice odhcpd[643]: Got DHCPv6 request
Tue Mar 28 17:45:22 2017 daemon.warn odhcpd[643]: DHCPV6 SOLICIT IA_NA from 000100011db08d7b40167e209f46 on br-lan: ok fd0d:2e0c:9224::2/128
Tue Mar 28 17:45:22 2017 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Tue Mar 28 17:45:23 2017 kern.info kernel: [   28.573423] br-lan: port 1(eth0.1) entered forwarding state
Tue Mar 28 17:45:23 2017 daemon.notice odhcpd[643]: Got DHCPv6 request
Tue Mar 28 17:45:23 2017 daemon.warn odhcpd[643]: DHCPV6 REQUEST IA_NA from 000100011db08d7b40167e209f46 on br-lan: ok fd0d:2e0c:9224::2/128
Tue Mar 28 17:45:23 2017 daemon.notice netifd: radio0 (757): command failed: Not supported (-122)
Tue Mar 28 17:45:24 2017 kern.info kernel: [   29.918962] b43-phy0: Loading firmware version 666.2 (2011-02-23 01:15:07)
Tue Mar 28 17:45:24 2017 kern.info kernel: [   30.072136] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Tue Mar 28 17:45:25 2017 daemon.notice netifd: radio0 (757): Successfully initialized wpa_supplicant
Tue Mar 28 17:45:26 2017 daemon.notice netifd: Interface 'wwan' is enabled
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.731591] wlan0: authenticate with 11:22:33:44:55:00
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.769895] wlan0: send auth to 11:22:33:44:55:00 (try 1/3)
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.779473] wlan0: authenticated
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.785736] wlan0: associate with 11:22:33:44:55:00 (try 1/3)
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.800345] wlan0: RX AssocResp from 11:22:33:44:55:00 (capab=0x411 status=0 aid=3)
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.808628] wlan0: associated
Tue Mar 28 17:45:27 2017 kern.info kernel: [   32.811989] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Tue Mar 28 17:45:27 2017 daemon.notice netifd: Network device 'wlan0' link is up
Tue Mar 28 17:45:27 2017 daemon.notice netifd: Interface 'wwan' has link connectivity
Tue Mar 28 17:45:27 2017 daemon.notice netifd: Interface 'wwan' is setting up now
Tue Mar 28 17:45:27 2017 daemon.notice netifd: wwan (938): udhcpc: started, v1.25.1
Tue Mar 28 17:45:27 2017 daemon.notice netifd: wwan (938): udhcpc: sending discover
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: started, version 2.76 cachesize 150
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: 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
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: DNS service limited to local subnets
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq-dhcp[958]: DHCP, IP range 192.168.3.100 -- 192.168.3.249, lease time 12h
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: using local addresses only for domain lan
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: reading /tmp/resolv.conf.auto
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: using local addresses only for domain lan
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: using nameserver 8.8.8.8#53
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: read /etc/hosts - 1 addresses
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: read /tmp/hosts/odhcpd - 1 addresses
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq[958]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses
Tue Mar 28 17:45:29 2017 daemon.info dnsmasq-dhcp[958]: read /etc/ethers - 0 addresses
Tue Mar 28 17:45:30 2017 daemon.notice netifd: wwan (938): udhcpc: sending discover
Tue Mar 28 17:45:30 2017 daemon.notice netifd: wwan (938): udhcpc: sending select for 192.168.2.97
Tue Mar 28 17:45:30 2017 daemon.notice netifd: wwan (938): udhcpc: lease of 192.168.2.97 obtained, lease time 43200
Tue Mar 28 17:45:30 2017 daemon.notice netifd: Interface 'wwan' is now up
Tue Mar 28 17:45:30 2017 daemon.info dnsmasq[958]: reading /tmp/resolv.conf.auto
Tue Mar 28 17:45:30 2017 daemon.info dnsmasq[958]: using local addresses only for domain lan
Tue Mar 28 17:45:30 2017 daemon.info dnsmasq[958]: using nameserver 8.8.8.8#53
Tue Mar 28 17:45:30 2017 daemon.info dnsmasq[958]: using nameserver 192.168.2.1#53
Tue Mar 28 17:45:31 2017 user.notice firewall: Reloading firewall due to ifup of wwan (wlan0)
Tue Mar 28 17:45:31 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 17:45:33 2017 daemon.info dnsmasq-dhcp[958]: DHCPDISCOVER(br-lan) 00:11:22:33:44:55
Tue Mar 28 17:45:33 2017 daemon.info dnsmasq-dhcp[958]: DHCPOFFER(br-lan) 192.168.3.3 00:11:22:33:44:55
Tue Mar 28 17:45:33 2017 daemon.info dnsmasq-dhcp[958]: DHCPREQUEST(br-lan) 192.168.3.3 00:11:22:33:44:55
Tue Mar 28 17:45:33 2017 daemon.info dnsmasq-dhcp[958]: DHCPACK(br-lan) 192.168.3.3 00:11:22:33:44:55 Iris9700HD02
Tue Mar 28 17:45:43 2017 kern.info kernel: [   48.541638] bcm63xx_enetsw bcm63xx_enetsw.0: link DOWN on Port 2
Tue Mar 28 17:51:19 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 17:51:20 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 17:51:20 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:01:35 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:01:36 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:01:36 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:11:52 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:11:53 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:11:53 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 18:12:18 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 18:25:24 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 18:25:30 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 18:35:06 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 19:04:13 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 19:04:18 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:04:18 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:11:32 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:16:05 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:16:05 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:19:47 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:19:47 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:25:03 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:30:21 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:31:08 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 19:35:07 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:35:07 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:47:33 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 19:56:17 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 20:18:54 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 20:48:07 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 21:09:20 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 21:09:20 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Tue Mar 28 21:16:24 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 21:43:19 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 22:10:56 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 22:37:22 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 23:06:33 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 23:33:39 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Tue Mar 28 23:38:47 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:38:47 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:38:48 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:45:30 2017 daemon.notice netifd: wwan (938): udhcpc: sending renew
Tue Mar 28 23:45:32 2017 daemon.info dnsmasq-dhcp[958]: DHCPREQUEST(br-lan) 192.168.3.3 00:11:22:33:44:55
Tue Mar 28 23:45:32 2017 daemon.info dnsmasq-dhcp[958]: DHCPACK(br-lan) 192.168.3.3 00:11:22:33:44:55 Iris9700HD02
Tue Mar 28 23:53:17 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:53:18 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:53:18 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Tue Mar 28 23:56:10 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 00:06:01 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Wed Mar 29 00:06:01 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Wed Mar 29 00:20:47 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Wed Mar 29 00:20:48 2017 daemon.warn dnsmasq[958]: possible DNS-rebind attack detected: sarect.noip.me
Wed Mar 29 00:24:13 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Wed Mar 29 00:24:32 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Wed Mar 29 00:25:38 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 00:32:26 2017 kern.info kernel: [24451.545758] bcm63xx_enetsw bcm63xx_enetsw.0: link UP on Port 2, 100Mbps, full-duplex
Wed Mar 29 00:32:26 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 00:32:26 2017 daemon.notice odhcpd[643]: Got DHCPv6 request
Wed Mar 29 00:32:26 2017 daemon.warn odhcpd[643]: DHCPV6 SOLICIT IA_NA from 000100011db08d7b40167e209f46 on br-lan: ok fd0d:2e0c:9224::2/128
Wed Mar 29 00:32:26 2017 daemon.info dnsmasq[958]: read /etc/hosts - 1 addresses
Wed Mar 29 00:32:26 2017 daemon.info dnsmasq[958]: read /tmp/hosts/odhcpd - 0 addresses
Wed Mar 29 00:32:26 2017 daemon.info dnsmasq[958]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses
Wed Mar 29 00:32:26 2017 daemon.info dnsmasq-dhcp[958]: read /etc/ethers - 0 addresses
Wed Mar 29 00:32:27 2017 daemon.notice odhcpd[643]: Got DHCPv6 request
Wed Mar 29 00:32:27 2017 daemon.warn odhcpd[643]: DHCPV6 REQUEST IA_NA from 000100011db08d7b40167e209f46 on br-lan: ok fd0d:2e0c:9224::2/128
Wed Mar 29 00:32:27 2017 daemon.info dnsmasq[958]: read /etc/hosts - 1 addresses
Wed Mar 29 00:32:27 2017 daemon.info dnsmasq[958]: read /tmp/hosts/odhcpd - 1 addresses
Wed Mar 29 00:32:27 2017 daemon.info dnsmasq[958]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses
Wed Mar 29 00:32:27 2017 daemon.info dnsmasq-dhcp[958]: read /etc/ethers - 0 addresses
Wed Mar 29 00:32:30 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 00:32:30 2017 daemon.info dnsmasq-dhcp[958]: DHCPREQUEST(br-lan) 192.168.3.2 00:11:22:33:44:66
Wed Mar 29 00:32:30 2017 daemon.info dnsmasq-dhcp[958]: DHCPACK(br-lan) 192.168.3.2 00:11:22:33:44:66 MediaSrv
Wed Mar 29 00:32:34 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 00:50:42 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 01:09:50 2017 daemon.warn dnsmasq-dhcp[958]: no address range available for DHCP request via wlan0
Wed Mar 29 01:17:29 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 01:45:23 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 02:10:44 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 02:34:49 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 02:45:31 2017 daemon.notice netifd: wwan (938): udhcpc: sending renew
Wed Mar 29 03:04:47 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan
Wed Mar 29 03:30:30 2017 daemon.info odhcpd[643]: Initial RA router lifetime 0, 1 address(es) available on br-lan

After the failure logged in through Luci web interface, then noticed Local time was wrong even Timezone was properly setted according to my timezone so i updated by syncing from browser. That's why there's the time jump in the last lines in system.log

----------

One or more files have been attached.

More information can be found at the following URL:
https://bugs.lede-project.org/index.php?do=details&task_id=665#comment2274