Description of problem: NetworkManager disconnects from wifi *exactly* every 2 minutes. If I try to connect "by hand" with NetworkManager stopped, it almost never disconnects (few times an hour). Sometimes NetworkManager also gets completely "mad" disconnecting/reconnceting every 1 to 5 seconds: wifi is then unusable. Version-Release number of selected component (if applicable): NetworkManager-0.7.0.99-3.fc10.i386 kernel 2.6.27.19-170.2.35.fc10.i686 => lspci | grep Wireless 02:02.0 Network controller: Intel Corporation PRO/Wireless 2915ABG [Calexico2] Network Connection (rev 05) How reproducible: Always: disconnecting/reconnecting *exactly* every 2 minutes Always: NetworkManager is disconnecting/reconnecting wifi (random, but few times per hour). Sometimes : NetworkManager goes "mad" and connect/disconnect every 1 to 5 seconds Steps to Reproduce: 1. Connect to a wifi AP via NetworkManager (mine is hidden SSID, WPA personal TKIP/AES, DHCP) 2. check the quality of the signal: iwlist eth1 scan: Quality=97/100 Signal level=-27 dBm 3. start a tail -f /var/log/messages 4. watch NetworkManager disconnect/reconnect wifi every 2 minutes Actual results: - NetworkManager disconnects wifi every 2 minutes exactly - NetworkManager sometimes gets "mad" Expected results: - NetworkManager shouldn't disconnect anything Additional info: here is a log session (tail -f /var/log/messages): 1. Mar 16 16:38:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected 2. Mar 16 16:38:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning 3. Mar 16 16:38:26 microlaptop NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating 4. Mar 16 16:38:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associating -> associated 5. Mar 16 16:38:28 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake 6. Mar 16 16:38:28 microlaptop NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake 7. Mar 16 16:38:29 microlaptop NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed 8. Mar 16 16:40:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected 9. Mar 16 16:40:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning 10. Mar 16 16:40:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating 11. Mar 16 16:40:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associating -> associated 12. Mar 16 16:40:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake 13. Mar 16 16:40:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake 14. Mar 16 16:40:22 microlaptop NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed 15. Mar 16 16:40:26 microlaptop NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected 16. Mar 16 16:40:26 microlaptop NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning 17. Mar 16 16:40:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating 18. Mar 16 16:40:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associating -> associated 19. Mar 16 16:40:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake 20. Mar 16 16:40:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake 21. Mar 16 16:40:28 microlaptop NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed 22. Mar 16 16:42:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected 23. Mar 16 16:42:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning 24. Mar 16 16:42:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating 25. Mar 16 16:42:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associating -> associated 26. Mar 16 16:42:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake 27. Mar 16 16:42:21 microlaptop NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake 28. Mar 16 16:42:22 microlaptop NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed 29. Mar 16 16:44:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected 30. Mar 16 16:44:20 microlaptop NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning 31. Mar 16 16:44:26 microlaptop NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating 32. Mar 16 16:44:27 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associating -> associated 33. Mar 16 16:44:28 microlaptop NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake 34. Mar 16 16:44:28 microlaptop NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake 35. Mar 16 16:44:29 microlaptop NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed When NetworkManager is stopped (/etc/init.d/NetworkManager stop) and the wifi connection is initiated "by hand" it randomly disconnects/reconnects several times an hour but no more "2 minutes stuff". My dmesg shows several of these lines (doesn't seem to happen after boot time): ipw2200: Failed to send SYSTEM_CONFIG: Already sending a command. Kismet says I'm alone on my wifi channel (fixed channel). This behaviour ("2 minutes" and "mad") do not happen on another computer also connected to the same wifi AP (running Fedora9 i386 up to date using NetworkManager). This computer gets disconnected a few times per hour though. My Fedora is up to date. Those connections/disconnections can expose my network to some cracking.
Sounds like your AP (or the driver) is killing the connection due to periodic scans, which back off to a maximum 2 minute interval. There's no real reason this should be happening other than a driver bug. But a few questions: 1) has this always happened? or has it just started happening? NM hasn't changed it's scan behavior in a long long time, so if it just started happening, I'd suspect either AP changes or driver changes. 2) What wifi card is the "other computer" that is OK using? 3) Can you check how long the card takes to do a scan for me? In a root terminal, do the following a) service NetworkManager stop b) killall -TERM wpa_supplicant c) time /sbin/iwlist eth1 scan and report the time printed out in (c), which will be something like: real 0m0.255s user 0m0.001s sys 0m0.002s Your 2915 is an a/b/g card, thus supports more channels and thus a scan could take longer. If the AP thinks you're gone long enough, or the driver has a bug where it thinks it hasn't heard from the AP recently, it could disconnect you. I do have a 2915 somewhere, so I can try to reproduce the issue this week.
Reporter, could you please reply to the previous question? If you won't reply in one month, I will have to close this bug as INSUFFICIENT_DATA. Thank you. -- Fedora Bugzappers volunteer triage team https://fedoraproject.org/wiki/BugZappers
I'm Ubuntu 9.04 user with a similar wifi (Intel 2200BG, using ipw2200) and I am seeing the same 1-5 second cycle: Apr 28 19:14:12 altair NetworkManager: <info> (eth1): supplicant connection state: completed -> disconnected Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: disconnected -> scanning Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: scanning -> associating Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: associating -> associated Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: associated -> 4-way handshake Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: 4-way handshake -> group handshake Apr 28 19:14:13 altair NetworkManager: <info> (eth1): supplicant connection state: group handshake -> completed This happened after ~2 hours of regular use, lasted for ~10 minutes and then stabilized again. I suspect it has to do with ipw2200. Here's info on my system and my wifi: uname -a Linux altair 2.6.28-11-generic #42-Ubuntu SMP Fri Apr 17 01:57:59 UTC 2009 i686 GNU/Linux lspci -vvv 02:04.0 Network controller: Intel Corporation PRO/Wireless 2200BG [Calexico2] Network Connection (rev 05) Subsystem: Hewlett-Packard Company Device 12f6 Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx- Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx- Latency: 64 (750ns min, 6000ns max), Cache Line Size: 64 bytes Interrupt: pin A routed to IRQ 21 Region 0: Memory at d0000000 (32-bit, non-prefetchable) [size=4K] Capabilities: <access denied> Kernel driver in use: ipw2200 Kernel modules: ipw2200 iwlist scan time: real 0m0.004s user 0m0.000s sys 0m0.004s Please let me know if I can help with any further info.
I am seeing the same problem with an Atheros card on a IBM Thinkpad X40 laptop and using WEP encryption. If I recall correcly, I've seen the same problem at work with WPA. 02:02.0 Ethernet controller [0200]: Atheros Communications Inc. AR5212 802.11ab) Here's some messages from my syslog, as you can see the interval seems to be N*60 seconds, and sometimes it is as frequent as every other minute, at other times it can take 9 minutes between the drops: May 6 04:17:50 grue NetworkManager: <info> (wlan0): supplicant connection state: completed -> disconnected May 6 04:17:50 grue NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning May 6 04:17:51 grue NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associated May 6 04:17:51 grue NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed May 6 04:26:50 grue NetworkManager: <info> (wlan0): supplicant connection state: completed -> disconnected May 6 04:26:50 grue NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning May 6 04:26:51 grue NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associated May 6 04:26:51 grue NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed May 6 04:34:50 grue NetworkManager: <info> (wlan0): supplicant connection state: completed -> disconnected May 6 04:34:50 grue NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning May 6 04:34:51 grue NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associated May 6 04:34:51 grue NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed May 6 04:36:50 grue NetworkManager: <info> (wlan0): supplicant connection state: completed -> disconnected May 6 04:36:50 grue NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning May 6 04:36:51 grue NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associated May 6 04:36:51 grue NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed
I think I'm a "me too" I've got a Dell D430 laptop with an Intel Corporation PRO/Wireless 3945ABG (iwl3945) and sometimes I see it re-requesting via DHCP for its address every 2-3 seconds. syslog on the FC11 laptop shows: May 19 07:46:11 tnz-jhaar-dell dhclient: DHCPREQUEST on wlan0 to 192.168.248.3 port 67 May 19 07:46:23 tnz-jhaar-dell dhclient: DHCPREQUEST on wlan0 to 192.168.248.3 port 67 May 19 07:46:42 tnz-jhaar-dell dhclient: DHCPREQUEST on wlan0 to 192.168.248.3 port 67 - nothing else. No kernel errors or any indication of a reason to do this. Similarly, the DHCP server shows these requests coming through, and the logs on the Cisco Access Point show NOTHING - no indication why this is happening. The AP is around 2feet from my laptop, it's the only ESSID I can "see" and I'm the only user. Assuming everyone on this ticket is experiencing the same issue, I'd say this wasn't a wireless driver problem - but something more in userspace? BTW, I see no evidence of an issue. Other than the loss of a wee bit of syslog diskspace, there appears to be no actual problem for me.
Here're my two cents: # lspci 02:06.0 Ethernet controller: Atheros Communications Inc. Atheros AR5001X+ Wireless Network Adapter (rev 01) # I got this output from running wpa_supplicant -c /etc/wpa_config/someconfig.conf -i wlan0 -d # This happens very often and, then, it reconnects RTM_NEWLINK: operstate=1 ifi_flags=0x1043 ([UP][RUNNING]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b15 len=24 Wireless event: new AP: 00:00:00:00:00:00 Setting scan request: 0 sec 100000 usec Added BSSID 00:0e:3b:07:a8:55 into blacklist CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0 ioctl[SIOCSIWENCODEEXT]: No such file or directory Driver did not support SIOCSIWENCODEEXT State: COMPLETED -> DISCONNECTED wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 EAPOL: External notification - portEnabled=0 EAPOL: SUPP_PAE entering state DISCONNECTED EAPOL: SUPP_BE entering state INITIALIZE EAPOL: External notification - portValid=0 EAPOL: External notification - EAP success=0 RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added State: DISCONNECTED -> SCANNING Starting AP scan (broadcast SSID) Scan requested (ret=0) - scan timeout 30 seconds RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b19 len=16 Received 3746 bytes of scan results (11 BSSes) CTRL-EVENT-SCAN-RESULTS Selecting BSS from priority group 0 Try to find WPA-enabled AP 0: 00:0e:3b:07:a8:55 ssid='PentExtender1' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 selected based on WPA IE selected WPA AP 00:0e:3b:07:a8:55 ssid='PentExtender1' Trying to associate with 00:0e:3b:07:a8:55 (SSID='PentExtender1' freq=2462 MHz) Cancelling scan request WPA: clearing own WPA/RSN IE Automatic auth_alg selection: 0x1 WPA: using IEEE 802.11i/D3.0 WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 1 WPA: set AP WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 WPA: clearing AP RSN IE WPA: using GTK TKIP WPA: using PTK TKIP WPA: using KEY_MGMT WPA-PSK WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 No keys have been configured - skip key clearing wpa_driver_wext_set_drop_unencrypted State: SCANNING -> ASSOCIATING wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 wpa_driver_wext_associate wpa_driver_wext_set_psk Setting authentication timeout: 20 sec 0 usec EAPOL: External notification - EAP success=0 EAPOL: External notification - EAP fail=0 EAPOL: External notification - portControl=Auto RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b04 len=16 RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b15 len=24 Wireless event: new AP: 00:00:00:00:00:00 BSSID 00:0e:3b:07:a8:55 blacklist count incremented to 2 CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0 wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0 ioctl[SIOCSIWENCODEEXT]: No such file or directory Driver did not support SIOCSIWENCODEEXT State: ASSOCIATING -> DISCONNECTED wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 EAPOL: External notification - portEnabled=0 EAPOL: External notification - portValid=0 EAPOL: External notification - EAP success=0 Authentication with 00:00:00:00:00:00 timed out. Added BSSID 00:00:00:00:00:00 into blacklist No keys have been configured - skip key clearing State: DISCONNECTED -> DISCONNECTED wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 EAPOL: External notification - portEnabled=0 EAPOL: External notification - portValid=0 EAPOL: External notification - EAP success=0 Setting scan request: 0 sec 0 usec State: DISCONNECTED -> SCANNING Starting AP scan (broadcast SSID) Scan requested (ret=0) - scan timeout 30 seconds RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b19 len=16 Scan results did not fit - trying larger buffer (8192 bytes) Received 5039 bytes of scan results (14 BSSes) CTRL-EVENT-SCAN-RESULTS Selecting BSS from priority group 0 Try to find WPA-enabled AP 0: 00:0e:3b:07:a8:55 ssid='PentExtender1' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 skip - blacklisted 1: 00:1a:c4:c4:70:a9 ssid='Penthouse' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 2: 00:23:6c:bf:7b:69 ssid='Notaria 85n' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 skip - SSID mismatch 3: 00:1f:b3:8a:e2:91 ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 4: 00:1f:b3:1a:5e:41 ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 5: 00:1f:b3:d3:c0:19 ssid='INFINITUM3869' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 6: 00:1f:b3:8a:e2:91 ssid='' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 7: 00:1f:b3:1a:5e:41 ssid='' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 8: 00:1c:0e:d4:e2:40 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 9: 00:1c:b0:ea:c9:30 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 10: 00:24:51:c9:05:10 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 11: 00:10:e7:f5:da:8b ssid='Bikku' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 12: 00:02:2d:c4:45:42 ssid='PFeAmQP4' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - no WPA/RSN IE 13: 00:02:2d:3d:f6:ba ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x1 skip - no WPA/RSN IE Try to find non-WPA AP 0: 00:0e:3b:07:a8:55 ssid='PentExtender1' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 skip - blacklisted 1: 00:1a:c4:c4:70:a9 ssid='Penthouse' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 2: 00:23:6c:bf:7b:69 ssid='Notaria 85n' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 skip - SSID mismatch 3: 00:1f:b3:8a:e2:91 ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 4: 00:1f:b3:1a:5e:41 ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 5: 00:1f:b3:d3:c0:19 ssid='INFINITUM3869' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 6: 00:1f:b3:8a:e2:91 ssid='' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 7: 00:1f:b3:1a:5e:41 ssid='' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 8: 00:1c:0e:d4:e2:40 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 9: 00:1c:b0:ea:c9:30 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 10: 00:24:51:c9:05:10 ssid='ASFG-WLAN' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 11: 00:10:e7:f5:da:8b ssid='Bikku' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 12: 00:02:2d:c4:45:42 ssid='PFeAmQP4' wpa_ie_len=0 rsn_ie_len=0 caps=0x11 skip - SSID mismatch 13: 00:02:2d:3d:f6:ba ssid=' ' wpa_ie_len=0 rsn_ie_len=0 caps=0x1 skip - SSID mismatch No APs found - clear blacklist and try again Removed BSSID 00:00:00:00:00:00 from blacklist (clear) Removed BSSID 00:0e:3b:07:a8:55 from blacklist (clear) Selecting BSS from priority group 0 Try to find WPA-enabled AP 0: 00:0e:3b:07:a8:55 ssid='PentExtender1' wpa_ie_len=22 rsn_ie_len=0 caps=0x11 selected based on WPA IE selected WPA AP 00:0e:3b:07:a8:55 ssid='PentExtender1' Trying to associate with 00:0e:3b:07:a8:55 (SSID='PentExtender1' freq=2462 MHz) Cancelling scan request WPA: clearing own WPA/RSN IE Automatic auth_alg selection: 0x1 WPA: using IEEE 802.11i/D3.0 WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 1 WPA: set AP WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 WPA: clearing AP RSN IE WPA: using GTK TKIP WPA: using PTK TKIP WPA: using KEY_MGMT WPA-PSK WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 No keys have been configured - skip key clearing wpa_driver_wext_set_drop_unencrypted State: SCANNING -> ASSOCIATING wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 wpa_driver_wext_associate wpa_driver_wext_set_psk Setting authentication timeout: 20 sec 0 usec EAPOL: External notification - EAP success=0 EAPOL: External notification - EAP fail=0 EAPOL: External notification - portControl=Auto RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b04 len=16 RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8c02 len=161 Association info event req_ies - hexdump(len=49): 00 0d 50 65 6e 74 45 78 74 65 6e 64 65 72 31 01 08 0c 12 18 24 30 48 60 6c dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 resp_ies - hexdump(len=10): 01 08 8c 92 98 a4 b0 48 60 6c WPA: set own WPA/RSN IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added Wireless event: cmd=0x8b15 len=24 Wireless event: new AP: 00:0e:3b:07:a8:55 State: ASSOCIATING -> ASSOCIATED wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT) WEXT: Operstate: linkmode=-1, operstate=5 Associated to a new BSS: BSSID=00:0e:3b:07:a8:55 No keys have been configured - skip key clearing Associated with 00:0e:3b:07:a8:55 WPA: Association event - clear replay counter WPA: Clear old PTK EAPOL: External notification - portEnabled=0 EAPOL: External notification - portValid=0 EAPOL: External notification - EAP success=0 EAPOL: External notification - portEnabled=1 EAPOL: SUPP_PAE entering state CONNECTING EAPOL: enable timer tick EAPOL: SUPP_BE entering state IDLE Setting authentication timeout: 10 sec 0 usec Cancelling scan request RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added RX EAPOL from 00:0e:3b:07:a8:55 Setting authentication timeout: 10 sec 0 usec IEEE 802.1X RX: version=1 type=3 length=95 EAPOL-Key type=254 key_info 0x89 (ver=1 keyidx=0 rsvd=0 Pairwise Ack) key_length=32 key_data_length=0 replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 00 key_nonce - hexdump(len=32): cf cb 67 42 5b 51 23 36 65 c3 44 e2 10 1c 87 a0 a3 47 fe aa 15 63 65 cb 3d cb ef 9b 6e a7 0c 6c key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00 key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00 key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 State: ASSOCIATED -> 4WAY_HANDSHAKE WPA: RX message 1 of 4-Way Handshake from 00:0e:3b:07:a8:55 (ver=1) WPA: Renewed SNonce - hexdump(len=32): b8 38 71 55 34 57 1f 93 78 a4 03 ba 3b 12 a2 ed f6 53 e5 7f 6d 85 7d c2 40 ea 32 8d 8b 5f 63 6e WPA: PTK derivation - A1=00:0d:88:c8:85:98 A2=00:0e:3b:07:a8:55 WPA: PMK - hexdump(len=32): [REMOVED] WPA: PTK - hexdump(len=64): [REMOVED] WPA: WPA IE for msg 2/4 - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 WPA: Sending EAPOL-Key 2/4 RX EAPOL from 00:0e:3b:07:a8:55 IEEE 802.1X RX: version=1 type=3 length=119 EAPOL-Key type=254 key_info 0x1c9 (ver=1 keyidx=0 rsvd=0 Pairwise Install Ack MIC) key_length=32 key_data_length=24 replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01 key_nonce - hexdump(len=32): cf cb 67 42 5b 51 23 36 65 c3 44 e2 10 1c 87 a0 a3 47 fe aa 15 63 65 cb 3d cb ef 9b 6e a7 0c 6c key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00 key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00 key_mic - hexdump(len=16): db 9b 44 3a 05 d0 8b 32 c9 a8 3b e5 ba 76 f8 bd State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE WPA: RX message 3 of 4-Way Handshake from 00:0e:3b:07:a8:55 (ver=1) WPA: IE KeyData - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 WPA: Sending EAPOL-Key 4/4 WPA: Installing PTK to the driver. WPA: RSC - hexdump(len=6): 00 00 00 00 00 00 wpa_driver_wext_set_key: alg=2 key_idx=0 set_tx=1 seq_len=6 key_len=32 State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE RX EAPOL from 00:0e:3b:07:a8:55 IEEE 802.1X RX: version=1 type=3 length=127 EAPOL-Key type=254 key_info 0x391 (ver=1 keyidx=1 rsvd=0 Group Ack MIC Secure) key_length=32 key_data_length=32 replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04 key_nonce - hexdump(len=32): cf cb 67 42 5b 51 23 36 65 c3 44 e2 10 1c 87 a0 a3 47 fe aa 15 63 65 cb 3d cb ef 9b 6e a7 0c 6e key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00 key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00 key_mic - hexdump(len=16): 1e bb f4 04 af 2c c1 01 35 ab 31 20 3e b3 06 3d WPA: RX message 1 of Group Key Handshake from 00:0e:3b:07:a8:55 (ver=1) State: GROUP_HANDSHAKE -> GROUP_HANDSHAKE WPA: Group Key - hexdump(len=32): [REMOVED] WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32). WPA: RSC - hexdump(len=6): 00 00 00 00 00 00 wpa_driver_wext_set_key: alg=2 key_idx=1 set_tx=0 seq_len=6 key_len=32 WPA: Sending EAPOL-Key 2/2 WPA: Key negotiation completed with 00:0e:3b:07:a8:55 [PTK=TKIP GTK=TKIP] Cancelling authentication timeout State: GROUP_HANDSHAKE -> COMPLETED CTRL-EVENT-CONNECTED - Connection to 00:0e:3b:07:a8:55 completed (reauth) [id=0 id_str=] wpa_driver_wext_set_operstate: operstate 0->1 (UP) WEXT: Operstate: linkmode=-1, operstate=6 EAPOL: External notification - portValid=1 EAPOL: External notification - EAP success=1 EAPOL: SUPP_PAE entering state AUTHENTICATING EAPOL: SUPP_BE entering state SUCCESS EAP: EAP entering state DISABLED EAPOL: SUPP_PAE entering state AUTHENTICATED EAPOL: SUPP_BE entering state IDLE EAPOL authentication completed successfully RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP]) RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added EAPOL: startWhen --> 0 EAPOL: disable timer tick
I see this issue regularly using FC10 on a Lenovo T61 laptop. Indeed, every two minutes. Jun 11 13:22:24 hagrid NetworkManager: <info> (wlan0): supplicant connection state: associating -> associated Jun 11 13:22:24 hagrid NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed Jun 11 13:22:24 hagrid NetworkManager: <info> (wlan0): supplicant connection state: completed -> disconnected Jun 11 13:22:24 hagrid NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning Jun 11 13:22:25 hagrid NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associated Jun 11 13:22:25 hagrid NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed Jun 11 13:24:21 hagrid NetworkManager: <info> (wlan0): supplicant connection state: completed -> associating Jun 11 13:24:21 hagrid NetworkManager: <info> (wlan0): supplicant connection state: associating -> associated
03:00.0 Network controller: Intel Corporation PRO/Wireless 3945ABG [Golan] Network Connection (rev 02) $ service NetworkManager stop Stopping NetworkManager daemon: [ OK ] $ killall -TERM wpa_supplicant $ time /sbin/iwlist wlan0 scan wlan0 Interface doesn't support scanning : Network is down real 0m0.002s user 0m0.000s sys 0m0.003s $ service NetworkManager start Setting network parameters... [ OK ] Starting NetworkManager daemon: [ OK ] $ time /sbin/iwlist wlan0 scan wlan0 Scan completed : Cell 01 - Address: 00:1F:6C:CA:7B:E0 ESSID:"rh-wireless" Mode:Master Channel:3 Frequency:2.422 GHz (Channel 3) Quality=31/100 Signal level:-90 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c11016e18c Extra: Last beacon: 4193ms ago Cell 02 - Address: 00:1E:F7:55:A3:70 ESSID:"rh-wireless" Mode:Master Channel:4 Frequency:2.427 GHz (Channel 4) Quality=46/100 Signal level:-81 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c1114c418c Extra: Last beacon: 3952ms ago Cell 03 - Address: 00:1E:F7:55:A8:10 ESSID:"rh-wireless" Mode:Master Channel:4 Frequency:2.427 GHz (Channel 4) Quality=31/100 Signal level:-90 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c1124c81d0 Extra: Last beacon: 3812ms ago Cell 04 - Address: 00:1F:6C:CA:7E:40 ESSID:"rh-wireless" Mode:Master Channel:8 Frequency:2.447 GHz (Channel 8) Quality=76/100 Signal level:-58 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c1105ba253 Extra: Last beacon: 219ms ago Cell 05 - Address: 00:1F:6C:CA:7C:80 ESSID:"rh-wireless" Mode:Master Channel:9 Frequency:2.452 GHz (Channel 9) Quality=58/100 Signal level:-73 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c10e09e18c Extra: Last beacon: 2418ms ago Cell 06 - Address: 00:1F:6C:CA:78:10 ESSID:"rh-wireless" Mode:Master Channel:11 Frequency:2.462 GHz (Channel 11) Quality=76/100 Signal level:-58 dBm Noise level=-127 dBm Encryption key:on Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 6 Mb/s; 9 Mb/s 11 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s 48 Mb/s; 54 Mb/s Extra:tsf=000005c1121a818c Extra: Last beacon: 2379ms ago Cell 07 - Address: 82:F2:9B:B4:2D:57 ESSID:"hpsetup" Mode:Ad-Hoc Channel:6 Frequency:2.437 GHz (Channel 6) Quality=59/100 Signal level:-72 dBm Noise level=-127 dBm Encryption key:off Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s Extra:tsf=000000437fb32142 Extra: Last beacon: 3408ms ago real 0m3.852s user 0m0.001s sys 0m0.002s
Ok, it seems that the reason for the network problems is simply that NetworkManager is performing a scan (calling nm_supplicant_interface_request_scan). If I start a ping in one shell and then run "iwlist wlan0 scanning", the network pauses for about 3-4 seconds and then restarts again: 64 bytes from gw.localnet (192.168.0.1): icmp_seq=3 ttl=64 time=0.902 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=4 ttl=64 time=0.908 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=5 ttl=64 time=0.880 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=6 ttl=64 time=0.911 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=7 ttl=64 time=0.903 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=8 ttl=64 time=0.896 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=9 ttl=64 time=3647 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=10 ttl=64 time=2647 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=11 ttl=64 time=1647 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=12 ttl=64 time=647 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=13 ttl=64 time=0.891 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=14 ttl=64 time=0.871 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=15 ttl=64 time=1.07 ms 64 bytes from gw.localnet (192.168.0.1): icmp_seq=16 ttl=64 time=2.78 ms This short hiccup is enough to completely ruin the interactive performance of a ssh session and if I try to load a web page during those 3 seconds, the load gets delayed so much that I usually end up pressing reload in the web browser, and things like streaming video is just a no-no (I some of this is due to TCP backoff which makes the perceived network outage last much longer). I just modified request_wireless_scan so that it does not perform a scan if it is already connected to a wireless network, and this seems to fix the problem for me. NMDeviceState state = nm_device_get_state (NM_DEVICE (self)); if (can_scan (self)) { if (state == NM_DEVICE_STATE_CONFIG || state == NM_DEVICE_STATE_NEED_AUTH || state == NM_DEVICE_STATE_IP_CONFIG || state == NM_DEVICE_STATE_ACTIVATED) { nm_debug ("%s: supressing scan, state %d", __func__, state); backoff = TRUE; } else { if (nm_supplicant_interface_request_scan (priv->supplicant.iface)) \ { /* success */ backoff = TRUE; } } } Of course, this means that I won't have an up to date AP list, but in my opinion it is _much_ better than having a network outage every other minute (a 4 second outage every 120 seconds means that the network is nonfunctional 3% of the time, and that is just terrible). So how is the Atheros driver supposed to behave? Is is supposed to be able to do a scan in the background without affecting network traffic, or is the outage the expected behavior? Anyway, as long as the driver behaves as it does, I'd suggest adding a configuration option to NetworkManager to disable the periodic scan, since the periodic scan basically makes the network useless for some use cases. Same hardware as in my previous report, a Thinkpad X40 with an Atheros card, Fedora 9, but this time with kernel 2.6.27.21-78.2.41.fc9.i686 and NetworkManager-0.7.1-1.fc9.i386.
And now when I know what's happening it's much easier to find the relevant bugs in the NetworkManager bugzilla: http://bugzilla.gnome.org/show_bug.cgi?id=513820 There was even a workaround added for this back in 2005: http://bugzilla.gnome.org/show_bug.cgi?id=165933 But that option is no longer present in nm-applet, so I guess it has been removed in the name of luser-friendliness or something.
I'm sorry to aks these, probably naive, questions. I have the same problem and I wanted to try the solution provided by Christer. But where to change these lines? Do I have to create a file somewhere? I hope, you can help me, since I have looked for this solution a long time now. thanks
I can confirm that this is affecting Fedora 11. I'm getting the same delay every 120 seconds. I'm using an Atheros AR5001X+ a/b/g desktop card (D-Link DWL-AG530). 'lspci -v' gives me: 01:07.0 Ethernet controller: Atheros Communications Inc. Atheros AR5001X+ Wireless Network Adapter (rev 01) Subsystem: D-Link System Inc D-Link AirPremier DWL-AG530 Wireless PCI Adapter Flags: bus master, medium devsel, latency 168, IRQ 19 Memory at fdee0000 (32-bit, non-prefetchable) [size=64K] Capabilities: <access denied> Kernel driver in use: ath5k Kernel modules: ath5k I don't get any coincident messages from NetworkManager in /var/log/messages, but if I ping my gateway, every 120 seconds I get this: (snip) 64 bytes from 10.42.43.1: icmp_seq=98 ttl=64 time=0.656 ms 64 bytes from 10.42.43.1: icmp_seq=99 ttl=64 time=0.667 ms 64 bytes from 10.42.43.1: icmp_seq=100 ttl=64 time=8076 ms 64 bytes from 10.42.43.1: icmp_seq=101 ttl=64 time=7077 ms 64 bytes from 10.42.43.1: icmp_seq=102 ttl=64 time=6074 ms 64 bytes from 10.42.43.1: icmp_seq=103 ttl=64 time=5062 ms 64 bytes from 10.42.43.1: icmp_seq=104 ttl=64 time=4050 ms 64 bytes from 10.42.43.1: icmp_seq=105 ttl=64 time=3038 ms 64 bytes from 10.42.43.1: icmp_seq=106 ttl=64 time=2027 ms 64 bytes from 10.42.43.1: icmp_seq=107 ttl=64 time=1015 ms 64 bytes from 10.42.43.1: icmp_seq=108 ttl=64 time=3.95 ms 64 bytes from 10.42.43.1: icmp_seq=109 ttl=64 time=0.696 ms 64 bytes from 10.42.43.1: icmp_seq=110 ttl=64 time=0.706 ms (snip) If I do 'sudo time iwlist wlan0 scan' I get a whole lot of APs and at the end: 0.00user 0.00system 0:08.82elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k 0inputs+0outputs (0major+169minor)pagefaults 0swaps I'm using kernel-2.6.30.5-43.fc11.i586 (it was also happening on the 2.6.29 series), NetworkManager-0.7.1-8.git20090708.fc11.i586, and wireless-tools-29-4.fc11.i586. I've only recently started using my wireless card since I usually had the option of wired ethernet, so I don't know how far back this problem goes. I can provide similar info for my Eee PC 901 and Gateway laptops, each with different b/g Realtek chipsets, if that's useful.
I should clarify that these other two laptops do exhibit the same behaviour in Fedora 11, except with shorter delays of 1-3 seconds.
The shorter delays are likely for devices that have hardware-assisted scanning or only support 2.4GHz channels. The 2.6.32 kernel solves this issue mainly due to the introduction of background scanning where the kernel driver will spread the scan over a longer time period but return to the active channel periodically. Again, the real fix is in the driver and the kernel's mac80211 stack to minimize scan interruption. Note that the disconnect/reconnect bug is fixed with kernels 2.6.29 and later which is in F10 updates for mac80211-based drivers. The original bug reporter here has an ipw2200-based card (2915 actaully, but same driver) and thus this bug is actually a dupe of bug 478686. The ipw2200 driver should not be disconnecting from the AP to scan. *** This bug has been marked as a duplicate of bug 478686 ***
(In reply to comment #14) > Again, the real fix is in the driver and the > kernel's mac80211 stack to minimize scan interruption. Looks like real fix still not available? Scanning with recent kernels (3.6 and 3.7) don't interrupts connection with ath9k driver but decreasing of downloading speed still notable couple of seconds at scanning time (when running 'iw dev wlan0 scan'). Also at this time rtt shown by ping increased from 1ms to 2000ms, but no packets lost.
(In reply to comment #15) > (In reply to comment #14) > > Again, the real fix is in the driver and the > > kernel's mac80211 stack to minimize scan interruption. > > Looks like real fix still not available? > Scanning with recent kernels (3.6 and 3.7) don't interrupts connection with > ath9k driver but decreasing of downloading speed still notable couple of > seconds at scanning time (when running 'iw dev wlan0 scan'). Also at this > time rtt shown by ping increased from 1ms to 2000ms, but no packets lost. The real fix is to lock your connection to the AP's BSSID if you do not want autoscanning behavior.
(In reply to comment #16) > The real fix is to lock your connection to the AP's BSSID if you do not want > autoscanning behavior. I already did this, but I think that real fix is make autoscanning not affecting on established connection such as increased to 3000ms delays.