Bug 1900580

Summary: WiFi takes about 30 seconds to reconnect after standby/sleep
Product: [Fedora] Fedora Reporter: Emil Kristensen <emil>
Component: NetworkManagerAssignee: Lubomir Rintel <lkundrak>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 33CC: acardace, bgalvani, dcbw, emil, fgiudici, gnome-sig, lkundrak, mclasen, rstrode, sandmann, thaller
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: NetworkManager-1.26.8-1.fc33 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-04-21 21:41:24 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
NetworkManager log
none
wpa supplicant log none

Description Emil Kristensen 2020-11-23 12:20:28 UTC
Description of problem:
I have a Dell XPS 13 (9380) with Fedora 33.


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Turn on computer
2. Login
3. Close lid to enter standby
4. Open computer
5. Login
6. Wait approximately 30 secs before Wifi connects

Actual results:
Wifi connection is slow. It is so slow that is is distracting right now. It is like the system is waiting for some timeout before trying again. It is quite annoying to wait for every single time as the rest of the OS starts very fast from sleep.

Expected results:
Wifi to connect with in a few secs.

Additional info:
I've tried to debug it myself. I've read something about enable power save makes it faster, but it is on:

[ek@dell-xps ~]$ iwconfig wlp2s0 
wlp2s0    IEEE 802.11  ESSID:"[WIFI-SSID]"  
          Mode:Managed  Frequency:5.18 GHz  Access Point: [MAC-HIDDEN] 
          Bit Rate=6 Mb/s   Tx-Power=23 dBm   
          Retry short limit:7   RTS thr:off   Fragment thr:off
          Power Management:on
          Link Quality=63/70  Signal level=-47 dBm  
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:49   Missed beacon:0

How can I provide the data needed to fix this issue?

Comment 1 Thomas Haller 2020-11-23 12:43:10 UTC
> How can I provide the data needed to fix this issue?

Collect full level=TRACE logs of NetworkManager and debug logs of wpa_supplicant.

Read https://cgit.freedesktop.org/NetworkManager/NetworkManager/tree/contrib/fedora/rpm/NetworkManager.conf#n28 for hints about logging for NetworkManager.

To get debug logs for supplicant, add "-ddd" to OTHER_ARGS in /etc/sysconfig/wpa_supplicant, and restart wpa_supplicant.

Comment 2 Emil Kristensen 2020-11-26 10:08:40 UTC
To show that I am up-to-date:
$ sudo dnf upgrade --refresh
[sudo] password for ek: 
Fedora 33 openh264 (From Cisco) - x86_64                                              731  B/s | 989  B     00:01    
Fedora Modular 33 - x86_64                                                             42 kB/s |  24 kB     00:00    
Fedora Modular 33 - x86_64 - Updates                                                   26 kB/s |  23 kB     00:00    
Fedora 33 - x86_64 - Updates                                                           24 kB/s |  20 kB     00:00    
Fedora 33 - x86_64                                                                     28 kB/s |  24 kB     00:00    
teams                                                                                 3.1 kB/s | 3.0 kB     00:00    
Dependencies resolved.
Nothing to do.
Complete!

Wakeup time:
$ journalctl -n4 -u sleep.target
Nov 26 10:44:23 dell-xps systemd[1]: Stopped target Sleep.

I got the log files with these commands:
NetworkManager log until "manager: NetworkManager state is now CONNECTED_GLOBAL":
$ journalctl -u NetworkManager --since "2020-11-26 10:44:23"

wpa_supplicant logs:
$ journalctl -u wpa_supplicant --since "2020-11-26 10:44:23"


What is this P2P thing? It seems like it is failing

Also this time it seems the connection "only" was 15 secs. I rebooted my laptop to make a clean log. Sometimes it takes about 30 secs. However 15 secs is still slow.

Comment 3 Emil Kristensen 2020-11-26 10:09:14 UTC
Created attachment 1733691 [details]
NetworkManager log

Comment 4 Emil Kristensen 2020-11-26 10:10:23 UTC
Created attachment 1733693 [details]
wpa supplicant log

Comment 5 Emil Kristensen 2021-04-11 10:16:18 UTC
I've got some new information. I think it is related to some broken P2P driver. See the following log:

