Bug 1471682 - wpa_supplicant randomly terminates WiFi connection, then fails to instantly reconnect [NEEDINFO]
wpa_supplicant randomly terminates WiFi connection, then fails to instantly r...
Status: NEW
Product: Fedora
Classification: Fedora
Component: wpa_supplicant (Show other bugs)
25
Unspecified Unspecified
unspecified Severity medium
: ---
: ---
Assigned To: Lubomir Rintel
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-07-17 05:06 EDT by Peter Backes
Modified: 2017-08-28 11:16 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
bgalvani: needinfo? (rtc)


Attachments (Terms of Use)
Sample log (5.20 KB, text/plain)
2017-07-17 05:06 EDT, Peter Backes
no flags Details

  None (edit)
Description Peter Backes 2017-07-17 05:06:22 EDT
Created attachment 1299733 [details]
Sample log

Description of problem:
I am using a Linksys WUSB600N v1 (serial numbers starts with JNW0) with the rt2800usb driver.

From time to time, wpa_supplicant terminates the connection, logging "CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1". (some web pages claim to be reason=4 is "Disassociated due to inactivity", but there is traffic on the device.) NetworkManager then tries to instantly reinitiate the connection, but wpa_supplicant fails with  "nl80211: send_and_recv->nl_recvmsgs failed: -33" and some seconds later, NetworkManager stops with "device (wlan0): link timed out."

It seems to happen fairly regularly (journalctl | grep CTRL-EVENT-DISCONNECTED| grep reason=4):
Apr 07 12:13:55 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:14:39 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:15:24 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:15:51 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:16:16 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:16:34 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 07 12:16:51 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 08 12:12:55 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 08 12:13:27 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 08 12:13:52 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:14:59 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:15:47 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:16:12 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:16:57 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:17:19 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 09 12:17:40 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 11 09:33:40 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 11 12:49:03 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 11 15:54:57 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 11 17:10:25 localhost wpa_supplicant[591]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 12 14:38:15 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 14 11:16:18 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 14 11:18:03 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 21 20:04:55 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 24 18:10:46 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 28 17:24:28 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Apr 28 20:09:57 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 01 11:41:52 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 03 12:29:19 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 03 13:44:49 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 04 15:00:17 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 04 22:45:45 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 05 09:16:15 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 08 15:03:15 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 08 18:48:43 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 08 19:49:14 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 08 22:19:42 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 08 23:35:10 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 09 15:05:41 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 12 11:41:02 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 13 17:41:59 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 14 17:57:30 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 14 21:12:59 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 24 13:33:21 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 26 22:50:57 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 27 15:06:55 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 27 15:09:00 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 28 16:47:43 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
May 30 20:57:10 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 02 09:14:02 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 02 14:44:31 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 04 22:14:59 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 07 21:35:11 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 08 20:21:09 localhost wpa_supplicant[602]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 10 13:06:37 localhost wpa_supplicant[624]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 10 21:07:08 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 11 13:08:06 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 12 07:53:34 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 15 17:56:00 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 16 00:41:28 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 16 16:03:31 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 18 18:07:45 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 18 19:42:58 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 19 09:43:29 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 22 21:55:43 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 23 08:34:52 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 23 12:35:20 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 24 20:20:50 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 24 20:21:52 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 25 22:52:52 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 27 08:08:51 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 27 10:54:21 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 28 08:40:19 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 29 11:10:49 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 30 10:32:37 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 30 11:03:08 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 30 16:18:38 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 30 17:04:08 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jun 30 20:49:39 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 01 16:32:40 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 03 11:49:33 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 07 20:52:43 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 08 11:53:14 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 08 12:38:44 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 09 00:09:14 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 09 18:25:45 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 11 17:56:16 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 12 02:41:44 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 13 20:42:13 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1
Jul 15 15:43:11 localhost wpa_supplicant[614]: wlan0: CTRL-EVENT-DISCONNECTED bssid=$BSSID reason=4 locally_generated=1


Version-Release number of selected component (if applicable):
wpa_supplicant-2.6-1.fc25.i686
NetworkManager-1.4.4-5.fc25.i686

How reproducible:
always

Steps to Reproduce:
1. wait until wpa_supplicant drops the connection

Actual results:
1. wpa_supplicant eventually drops the connection
2. After breaking down, the connection fails to re-establish

Expected results:
1. The connection does not break down
2. If it breaks down, it is re-established

Additional info:
When some time has passed after the failed attempt to re-estalish, NetworkManager tries again, and succeeds.

When I run "sudo nmcli connection up $CONNECTION" manually after the failed attempt to re-establish, the connect succeeds.

If I remember correctly, the connection drop did not happen until some (quite long) time ago.
Comment 1 Beniamino Galvani 2017-08-28 11:16:25 EDT
Can you please provide trace logs of the disconnection? To capture them:

 # add '-dd' to OTHER_ARGS in /etc/sysconfig/wpa_supplicant, then
 systemctl restart wpa_supplicant

 # set level=TRACE in the [logging] section
 # of /etc/NetworkManager/NetworkManager.conf, then
 systemctl restart NetworkManager

 # ... wait for a disconnection, then attach the output of the relevant logs, as
 journalctl -u NetworkManager -u wpa_supplicant -e

Thanks!

Note You need to log in before you can comment on or make changes to this bug.