Bug 1471126 - WiFi is constantly reconnecting between 2.4 and 5 GHz without obvious reasons
WiFi is constantly reconnecting between 2.4 and 5 GHz without obvious reasons
Status: NEW
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
27
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Lubomir Rintel
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-07-14 09:19 EDT by Vít Ondruch
Modified: 2017-10-09 16:18 EDT (History)
6 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: ---


Attachments (Terms of Use)

  None (edit)
Description Vít Ondruch 2017-07-14 09:19:29 EDT
Description of problem:

~~~
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: disconnect from AP 58:6d:8f:ae:c1:93 for new auth to 58:6d:8f:ae:c1:94
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: authenticate with 58:6d:8f:ae:c1:94
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: send auth to 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:34:38 localhost.localdomain NetworkManager[992]: <info>  [1500032078.7089] device (wlp58s0): supplicant interface state: completed -> authenticating
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: authenticated
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: associate with 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: RX AssocResp from 58:6d:8f:ae:c1:94 (capab=0x11 status=0 aid=1)
Jul 14 13:34:38 localhost.localdomain kernel: wlp58s0: associated
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Associated with 58:6d:8f:ae:c1:94
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:94 [PTK=CCMP GTK=CCMP]
Jul 14 13:34:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:94 completed [id=0 id_str=]
Jul 14 13:34:38 localhost.localdomain NetworkManager[992]: <info>  [1500032078.7319] device (wlp58s0): supplicant interface state: authenticating -> associated
Jul 14 13:34:38 localhost.localdomain NetworkManager[992]: <info>  [1500032078.7447] device (wlp58s0): supplicant interface state: associated -> 4-way handshake
Jul 14 13:34:38 localhost.localdomain NetworkManager[992]: <info>  [1500032078.7456] device (wlp58s0): supplicant interface state: 4-way handshake -> completed

... snip ...

Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:93 (SSID='VitaLinksysE4200' freq=2462 MHz)
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: disconnect from AP 58:6d:8f:ae:c1:94 for new auth to 58:6d:8f:ae:c1:93
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: authenticate with 58:6d:8f:ae:c1:93
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: send auth to 58:6d:8f:ae:c1:93 (try 1/3)
Jul 14 13:36:38 localhost.localdomain NetworkManager[992]: <info>  [1500032198.8228] device (wlp58s0): supplicant interface state: completed -> authenticating
Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:93 (SSID='VitaLinksysE4200' freq=2462 MHz)
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: authenticated
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: associate with 58:6d:8f:ae:c1:93 (try 1/3)
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: RX AssocResp from 58:6d:8f:ae:c1:93 (capab=0x411 status=0 aid=2)
Jul 14 13:36:38 localhost.localdomain kernel: wlp58s0: associated
Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Associated with 58:6d:8f:ae:c1:93
Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 14 13:36:38 localhost.localdomain NetworkManager[992]: <info>  [1500032198.8508] device (wlp58s0): supplicant interface state: authenticating -> associating
Jul 14 13:36:38 localhost.localdomain NetworkManager[992]: <info>  [1500032198.8551] device (wlp58s0): supplicant interface state: associating -> associated
Jul 14 13:36:38 localhost.localdomain NetworkManager[992]: <info>  [1500032198.8644] device (wlp58s0): supplicant interface state: associated -> 4-way handshake
Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:93 [PTK=CCMP GTK=CCMP]
Jul 14 13:36:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:93 completed [id=0 id_str=]
Jul 14 13:36:38 localhost.localdomain NetworkManager[992]: <info>  [1500032198.8771] device (wlp58s0): supplicant interface state: 4-way handshake -> completed

... snip ...

Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: disconnect from AP 58:6d:8f:ae:c1:93 for new auth to 58:6d:8f:ae:c1:94
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: authenticate with 58:6d:8f:ae:c1:94
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: send auth to 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:46:38 localhost.localdomain NetworkManager[992]: <info>  [1500032798.8240] device (wlp58s0): supplicant interface state: completed -> authenticating
Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: authenticated
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: associate with 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: RX AssocResp from 58:6d:8f:ae:c1:94 (capab=0x11 status=0 aid=1)
Jul 14 13:46:38 localhost.localdomain kernel: wlp58s0: associated
Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Associated with 58:6d:8f:ae:c1:94
Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 14 13:46:38 localhost.localdomain NetworkManager[992]: <info>  [1500032798.8467] device (wlp58s0): supplicant interface state: authenticating -> associating
Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:94 [PTK=CCMP GTK=CCMP]
Jul 14 13:46:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:94 completed [id=0 id_str=]
Jul 14 13:46:38 localhost.localdomain NetworkManager[992]: <info>  [1500032798.8629] device (wlp58s0): supplicant interface state: associating -> 4-way handshake
Jul 14 13:46:38 localhost.localdomain NetworkManager[992]: <info>  [1500032798.8634] device (wlp58s0): supplicant interface state: 4-way handshake -> completed