Apr 11 12:09:32 dell-xps NetworkManager[1184]: <info>  [1618135772.1578] Wi-Fi P2P device controlled by interface wlp2s0 created
Apr 11 12:09:32 dell-xps NetworkManager[1184]: <info>  [1618135772.1580] manager: (p2p-dev-wlp2s0): new 802.11 Wi-Fi P2P device (/org/freedesktop/NetworkManager/Devices/6)
Apr 11 12:09:32 dell-xps NetworkManager[1184]: <info>  [1618135772.1582] device (p2p-dev-wlp2s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Apr 11 12:09:32 dell-xps NetworkManager[1184]: <info>  [1618135772.1587] device (wlp2s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Apr 11 12:09:32 dell-xps NetworkManager[1184]: <info>  [1618135772.1597] device (p2p-dev-wlp2s0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Apr 11 12:09:32 dell-xps NetworkManager[1184]: <warn>  [1618135772.1605] sup-iface[xxxxxxxxxxxxxxxx,1,wlp2s0]: call-p2p-cancel: failed with P2P cancel failed
Apr 11 12:09:32 dell-xps gnome-shell[1999]: Removing a network device that was not added
Apr 11 12:09:32 dell-xps wpa_supplicant[1370]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Apr 11 12:09:33 dell-xps gnome-shell[1999]: libinput error: event5  - DELL08AF:00 06CB:76AF Touchpad: client bug: event processing lagging behind by 14ms, your system is too slow
Apr 11 12:09:33 dell-xps wpa_supplicant[1370]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Apr 11 12:09:33 dell-xps wpa_supplicant[1370]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Apr 11 12:09:36 dell-xps wpa_supplicant[1370]: wlp2s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Apr 11 12:09:39 dell-xps gsd-media-keys[2276]: Couldn't lock screen: Timeout was reached
Apr 11 12:09:46 dell-xps NetworkManager[1184]: <info>  [1618135786.7295] policy: auto-activating connection 'EK-5GHz' (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)

I have compared the connection log with my old ThinkPad and it does not spend time on P2P.

I have tried to add p2p_disabled=1 in /etc/wpa_supplicant/wpa_supplicant.conf but it does not seem to make any difference. I do not know how to check if wpa_supplicant is reading that parameter except for the config file location matching the file it list in systemctl status wpa_supplicant

[ek@dell-xps ~]$ systemctl status wpa_supplicant
● wpa_supplicant.service - WPA supplicant
     Loaded: loaded (/usr/lib/systemd/system/wpa_supplicant.service; disabled; vendor preset: disabled)
     Active: active (running) since Sun 2021-04-11 12:02:57 CEST; 11min ago
   Main PID: 1370 (wpa_supplicant)
      Tasks: 1 (limit: 18735)
     Memory: 4.1M
        CPU: 132ms
     CGroup: /system.slice/wpa_supplicant.service
             └─1370 /usr/sbin/wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -u -s

What is next now? On my other laptop wifi connection after sleep takes around 3 secs, on this one it takes around 20 secs. It seems clear to me that there is some timeout every time it connects.

Comment 6 Emil Kristensen 2021-04-11 10:19:01 UTC
Additionally this line "manager: (p2p-dev-wlp2s0): new 802.11 Wi-Fi P2P device (/org/freedesktop/NetworkManager/Devices/6)" with the number in the end.

It keeps increasing for every time i suspend and resume my laptop with Fedora. Like it always fails to add some P2P device. Such that it becomes /Devices/7, /Devices/8 etc.

Comment 7 Beniamino Galvani 2021-04-12 07:33:50 UTC
I think the problem is similar to:

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/574

and is not related to the P2P device. The problem is that NM does multiple scans before auto-activating the network connection.

There is already a fix in branch nm-1-26; what is missing is a new bugfix release (1.26.8) and a Fedora update for it.

Comment 8 Emil Kristensen 2021-04-13 08:24:30 UTC
(In reply to Beniamino Galvani from comment #7)

It looks very much like my issue. I only blamed P2P because I wasn't able to identify whether the issue is related to the wifi scan. However it matches pretty well as the connection itself is really fast, pretty much instant once NetworkManager decides to auto connect.

I do not think 1.26.8 will make it into Fedora 33 anytime soon. See: https://src.fedoraproject.org/rpms/NetworkManager/commits/f33

Fedora 33 is still at 10.26.6, and from the website I linked it looks like updates to NetworkManager are rare.

Fedora 34 is on 1.30.2 and from what I can see here: https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/blob/1.30.2/src/core/devices/wifi/nm-device-wifi.c#L1748 that version does contain the fix for that issue.

I'll test again later, most likely in Fedora 34 instead of 33. I usually update Fedora right away once the stable version comes out (looks like it might be released in 7 days or so) :) And I think that might happen faster than a bugfix update to NetworkManager.

Thank you very much for your help. I really hope this resolves the issue :)

Comment 9 Thomas Haller 2021-04-13 08:35:52 UTC
> I do not think 1.26.8 will make it into Fedora 33 anytime soon. See: https://src.fedoraproject.org/rpms/NetworkManager/commits/f33

The upstream maintainers of NetworkManager also maintain the Fedora package.
So, things happen, when somebody thinks it's important enough to do the work.

We infrequently release minor releases (like 1.26.8), and less frequently as time goes by.
But by now, there is a good mount of fixes on nm-1-26 branch. So a 1.26.8 release is due.

And minor releases (like 1.26.8) will reach the respective Fedora version, once they are done.


And of course, the more somebody expresses a need for an update, the more important an update will be perceived. So, thanks for the report!!


Btw, if you wish you can also try the copr repositories that are build from upstream:
https://copr.fedorainfracloud.org/coprs/networkmanager/
These are maintained by the same people.

Comment 10 Emil Kristensen 2021-04-13 13:30:18 UTC
(In reply to Thomas Haller from comment #9)
> And of course, the more somebody expresses a need for an update, the more
> important an update will be perceived. So, thanks for the report!!

I'm happy to hear that my effort is worth something :)

> Btw, if you wish you can also try the copr repositories that are build from
> upstream:
> https://copr.fedorainfracloud.org/coprs/networkmanager/
> These are maintained by the same people.

I've tried this now with
$ dnf copr enable networkmanager/NetworkManager-1.28

After a update I've got this version now:
$ nmcli --version
nmcli tool, version 1.28.1-27001.copr.6e4b1b25cb.fc33

After a reboot the WiFi now connect within a few secs of my computer coming back to life after suspend. It takes about the same time as it does for me to type my password to login (I've only tested it two times after a single reboot though). It other words it is as expected/usable now, and it seems that the latest fixes in the 1.28 branch fixes the issue I've reported here :)

Though I am not sure how version 1.28.1-27001 from copr is relative to version 1.28.8 you are talking about.

Comment 11 Thomas Haller 2021-04-13 13:35:13 UTC
>  nmcli tool, version 1.28.1-27001.copr.6e4b1b25cb.fc33
>
>  Though I am not sure how version 1.28.1-27001 from copr is relative to version 1.28.8 you are talking about.


the version is a build from git-commit 6e4b1b25cb, which is the current tip of "nm-1-28" branch.

`git describe 6e4b1b25cb` gives 1.28.1-dev-47-g6e4b1b25cbb4, meaning it's tag "1.28.1-dev" + 47 patches.

Comment 12 Thomas Haller 2021-04-13 13:40:19 UTC
>  Though I am not sure how version 1.28.1-27001 from copr is relative to version 1.28.8 you are talking about.

I was talking about 1.26.8. Fedora 33 is stuck with 1.26.x, and will get minor releases to 1.26.x only.

You took 1.28.x from a new stable branch. But there is no problem with that. New releases are supposed to be backward compatible, so that is supposed to work just fine also on Fedora 33.

Comment 13 Emil Kristensen 2021-04-13 13:44:00 UTC
(In reply to Thomas Haller from comment #12)
> >  Though I am not sure how version 1.28.1-27001 from copr is relative to version 1.28.8 you are talking about.
> 
> I was talking about 1.26.8. Fedora 33 is stuck with 1.26.x, and will get
> minor releases to 1.26.x only.
> 
> You took 1.28.x from a new stable branch. But there is no problem with that.
> New releases are supposed to be backward compatible, so that is supposed to
> work just fine also on Fedora 33.

I got version 1.26.x and 1.28.x mixed up for some reason. I can try with 1.26 if that is helpful for you? Otherwise I think I'll just let it be as it is now :)

Comment 14 Thomas Haller 2021-04-13 13:47:23 UTC
> I can try with 1.26 if that is helpful for you?

Not necessary. Thanks :)

Comment 15 Fedora Update System 2021-04-19 11:07:53 UTC
FEDORA-2021-8a91778c77 has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2021-8a91778c77

Comment 16 Fedora Update System 2021-04-19 18:33:10 UTC
FEDORA-2021-8a91778c77 has been pushed to the Fedora 33 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-8a91778c77`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-8a91778c77

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 17 Emil Kristensen 2021-04-20 08:16:50 UTC
Hello. I've performed a quick test.

$ sudo dnf copr disable networkmanager/NetworkManager-1.28
$ sudo dnf distro-sync

This was to get back to the standard Fedora version of NetworkManager without copr. Then to get the test update:

$ sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-8a91778c77

After a reboot I have network and the connection seem to be fast after the computer resume from suspend. It does not wait a long time with the question mark over the WiFi icon like it did before this update.

Now my current version is this:
$ nmcli --version
nmcli tool, version 1.26.8-1.fc33

I will report back if I run into any issues.

Comment 18 Fedora Update System 2021-04-21 21:41:24 UTC
FEDORA-2021-8a91778c77 has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.