GNOME Bugzilla – Bug 653870
network manager slow to reconnect after suspend/resume
Last modified: 2013-04-18 19:28:46 UTC
From downstream https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/274405 : > On my Thinkpad T61 with Intel 3945abg (iwl3945 driver), Network Manager usually takes around 1 minute before trying to reconnect to my WiFi router. I noticed that if I run the following command: > > # iwlist eth1 scan > > Network Manager seems to "wake-up" right after the scan is complete and connects right away. > > Would there be a way to send a signal upon resume that would trigger the same "wake-up" call? Occurs when suspending around one AP, and resuming at the same AP. Notable is that after resume, NetworkManager doesn't attempt to connect until some time, but forcing a scan seems to get it acting right again. Some workarounds and logs are available at the downstream report.
I would like to point out that this bug is still alive and kicking. I am running ArchLinux x86_64 using the following versions yaourt -Ss networkmanager extra/network-manager-applet 0.9.1.90-1 [installed] GNOME frontends to NetWorkmanager extra/networkmanager 0.9.1.90-1 [installed] Network Management daemon Pretty much all info given on launchpad is correct. Throwing a script into /usr/lib/pm-utils/sleep.d/ which runs "iwlist eth1 scanning &" does shorten the wakeup time down to ~10sec. Without running "iwlist eth1 scanning &" it takes 1min+ and approx. 5-10 popups asking for my sudo pw followed by a popup asking me for the wireless key, the key-textbox is prepolulated with the correct key. Any additional info can be provided upon request.
The launchpad bug doesn't really have the right logs for recent versions of NM. We'd need more complete debugging information, which can be gotten via the steps here: http://live.gnome.org/NetworkManager/Debugging Specifically, we'd need the supplicant debug logs to see what the supplicant is actually getting from the driver, which is what NM also gets. So if the wifi driver is for some reason refusing to scan right after resume, that's a problem with the wifi driver, but we need the supplicant debug log to figure that out.
Ok, here it comes, hope i am not drowning you in information: System running is most recent Arch Linux as of 10/22/2011 uname -a Linux zwerg 3.0-ARCH #1 SMP PREEMPT Wed Oct 19 10:27:51 CEST 2011 x86_64 Intel(R) Core(TM)2 Duo CPU T7300 @ 2.00GHz GenuineIntel GNU/Linux lspci -vn 03:00.0 0280: 8086:4227 (rev 02) Subsystem: 8086:1011 Flags: bus master, fast devsel, latency 0, IRQ 48 Memory at df3ff000 (32-bit, non-prefetchable) [size=4K] Capabilities: [c8] Power Management version 2 Capabilities: [d0] MSI: Enable+ Count=1/1 Maskable- 64bit+ Capabilities: [e0] Express Legacy Endpoint, MSI 00 Capabilities: [100] Advanced Error Reporting Capabilities: [140] Device Serial Number 00-1c-bf-ff-ff-2c-0d-ef Kernel driver in use: iwl3945 Kernel modules: iwl3945 dmesg: [ 212.110075] ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 220.642661] wlan0: direct probe to 00:24:fe:ab:41:92 (try 1/3) [ 220.840028] wlan0: direct probe to 00:24:fe:ab:41:92 (try 2/3) [ 221.040022] wlan0: direct probe to 00:24:fe:ab:41:92 (try 3/3) [ 221.240020] wlan0: direct probe to 00:24:fe:ab:41:92 timed out [ 229.984835] wlan0: direct probe to 00:24:fe:ab:41:92 (try 1/3) [ 230.183356] wlan0: direct probe to 00:24:fe:ab:41:92 (try 2/3) [ 230.383363] wlan0: direct probe to 00:24:fe:ab:41:92 (try 3/3) [ 230.583359] wlan0: direct probe to 00:24:fe:ab:41:92 timed out [ 238.986698] mei 0000:00:03.0: unexpected reset. [ 239.321825] wlan0: direct probe to 00:24:fe:ab:41:92 (try 1/3) [ 239.520024] wlan0: direct probe to 00:24:fe:ab:41:92 (try 2/3) [ 239.720027] wlan0: direct probe to 00:24:fe:ab:41:92 (try 3/3) [ 239.920028] wlan0: direct probe to 00:24:fe:ab:41:92 timed out [ 250.429172] wlan0: authenticate with 00:24:fe:e8:71:65 (try 1) [ 250.431857] wlan0: authenticated [ 250.433143] wlan0: associate with 00:24:fe:e8:71:65 (try 1) [ 250.436148] wlan0: RX AssocResp from 00:24:fe:e8:71:65 (capab=0x431 status=0 aid=1) [ 250.436155] wlan0: associated [ 250.443742] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready [ 261.136654] wlan0: no IPv6 routers present syslog: Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): now managed Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): bringing up device. Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): preparing device. Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): deactivating device (reason 'managed') [2] Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: starting -> ready Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42] Oct 22 02:15:19 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: ready -> inactive Oct 22 02:15:24 localhost NetworkManager[933]: <info> Auto-activating connection 'Auto Erdnussmann'. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) starting connection 'Auto Erdnussmann' Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0/wireless): access point 'Auto Erdnussmann' has security, but secrets are required. Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0] Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0] Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0/wireless): connection 'Auto Erdnussmann' has security, and secrets exist. No new secrets needed. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: added 'ssid' value 'Erdnussmann' Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: added 'scan_ssid' value '1' Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: added 'key_mgmt' value 'WPA-PSK' Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: added 'auth_alg' value 'OPEN' Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: added 'psk' value '<omitted>' Oct 22 02:15:24 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Oct 22 02:15:24 localhost NetworkManager[933]: <info> Config: set interface ap_scan to 1 Oct 22 02:15:24 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: inactive -> scanning Oct 22 02:15:27 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: scanning -> authenticating Oct 22 02:15:49 localhost NetworkManager[933]: <warn> Activation (wlan0/wireless): association took too long. Oct 22 02:15:49 localhost NetworkManager[933]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0] Oct 22 02:15:49 localhost NetworkManager[933]: <warn> Activation (wlan0/wireless): asking for new secrets Oct 22 02:15:49 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: authenticating -> disconnected Oct 22 02:15:49 localhost NetworkManager[933]: <warn> Couldn't disconnect supplicant interface: This interface is not connected. Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Oct 22 02:15:54 localhost NetworkManager[933]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0] Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Oct 22 02:15:54 localhost NetworkManager[933]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0/wireless): connection 'Auto Erdnussmann' has security, and secrets exist. No new secrets needed. Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: added 'ssid' value 'Erdnussmann' Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: added 'scan_ssid' value '1' Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: added 'key_mgmt' value 'WPA-PSK' Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: added 'auth_alg' value 'OPEN' Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: added 'psk' value '<omitted>' Oct 22 02:15:54 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Oct 22 02:15:54 localhost NetworkManager[933]: <info> Config: set interface ap_scan to 1 Oct 22 02:15:54 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: disconnected -> scanning Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: scanning -> authenticating Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: authenticating -> associating Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'Erdnussmann'. Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0] Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds) Oct 22 02:15:57 localhost NetworkManager[933]: <info> dhcpcd started with pid 2475 Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0) Beginning IP6 addrconf. Oct 22 02:15:57 localhost dhcpcd[2475]: version 5.2.12 starting Oct 22 02:15:57 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. Oct 22 02:15:57 localhost dhcpcd[2475]: wlan0: rebinding lease of 192.168.8.39 Oct 22 02:15:57 localhost NetworkManager[933]: <info> (wlan0): DHCPv4 state changed nbi -> preinit Oct 22 02:15:57 localhost dhcpcd[2475]: wlan0: acknowledged 192.168.8.39 from 192.168.8.254 Oct 22 02:15:57 localhost dhcpcd[2475]: wlan0: checking for 192.168.8.39 Oct 22 02:16:02 localhost dhcpcd[2475]: wlan0: leased 192.168.8.39 for 864000 seconds Oct 22 02:16:02 localhost NetworkManager[933]: <info> (wlan0): DHCPv4 state changed preinit -> bound Oct 22 02:16:02 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled... Oct 22 02:16:02 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started... Oct 22 02:16:02 localhost NetworkManager[933]: <info> address 192.168.8.39 Oct 22 02:16:02 localhost NetworkManager[933]: <info> prefix 24 (255.255.255.0) Oct 22 02:16:02 localhost NetworkManager[933]: <info> gateway 192.168.8.254 Oct 22 02:16:02 localhost NetworkManager[933]: <info> nameserver '192.168.8.254' Oct 22 02:16:02 localhost NetworkManager[933]: <info> domain name 'fritz.box' Oct 22 02:16:02 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete. Oct 22 02:16:18 localhost NetworkManager[933]: <info> (wlan0): IP6 addrconf timed out or failed. Oct 22 02:16:18 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) scheduled... Oct 22 02:16:18 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) started... Oct 22 02:16:18 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... Oct 22 02:16:18 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Timeout) complete. Oct 22 02:16:18 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... Oct 22 02:16:19 localhost NetworkManager[933]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0] Oct 22 02:16:19 localhost NetworkManager[933]: <info> Policy set 'Auto Erdnussmann' (wlan0) as default for IPv4 routing and DNS. Oct 22 02:16:19 localhost NetworkManager[933]: <info> Activation (wlan0) successful, device activated. Oct 22 02:16:19 localhost NetworkManager[933]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete. wpa-supplicant.log: Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) Trying to authenticate with 00:24:fe:e8:71:65 (SSID='Erdnussmann' freq=2427 MHz) Trying to associate with 00:24:fe:e8:71:65 (SSID='Erdnussmann' freq=2427 MHz) Associated with 00:24:fe:e8:71:65 WPA: Key negotiation completed with 00:24:fe:e8:71:65 [PTK=CCMP GTK=TKIP] CTRL-EVENT-CONNECTED - Connection to 00:24:fe:e8:71:65 completed (auth) [id=0 id_str=] Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) CTRL-EVENT-DISCONNECTED bssid=00:24:fe:ab:41:92 reason=4 Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) Trying to authenticate with 00:24:fe:e8:71:65 (SSID='Erdnussmann' freq=2427 MHz) Trying to associate with 00:24:fe:e8:71:65 (SSID='Erdnussmann' freq=2427 MHz) Associated with 00:24:fe:e8:71:65 WPA: Key negotiation completed with 00:24:fe:e8:71:65 [PTK=CCMP GTK=TKIP] CTRL-EVENT-CONNECTED - Connection to 00:24:fe:e8:71:65 completed (reauth) [id=0 id_str=] Trying to authenticate with 00:24:fe:ab:41:92 (SSID='Erdnussmann' freq=5180 MHz) CTRL-EVENT-DISCONNECTED bssid=00:24:fe:ab:41:92 reason=4
I noticed today that this bug only occurs if you stay within a wireless network. If i am connected to Network A and suspend my computer and resume in the range of the same network the above bug will happen. If i suspend on Network A and resume in the range of Network B it will connect instantly. Hardware is a Lenovo Thinkpad T61 7661 if that helps
Again, we need the supplicant debug logs as described above, those are the only things that will show when scan requests to the driver happen and when they are denied by the driver. wpa_supplicant does all the scan handling; NetworkManager simply requests scans from the supplicant. NM will note when they fail, but the supplicant also does internal scan requests and failures of those aren't relayed to NM (since they weren't requested by NM). We need to know if the driver is denying the supplicant's scan requests, which the debug logs will tell us.
Created attachment 200841 [details] wpa supplicant log That's mostlikely way more data than you wanted....
Any News on the issue? Should i forward the bug to the wpa-supplicant devs or will you do it?
Dan, is log provided in comment6 sufficient ?
In the logs, one run of the supplicant starts near the bottom at 1320600698.708334. From there until 1320601333.545348, which is a period of about 10 minutes, the supplicant simply cannot connect to Erdnussman, which is likely due to driver issues or a flaky AP. Every time it tries, you'll see: 1320601250.965113: nl80211: Event message available 1320601250.965179: nl80211: MLME event 37; timeout with 00:24:fe:ab:41:92 1320601250.965191: SME: Authentication timed out That's something well below the supplicant, and would have to be debugged separately (either by rebooting the AP, which sometimes is required on consumer-level access points) or by rmmod-ing the kernel driver, modprobing it back, and seeing if that fixes things. It looks like some of the suspend/resume cycles are pretty short, ie: 1320258906.123299: netlink: Operstate: linkmode=0, operstate=6 1320259019.455685: dbus: fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1) which is about two minutes. Assuming that is really a suspend/resume cycle, lets pick that one apart: 1320259019.455685: dbus: fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1) 1320259019.455719: Initializing interface 'wlan0' conf 'N/A' driver 'nl80211,wext' ctrl_interface 'N/A' bridge 'N/A' *** NM wakes up and reinitializes the wifi interface, telling the supplicant to start using wlan0 1320259019.857013: dbus: fi.w1.wpa_supplicant1.Interface.Scan (/fi/w1/wpa_supplicant1/Interfaces/7) 1320259019.857105: nl80211: Scan trigger failed: ret=-16 (Device or resource busy) *** the first scan is requested, but fails because the driver is already scanning; usually not a huge issue since scan results will be delivered to the supplicant anyway when the ongoing scan finishes. 1320259024.149017: Received scan results (22 BSSes) *** scan finished, it took about 4 seconds, which is pretty quick. 1320259024.175383: dbus: Register network object '/fi/w1/wpa_supplicant1/Interfaces/7/Networks/0' 1320259024.198131: dbus: fi.w1.wpa_supplicant1.Interface.SelectNetwork (/fi/w1/wpa_supplicant1/Interfaces/7) *** NetworkManager asks the supplicant to connect to connect to "Erdnussmann". It has now been 5 seconds since resume, and everything seems to be going well. 1320259024.199133: Scan requested (ret=0) - scan timeout 30 seconds *** the supplicant requests an internal scan due to the connection request, which is sub-optimal but that's how the supplicant works. 1320259027.929454: selected WPA AP 00:24:fe:ab:41:92 ssid='Erdnussmann' *** the supplicant actually begins to connect to Erdnussmann 1320259027.930853: nl80211: Authentication request send successfully *** The supplicant successfully sends the authentication request to the driver 1320259028.542160: nl80211: MLME event 37; timeout with 00:24:fe:ab:41:92 1320259028.542185: Setting scan request: 5 sec 0 usec *** unfortunately, the driver hasn't been able to talk to the AP, despite the fact that the AP is known to exist from scan results. so the supplicant tries again. this could be due to driver problems, or the AP being flaky. 1320259037.272278: SME: Authentication response: peer=00:24:fe:e8:71:65 auth_type=0 status_code=0 *** yay, the second authentication request was successful 1320259037.295507: CTRL-EVENT-CONNECTED - Connection to 00:24:fe:e8:71:65 completed (auth) [id=0 id_str=] *** and finally we're connected to Erdnussmann So in this specific case, after resume, a connection to Erdnussmann took a total of 18 seconds, which is pretty bad, actually. But that appears to be almost entirely due to the "MLME event 32; timeout" issue, which also appears later in the logs. At this point, this appears to be more of a kernel driver issue than anything to do with the supplicant or NetworkManager. Any chance an updated kernel solves the issue? What kernel are you currently running? There have been some fixes to the iwl3945 driver in the past half-year or so that may fix some of these issues.
May I presume this to be NOTGNOME? Please reopen if that is not the case.