... snip ...

Jul 14 13:50:36 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=fprintd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?
Jul 14 13:50:38 localhost.localdomain kernel: nfs: server nfs-01.eng.brq.redhat.com not responding, timed out
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:93 (SSID='VitaLinksysE4200' freq=2462 MHz)
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: disconnect from AP 58:6d:8f:ae:c1:94 for new auth to 58:6d:8f:ae:c1:93
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: authenticate with 58:6d:8f:ae:c1:93
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: send auth to 58:6d:8f:ae:c1:93 (try 1/3)
Jul 14 13:50:38 localhost.localdomain NetworkManager[992]: <info>  [1500033038.6469] device (wlp58s0): supplicant interface state: completed -> authenticating
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:93 (SSID='VitaLinksysE4200' freq=2462 MHz)
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: authenticated
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: associate with 58:6d:8f:ae:c1:93 (try 1/3)
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: RX AssocResp from 58:6d:8f:ae:c1:93 (capab=0x411 status=0 aid=2)
Jul 14 13:50:38 localhost.localdomain NetworkManager[992]: <info>  [1500033038.6636] device (wlp58s0): supplicant interface state: authenticating -> associating
Jul 14 13:50:38 localhost.localdomain kernel: wlp58s0: associated
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Associated with 58:6d:8f:ae:c1:93
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 14 13:50:38 localhost.localdomain NetworkManager[992]: <info>  [1500033038.6843] device (wlp58s0): supplicant interface state: associating -> associated
Jul 14 13:50:38 localhost.localdomain NetworkManager[992]: <info>  [1500033038.6942] device (wlp58s0): supplicant interface state: associated -> 4-way handshake
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:93 [PTK=CCMP GTK=CCMP]
Jul 14 13:50:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:93 completed [id=0 id_str=]
Jul 14 13:50:38 localhost.localdomain NetworkManager[992]: <info>  [1500033038.7122] device (wlp58s0): supplicant interface state: 4-way handshake -> completed

... snip ...

Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: disconnect from AP 58:6d:8f:ae:c1:93 for new auth to 58:6d:8f:ae:c1:94
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: authenticate with 58:6d:8f:ae:c1:94
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: send auth to 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:52:38 localhost.localdomain NetworkManager[992]: <info>  [1500033158.8307] device (wlp58s0): supplicant interface state: completed -> authenticating
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: authenticated
Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: associate with 58:6d:8f:ae:c1:94 (try 1/3)
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: RX AssocResp from 58:6d:8f:ae:c1:94 (capab=0x11 status=0 aid=1)
Jul 14 13:52:38 localhost.localdomain kernel: wlp58s0: associated
Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: Associated with 58:6d:8f:ae:c1:94
Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:94 [PTK=CCMP GTK=CCMP]
Jul 14 13:52:38 localhost.localdomain wpa_supplicant[1109]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:94 completed [id=0 id_str=]
Jul 14 13:52:38 localhost.localdomain NetworkManager[992]: <info>  [1500033158.8753] device (wlp58s0): supplicant interface state: authenticating -> associated
Jul 14 13:52:38 localhost.localdomain NetworkManager[992]: <info>  [1500033158.8764] device (wlp58s0): supplicant interface state: associated -> 4-way handshake
Jul 14 13:52:38 localhost.localdomain NetworkManager[992]: <info>  [1500033158.8767] device (wlp58s0): supplicant interface state: 4-way handshake -> completed
~~~

It is interesting to see that there is some pattern. It tries to reconnect every 38th second and it is always even minute. The shortest interval appears to be 120 seconds.


Version-Release number of selected component (if applicable):
I observe this behavior on Lenovo T470s if that might be hardware specific.

$ rpm -q NetworkManager
NetworkManager-1.8.0-6.fc27.x86_64

$ rpm -q kernel
kernel-4.11.0-2.fc26.x86_64
kernel-4.12.0-0.rc7.git2.1.fc27.x86_64
kernel-4.12.0-1.fc27.x86_64

$ uname -a
Linux localhost.localdomain 4.12.0-1.fc27.x86_64 #1 SMP Mon Jul 3 15:45:36 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux



How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
Comment 1 Francesco Giudici 2017-07-14 16:17:01 EDT
Hi Vit,
  IIRC, NetworkManager will trigger periodic scans every two minutes to allow promptly roaming in the case current WiFi network signal is low and another with the same SSID and better signal is available: yes, those are the 120 seconds you can see as the base unit interval between the two disconnections.

Looking at the logs, the two WiFi networks have two consecutive BSSIDs: these let me guess that you have an AP advertising the same WiFi network on both 2.4 and 5GHz.
My guess for the issue is that you are not very near the AP and the signal you get is not that great: every two minutes, when there is a new WiFi network scan, both the 2.4 and 5Ghz networks will be detected: if the beacon from the one you are not connected to is received with higher power that the other one your laptop will roam to the other frequency: as you are equally distant from both, you will get once a little more strong beacon from one and maybe the other round from the other.

