Rpi3 wlan0 won't reconnect

iurly · Sun May 14, 2017 11:17 pm

Hi,

I'm having some weird issues with the onboard wifi of a Raspberry Pi 3, running raspbian

pi@quasi:~ $ cat /etc/debian_version 
8.0
pi@quasi:~ $ uname -a
Linux quasi 4.4.50-v7+ #970 SMP Mon Feb 20 19:18:29 GMT 2017 armv7l GNU/Linux

The interface is configured as wireless station, connecting to the wireless router provided by the network provider. Pretty standard I guess.

Everything works fine, except that after a certain time (in this last case it's been about 20 days), the RPi will get disconnected and won't reconnect.

I tracked the disconnection down under /var/log/syslog:

May 14 00:17:01 quasi CRON[22955]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 14 00:38:58 quasi dhcpcd[499]: wlan0: carrier lost
May 14 00:38:58 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-DISCONNECTED bssid=ac:f1:df60:44 reason=0 locally_generated=1
May 14 00:38:58 quasi rsyslogd-2007: action 'action 17' suspended, next retry is Sun May 14 00:40:28 2017 [try http://www.rsyslog.com/e/2007 ]
May 14 00:38:58 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
May 14 00:38:58 quasi kernel: [1644205.327596] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code
May 14 00:38:58 quasi kernel: [1644205.327633] cfg80211: World regulatory domain updated:
May 14 00:38:58 quasi kernel: [1644205.327643] cfg80211: DFS Master region: unset
May 14 00:38:58 quasi kernel: [1644205.327652] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 14 00:38:58 quasi kernel: [1644205.327671] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:38:58 quasi kernel: [1644205.327687] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:38:58 quasi kernel: [1644205.327700] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:38:58 quasi kernel: [1644205.327715] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:38:58 quasi kernel: [1644205.327753] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
May 14 00:38:58 quasi kernel: [1644205.327789] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
May 14 00:38:58 quasi kernel: [1644205.327805] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:38:58 quasi kernel: [1644205.327829] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
May 14 00:38:58 quasi dhcpcd[499]: wlan0: deleting address fe80::e12e:8e9d:3212:7309
May 14 00:38:58 quasi avahi-daemon[448]: Withdrawing address record for fe80::e12e:8e9d:3212:7309 on wlan0.
May 14 00:38:58 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:38:58 quasi avahi-daemon[448]: Interface wlan0.IPv6 no longer relevant for mDNS.
May 14 00:38:58 quasi dhcpcd[499]: wlan0: deleting route to 192.168.1.0/24
May 14 00:38:58 quasi dhcpcd[499]: wlan0: deleting default route via 192.168.1.2
May 14 00:38:58 quasi avahi-daemon[448]: Withdrawing address record for 192.168.1.8 on wlan0.
May 14 00:38:58 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 14 00:38:58 quasi avahi-daemon[448]: Interface wlan0.IPv4 no longer relevant for mDNS.
May 14 00:38:58 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:00 quasi ntpd[647]: Deleting interface #333 wlan0, 192.168.1.8#123, interface stats: received=0, sent=0, dropped=0, active_time=10027 secs
May 14 00:39:00 quasi ntpd[647]: Deleting interface #331 wlan0, fe80::e12e:8e9d:3212:7309#123, interface stats: received=0, sent=0, dropped=0, active_time=11633 secs
May 14 00:39:00 quasi ntpd[647]: peers refreshed
May 14 00:39:04 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:39:05 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:12 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:39:13 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:14 quasi wpa_supplicant[552]: wlan0: Associated with ac:f1:df60:44
May 14 00:39:14 quasi wpa_supplicant[552]: wlan0: WPA: Key negotiation completed with ac:f1:df60:44 [PTK=CCMP GTK=CCMP]
May 14 00:39:14 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-CONNECTED - Connection to ac:f1:df60:44 completed [id=1 id_str=]
May 14 00:39:14 quasi dhcpcd[499]: wlan0: carrier acquired
May 14 00:39:14 quasi dhcpcd[499]: wlan0: adding address fe80::e12e:8e9d:3212:7309
May 14 00:39:14 quasi dhcpcd[499]: wlan0: IAID eb:f7:3e:aa
May 14 00:39:14 quasi dhcpcd[499]: wlan0: soliciting an IPv6 router
May 14 00:39:15 quasi dhcpcd[499]: wlan0: rebinding lease of 192.168.1.8
May 14 00:39:16 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:16 quasi avahi-daemon[448]: New relevant interface wlan0.IPv6 for mDNS.
May 14 00:39:16 quasi avahi-daemon[448]: Registering new address record for fe80::e12e:8e9d:3212:7309 on wlan0.*.
May 14 00:39:18 quasi ntpd[647]: Listen normally on 334 wlan0 fe80::e12e:8e9d:3212:7309 UDP 123
May 14 00:39:18 quasi ntpd[647]: peers refreshed
May 14 00:39:19 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-DISCONNECTED bssid=ac:f1:df60:44 reason=0 locally_generated=1
May 14 00:39:19 quasi dhcpcd[499]: wlan0: leased 192.168.1.8 for 86400 seconds
May 14 00:39:19 quasi dhcpcd[499]: wlan0: adding route to 192.168.1.0/24
May 14 00:39:19 quasi dhcpcd[499]: wlan0: adding default route via 192.168.1.2
May 14 00:39:19 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 14 00:39:19 quasi avahi-daemon[448]: New relevant interface wlan0.IPv4 for mDNS.
May 14 00:39:19 quasi avahi-daemon[448]: Registering new address record for 192.168.1.8 on wlan0.IPv4.
May 14 00:39:19 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
May 14 00:39:19 quasi kernel: [1644226.891389] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code
May 14 00:39:19 quasi kernel: [1644226.891422] cfg80211: World regulatory domain updated:
May 14 00:39:19 quasi kernel: [1644226.891432] cfg80211: DFS Master region: unset
May 14 00:39:19 quasi kernel: [1644226.891441] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 14 00:39:19 quasi kernel: [1644226.891456] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:19 quasi kernel: [1644226.891471] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:19 quasi kernel: [1644226.891484] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:19 quasi kernel: [1644226.891498] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:19 quasi kernel: [1644226.891513] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
May 14 00:39:19 quasi kernel: [1644226.891526] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
May 14 00:39:19 quasi kernel: [1644226.891540] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:19 quasi kernel: [1644226.891553] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
May 14 00:39:19 quasi dhcpcd[499]: wlan0: carrier lost
May 14 00:39:19 quasi dhcpcd[499]: wlan0: deleting address fe80::e12e:8e9d:3212:7309
May 14 00:39:19 quasi avahi-daemon[448]: Withdrawing address record for fe80::e12e:8e9d:3212:7309 on wlan0.
May 14 00:39:19 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:19 quasi dhcpcd[499]: wlan0: deleting route to 192.168.1.0/24
May 14 00:39:19 quasi avahi-daemon[448]: Interface wlan0.IPv6 no longer relevant for mDNS.
May 14 00:39:19 quasi dhcpcd[499]: wlan0: deleting default route via 192.168.1.2
May 14 00:39:19 quasi avahi-daemon[448]: Withdrawing address record for 192.168.1.8 on wlan0.
May 14 00:39:19 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 14 00:39:19 quasi avahi-daemon[448]: Interface wlan0.IPv4 no longer relevant for mDNS.
May 14 00:39:20 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:22 quasi ntpd[647]: Deleting interface #334 wlan0, fe80::e12e:8e9d:3212:7309#123, interface stats: received=0, sent=0, dropped=0, active_time=4 secs
May 14 00:39:22 quasi ntpd[647]: peers refreshed
May 14 00:39:23 quasi wpa_supplicant[552]: wlan0: Associated with ac:f1:df60:44
May 14 00:39:23 quasi wpa_supplicant[552]: wlan0: WPA: Key negotiation completed with ac:f1:df60:44 [PTK=CCMP GTK=CCMP]
May 14 00:39:23 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-CONNECTED - Connection to ac:f1:df60:44 completed [id=1 id_str=]
May 14 00:39:23 quasi dhcpcd[499]: wlan0: carrier acquired
May 14 00:39:23 quasi dhcpcd[499]: wlan0: adding address fe80::e12e:8e9d:3212:7309
May 14 00:39:23 quasi dhcpcd[499]: wlan0: IAID eb:f7:3e:aa
May 14 00:39:24 quasi dhcpcd[499]: wlan0: soliciting an IPv6 router
May 14 00:39:24 quasi dhcpcd[499]: wlan0: rebinding lease of 192.168.1.8
May 14 00:39:25 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:25 quasi avahi-daemon[448]: New relevant interface wlan0.IPv6 for mDNS.
May 14 00:39:25 quasi avahi-daemon[448]: Registering new address record for fe80::e12e:8e9d:3212:7309 on wlan0.*.
May 14 00:39:27 quasi ntpd[647]: Listen normally on 335 wlan0 fe80::e12e:8e9d:3212:7309 UDP 123
May 14 00:39:27 quasi ntpd[647]: peers refreshed
May 14 00:39:28 quasi dhcpcd[499]: wlan0: leased 192.168.1.8 for 86400 seconds
May 14 00:39:28 quasi dhcpcd[499]: wlan0: adding route to 192.168.1.0/24
May 14 00:39:28 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 14 00:39:28 quasi dhcpcd[499]: wlan0: adding default route via 192.168.1.2
May 14 00:39:28 quasi avahi-daemon[448]: New relevant interface wlan0.IPv4 for mDNS.
May 14 00:39:28 quasi avahi-daemon[448]: Registering new address record for 192.168.1.8 on wlan0.IPv4.
May 14 00:39:29 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-DISCONNECTED bssid=ac:f1:df60:44 reason=0 locally_generated=1
May 14 00:39:29 quasi dhcpcd[499]: wlan0: carrier lost
May 14 00:39:29 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
May 14 00:39:29 quasi kernel: [1644236.498788] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code
May 14 00:39:29 quasi kernel: [1644236.498818] cfg80211: World regulatory domain updated:
May 14 00:39:29 quasi kernel: [1644236.498828] cfg80211: DFS Master region: unset
May 14 00:39:29 quasi kernel: [1644236.498837] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 14 00:39:29 quasi kernel: [1644236.498852] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:29 quasi kernel: [1644236.498867] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:29 quasi kernel: [1644236.498880] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:29 quasi kernel: [1644236.498894] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:29 quasi kernel: [1644236.498908] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
May 14 00:39:29 quasi kernel: [1644236.498921] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
May 14 00:39:29 quasi kernel: [1644236.498934] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:29 quasi kernel: [1644236.498946] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
May 14 00:39:29 quasi dhcpcd[499]: wlan0: deleting address fe80::e12e:8e9d:3212:7309
May 14 00:39:29 quasi avahi-daemon[448]: Withdrawing address record for fe80::e12e:8e9d:3212:7309 on wlan0.
May 14 00:39:29 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:29 quasi avahi-daemon[448]: Interface wlan0.IPv6 no longer relevant for mDNS.
May 14 00:39:29 quasi dhcpcd[499]: wlan0: deleting route to 192.168.1.0/24
May 14 00:39:29 quasi dhcpcd[499]: wlan0: deleting default route via 192.168.1.2
May 14 00:39:29 quasi avahi-daemon[448]: Withdrawing address record for 192.168.1.8 on wlan0.
May 14 00:39:29 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 14 00:39:29 quasi avahi-daemon[448]: Interface wlan0.IPv4 no longer relevant for mDNS.
May 14 00:39:29 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:31 quasi ntpd[647]: Deleting interface #335 wlan0, fe80::e12e:8e9d:3212:7309#123, interface stats: received=0, sent=0, dropped=0, active_time=4 secs
May 14 00:39:31 quasi ntpd[647]: peers refreshed
May 14 00:39:31 quasi wpa_supplicant[552]: wlan0: Associated with ac:f1:df60:44
May 14 00:39:31 quasi wpa_supplicant[552]: wlan0: WPA: Key negotiation completed with ac:f1:df60:44 [PTK=CCMP GTK=CCMP]
May 14 00:39:31 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-CONNECTED - Connection to ac:f1:df60:44 completed [id=1 id_str=]
May 14 00:39:31 quasi dhcpcd[499]: wlan0: carrier acquired
May 14 00:39:31 quasi dhcpcd[499]: wlan0: adding address fe80::e12e:8e9d:3212:7309
May 14 00:39:31 quasi dhcpcd[499]: wlan0: IAID eb:f7:3e:aa
May 14 00:39:31 quasi dhcpcd[499]: wlan0: rebinding lease of 192.168.1.8
May 14 00:39:31 quasi dhcpcd[499]: wlan0: soliciting an IPv6 router
May 14 00:39:33 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:33 quasi avahi-daemon[448]: New relevant interface wlan0.IPv6 for mDNS.
May 14 00:39:33 quasi avahi-daemon[448]: Registering new address record for fe80::e12e:8e9d:3212:7309 on wlan0.*.
May 14 00:39:35 quasi ntpd[647]: Listen normally on 336 wlan0 fe80::e12e:8e9d:3212:7309 UDP 123
May 14 00:39:35 quasi ntpd[647]: peers refreshed
May 14 00:39:35 quasi dhcpcd[499]: wlan0: carrier lost
May 14 00:39:35 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-DISCONNECTED bssid=ac:f1:df60:44 reason=0 locally_generated=1
May 14 00:39:35 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
May 14 00:39:35 quasi kernel: [1644243.114694] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code
May 14 00:39:35 quasi kernel: [1644243.114734] cfg80211: World regulatory domain updated:
May 14 00:39:35 quasi kernel: [1644243.114745] cfg80211: DFS Master region: unset
May 14 00:39:35 quasi kernel: [1644243.114754] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 14 00:39:35 quasi kernel: [1644243.114769] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:35 quasi kernel: [1644243.114784] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:35 quasi kernel: [1644243.114797] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:35 quasi kernel: [1644243.114811] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
May 14 00:39:35 quasi kernel: [1644243.114828] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
May 14 00:39:35 quasi kernel: [1644243.114859] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
May 14 00:39:35 quasi kernel: [1644243.114878] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 14 00:39:35 quasi kernel: [1644243.114891] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
May 14 00:39:35 quasi dhcpcd[499]: wlan0: deleting address fe80::e12e:8e9d:3212:7309
May 14 00:39:35 quasi avahi-daemon[448]: Withdrawing address record for fe80::e12e:8e9d:3212:7309 on wlan0.
May 14 00:39:35 quasi avahi-daemon[448]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 14 00:39:35 quasi avahi-daemon[448]: Interface wlan0.IPv6 no longer relevant for mDNS.
May 14 00:39:36 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:38 quasi ntpd[647]: Deleting interface #336 wlan0, fe80::e12e:8e9d:3212:7309#123, interface stats: received=0, sent=0, dropped=0, active_time=3 secs
May 14 00:39:38 quasi ntpd[647]: peers refreshed
May 14 00:39:42 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:39:43 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:49 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:39:51 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:39:58 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:39:58 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=1 ssid="wharfedale" auth_failures=1 duration=10 reason=CONN_FAILED
May 14 00:40:34 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-REENABLED id=1 ssid="wharfedale"
May 14 00:40:34 quasi rsyslogd-2007: action 'action 17' suspended, next retry is Sun May 14 00:42:04 2017 [try http://www.rsyslog.com/e/2007 ]
May 14 00:40:34 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:40:41 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:40:41 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=1 ssid="wharfedale" auth_failures=2 duration=26 reason=CONN_FAILED
May 14 00:41:22 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-REENABLED id=1 ssid="wharfedale"
May 14 00:41:22 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 14 00:41:28 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-ASSOC-REJECT status_code=16
May 14 00:41:28 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=1 ssid="wharfedale" auth_failures=3 duration=57 reason=CONN_FAILED
May 14 01:17:01 quasi rsyslogd-2007: action 'action 17' suspended, next retry is Sun May 14 01:18:31 2017 [try http://www.rsyslog.com/e/2007 ]
May 14 01:17:01 quasi CRON[23419]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 14 02:17:01 quasi rsyslogd-2007: action 'action 17' suspended, next retry is Sun May 14 02:18:31 2017 [try http://www.rsyslog.com/e/2007 ]
May 14 02:17:01 quasi CRON[23490]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)

What I noticed is that under these circumstances the RX counters would keep going up but not the TX counters:

Code: Select all

pi@quasi:~ $ ifconfig  wlan0
wlan0     Link encap:Ethernet  HWaddr b8:27:eb:f7:3e:aa
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:4454449 errors:0 dropped:4307661 overruns:0 frame:0
          TX packets:23176 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:495002219 (472.0 MiB)  TX bytes:2884733 (2.7 MiB)

pi@quasi:~ $ ifconfig  wlan0
wlan0     Link encap:Ethernet  HWaddr b8:27:eb:f7:3e:aa
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:4454463 errors:0 dropped:4307675 overruns:0 frame:0
          TX packets:23176 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:495003059 (472.0 MiB)  TX bytes:2884733 (2.7 MiB)

Also, issuing a wpa_cli scan immediately fixes the situation:

Code: Select all

pi@quasi:~ $ wpa_cli scan
Selected interface 'wlan0'
OK

And my /var/log/syslog looks quite happy about it:

May 15 00:17:01 quasi systemd[1]: Starting Cleanup of Temporary Directories...
May 15 00:17:01 quasi CRON[24709]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 15 00:17:01 quasi systemd[1]: Started Cleanup of Temporary Directories.
May 15 00:27:21 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-SSID-REENABLED id=1 ssid="wharfedale"
May 15 00:27:21 quasi wpa_supplicant[552]: wlan0: Trying to associate with ac:f1:df60:44 (SSID='wharfedale' freq=2412 MHz)
May 15 00:27:21 quasi wpa_supplicant[552]: wlan0: Associated with ac:f1:df60:44
May 15 00:27:21 quasi wpa_supplicant[552]: wlan0: WPA: Key negotiation completed with ac:f1:df60:44 [PTK=CCMP GTK=CCMP]
May 15 00:27:21 quasi wpa_supplicant[552]: wlan0: CTRL-EVENT-CONNECTED - Connection to ac:f1:df60:44 completed [id=1 id_str=]
May 15 00:27:21 quasi dhcpcd[499]: wlan0: carrier acquired
May 15 00:27:21 quasi dhcpcd[499]: wlan0: adding address fe80::e12e:8e9d:3212:7309
May 15 00:27:21 quasi dhcpcd[499]: wlan0: IAID eb:f7:3e:aa
May 15 00:27:22 quasi dhcpcd[499]: wlan0: soliciting an IPv6 router
May 15 00:27:22 quasi dhcpcd[499]: wlan0: rebinding lease of 192.168.1.8
May 15 00:27:23 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::e12e:8e9d:3212:7309.
May 15 00:27:23 quasi avahi-daemon[448]: New relevant interface wlan0.IPv6 for mDNS.
May 15 00:27:23 quasi avahi-daemon[448]: Registering new address record for fe80::e12e:8e9d:3212:7309 on wlan0.*.
May 15 00:27:25 quasi ntpd[647]: Listen normally on 337 wlan0 fe80::e12e:8e9d:3212:7309 UDP 123
May 15 00:27:25 quasi ntpd[647]: peers refreshed
May 15 00:27:28 quasi dhcpcd[499]: wlan0: leased 192.168.1.8 for 86400 seconds
May 15 00:27:28 quasi avahi-daemon[448]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.8.
May 15 00:27:28 quasi dhcpcd[499]: wlan0: adding route to 192.168.1.0/24
May 15 00:27:28 quasi avahi-daemon[448]: New relevant interface wlan0.IPv4 for mDNS.
May 15 00:27:28 quasi dhcpcd[499]: wlan0: adding default route via 192.168.1.2
May 15 00:27:28 quasi avahi-daemon[448]: Registering new address record for 192.168.1.8 on wlan0.IPv4.
May 15 00:27:30 quasi ntpd[647]: Listen normally on 338 wlan0 192.168.1.8 UDP 123
May 15 00:27:30 quasi ntpd[647]: peers refreshed
May 15 00:27:35 quasi dhcpcd[499]: wlan0: no IPv6 Routers available

I think it might have something to do with the router (notice these CTRL-EVENT-REGDOM-CHANGE messages which are not very good I guess), still I don't see why it shouldn't automatically recover at some point without manual intervention.
I also haven't been able to reproduce this at will, so this gets even more frustrating if it only happens so often.
I guess could add an hourly cron job to run "wpa_cli scan", but this doesn't look like a proper solution to me.
Any idea what might be wrong here?

Thanks!

runboy93 · Sun May 14, 2017 11:37 pm

Buy official WiFi dongle, much stable and stronger signal.

iurly · Sun May 14, 2017 11:48 pm

runboy93 wrote:Buy official WiFi dongle, much stable and stronger signal.

That's of course an option I guess...
Though it looks more like a software issue with wpa_supplicant to me, and a high level one at that.
I mean, hardware might be responsible for instability issues, but this one?
Software should be able to recover from that eventually, one way or another.
Or am I wrong?

bnz99 · Mon May 15, 2017 8:09 am

I'm having the same problem. I'd be glad to hear any solution that you possibly find. Just out of curiosity: how is your rpi3 powered? Is it powered by the official raspberry power supply or do you use the usb port of a TV / hub or similar? If the latter is the case, did you try the official power supply? Unfortunately, my raspberry pi is embeeded into a bigger DIY build, that it's hard for me to change and test it.

iurly · Tue May 16, 2017 6:31 am

Hi, thanks for your reply.
In my case, it is powered by a DIN rail power supply by RS, which should provide 2A of power. So I strongly doubt the power supply could be held responsible for my issues.
As I said, it's most probably the router's (access point) fault, which, for starters, is fiddling with the regulatory domain. Then it's rejecting any authentication request. In that case I had to reboot it because it wasn't letting in other devices either.

What really bothers me is that the raspberrypi would somehow blacklist the access point, and not even a power cycle of the router would fix it. However, forcing a "wpa_cli scan" on the raspberrypi worked every time I tried.

What I'm gonna try next would be to try and reproduce this issue by purpotedly changing the WPA-PSK on the AP so to make it wrong, and then changing it back, to see if the raspberrypi would try again.
I'll let you know what comes out of it. Unfortunately this setup is at a friend's place so it might be a while before I get to try it.

Are you able to gather any logs from your system? Any chance you could try adding a cron job to periodically run a"wpa_cli scan"?

Cheers!

Rpi3 wlan0 won't reconnect

Rpi3 wlan0 won't reconnect

Re: Rpi3 wlan0 won't reconnect

Re: Rpi3 wlan0 won't reconnect

Re: Rpi3 wlan0 won't reconnect

Re: Rpi3 wlan0 won't reconnect