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-11-16 14:48 EST (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!
Comment 2 Fedora End Of Life 2017-11-16 14:48:03 EST
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '25'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

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