This should not happen if you are very near the AP.
In this case the behavior seems correct... but of course you want to disable roaming for this case and connect to a specific one of the two (I would advice to the 5GHz one).
You can achieve this by setting a fixed bssid in the NM wifi connection:

nmcli conn modify VitaLinksysE4200Y 802-11-wireless.bssid 58:6d:8f:ae:c1:94

which will also completely disable the background scan.

Can you please check if this would solve your issue?
Thanks
Francesco
Comment 2 Vít Ondruch 2017-07-17 10:42:04 EDT
Hi Francesco,

Thanks for elaboration. Your explanation seems plausible. I'll need to test the proposed solution as soon as I'll get my LP home again.

Nevertheless, I consider the proposed solution just workaround. Is it the roaming algorithm really that simple to choose the AP just by signal strength? E.g. if strength was between 0-100, while AP 1 had strength 57 while AP 2 had strength 58, the AP 2 would be chosen? Is there some range, where the current connection had preference? Is there a way to adjust the range?
Comment 3 Vít Ondruch 2017-07-28 04:20:29 EDT
(In reply to Francesco Giudici from comment #1)
Hmm, so I was connected and did what you proposed during connection:

~~~ 
nmcli conn modify VitaLinksysE4200Y 802-11-wireless.bssid 58:6d:8f:ae:c1:94
~~~

But again I was reconnected.

Going to switch off WiFi and reconnect if that makes any difference ...
Comment 4 Vít Ondruch 2017-07-31 11:48:23 EDT
So after reconnection, the WiFi was stable for almost 3 days, although one reconnect happened, not sure why:

~~~
Jul 28 10:31:54 localhost.localdomain wpa_supplicant[1158]: wlp58s0: CTRL-EVENT-DISCONNECTED bssid=58:6d:8f:ae:c1:94 reason=4 locally_generated=1
Jul 28 10:31:54 localhost.localdomain NetworkManager[945]: <warn>  [1501230714.2741] sup-iface[0x55f53adf2830,wlp58s0]: connection disconnected (reason -4)
Jul 28 10:31:54 localhost.localdomain NetworkManager[945]: <info>  [1501230714.2917] device (wlp58s0): supplicant interface state: completed -> disconnected
Jul 28 10:31:54 localhost.localdomain NetworkManager[945]: <info>  [1501230714.3797] device (wlp58s0): supplicant interface state: disconnected -> scanning
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: SME: Trying to authenticate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 28 10:31:55 localhost.localdomain NetworkManager[945]: <info>  [1501230715.2507] device (wlp58s0): supplicant interface state: scanning -> authenticating
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: Trying to associate with 58:6d:8f:ae:c1:94 (SSID='VitaLinksysE4200' freq=5220 MHz)
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: Associated with 58:6d:8f:ae:c1:94
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jul 28 10:31:55 localhost.localdomain NetworkManager[945]: <info>  [1501230715.2619] device (wlp58s0): supplicant interface state: authenticating -> associated
Jul 28 10:31:55 localhost.localdomain NetworkManager[945]: <info>  [1501230715.2699] device (wlp58s0): supplicant interface state: associated -> 4-way handshake
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: WPA: Key negotiation completed with 58:6d:8f:ae:c1:94 [PTK=CCMP GTK=CCMP]
Jul 28 10:31:55 localhost.localdomain wpa_supplicant[1158]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to 58:6d:8f:ae:c1:94 completed [id=0 id_str=]
Jul 28 10:31:55 localhost.localdomain NetworkManager[945]: <info>  [1501230715.2883] device (wlp58s0): supplicant interface state: 4-way handshake -> completed
~~~
Comment 5 Beniamino Galvani 2017-08-03 05:44:43 EDT
(In reply to Vít Ondruch from comment #2)
> Hi Francesco,
> 
> Thanks for elaboration. Your explanation seems plausible. I'll need to test
> the proposed solution as soon as I'll get my LP home again.
> 
> Nevertheless, I consider the proposed solution just workaround. Is it the
> roaming algorithm really that simple to choose the AP just by signal
> strength? E.g. if strength was between 0-100, while AP 1 had strength 57
> while AP 2 had strength 58, the AP 2 would be chosen? Is there some range,
> where the current connection had preference? Is there a way to adjust the
> range?

I think this will be solved by:

https://bugzilla.gnome.org/show_bug.cgi?id=766482

which basically disables automatic scanning while the signal is good enough.
Comment 6 Jan Kurik 2017-08-15 05:34:44 EDT
This bug appears to have been reported against 'rawhide' during the Fedora 27 development cycle.
Changing version to '27'.

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