GNOME Bugzilla – Bug 564457
NetworkManager takes too many time for starting because of trying to join to unproper AP
Last modified: 2010-02-01 20:59:50 UTC
Please describe the problem: I get this problem when switching my RF Kill button in my laptop. When I switch wireless of I see these messages: Dec 14 10:34:26 belkin3 atkbd.c: Unknown key pressed (translated set 2, code 0x88 on isa0060/serio0). Dec 14 10:34:26 belkin3 atkbd.c: Use 'setkeycodes e008 <keycode>' to make it known. Dec 14 10:34:26 belkin3 iwl4965: Radio Frequency Kill Switch is On: Dec 14 10:34:26 belkin3 Kill switch must be turned off for wireless networking to work. Dec 14 10:34:27 belkin3 NetworkManager: <info> Wireless now disabled by radio killswitch Dec 14 10:34:27 belkin3 NetworkManager: <info> (wlan0): device state change: 8 -> 2 Dec 14 10:34:27 belkin3 NetworkManager: <info> (wlan0): deactivating device (reason: 0). Dec 14 10:34:27 belkin3 wlan0: Initial auth_alg=0 Dec 14 10:34:27 belkin3 wlan0: authenticate with AP 00:0c:f6:1d:c9:e8 Dec 14 10:34:27 belkin3 NetworkManager: <info> (wlan0): deactivating device (reason: 0). Dec 14 10:34:27 belkin3 wlan0: Initial auth_alg=0 Dec 14 10:34:27 belkin3 wlan0: authenticate with AP 00:0c:f6:1d:c9:e8 Dec 14 10:34:27 belkin3 wlan0: disassociate(reason=3) Dec 14 10:34:27 belkin3 NetworkManager: <WARN> check_one_route(): (wlan0) error -34 returned from rtnl_route_del(): Missing link name TLV (errno = Invalid argument) Dec 14 10:34:27 belkin3 iwl4965: Error sending REPLY_WEPKEY: enqueue_hcmd failed: -5 Dec 14 10:34:27 belkin3 mac80211-phy0: failed to remove key (0, ff:ff:ff:ff:ff:ff) from hardware (-5) Dec 14 10:34:27 belkin3 NetworkManager: <info> (wlan0): taking down device. Dec 14 10:34:27 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:27 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:28 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 usb 3-2: USB disconnect, address 10 Dec 14 10:34:29 belkin3 usb 3-2.1: USB disconnect, address 11 Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 hcid[18729]: HCI dev 0 down Dec 14 10:34:29 belkin3 hcid[18729]: Stopping security manager 0 Dec 14 10:34:29 belkin3 hcid[18729]: Device hci0 has been disabled Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 iwl4965: WARNING: Requesting MAC access during RFKILL wakes up NIC Dec 14 10:34:29 belkin3 usb 3-2.2: USB disconnect, address 12 Dec 14 10:34:29 belkin3 hcid[18729]: HCI dev 0 unregistered Dec 14 10:34:29 belkin3 hcid[18729]: HCI dev 0 unregistered Dec 14 10:34:29 belkin3 hcid[18729]: Unregister path: /org/bluez/hci0 Dec 14 10:34:29 belkin3 hcid[18729]: Device hci0 has been removed Dec 14 10:34:29 belkin3 usb 3-2.3: USB disconnect, address 13 Dec 14 10:34:29 belkin3 hcid[18729]: Unregistered manager path Dec 14 10:34:29 belkin3 hcid[18729]: bridge pan0 removed Dec 14 10:34:29 belkin3 hcid[18729]: Unregistered manager path Dec 14 10:34:29 belkin3 hcid[18729]: Unregistered manager path Dec 14 10:34:29 belkin3 hcid[18729]: Stopping SDP server Dec 14 10:34:29 belkin3 hcid[18729]: Exit Even with some errors (maybe related to the driver) it is switched off properly, but now, I get the following when switching on: Dec 14 10:34:45 belkin3 atkbd.c: Unknown key pressed (translated set 2, code 0x88 on isa0060/serio0). Dec 14 10:34:45 belkin3 atkbd.c: Use 'setkeycodes e008 <keycode>' to make it known. Dec 14 10:34:45 belkin3 usb 3-2: new full speed USB device using uhci_hcd and address 14 Dec 14 10:34:46 belkin3 usb 3-2: configuration #1 chosen from 1 choice Dec 14 10:34:46 belkin3 hub 3-2:1.0: USB hub found Dec 14 10:34:46 belkin3 hub 3-2:1.0: 3 ports detected Dec 14 10:34:46 belkin3 usb 3-2: New USB device found, idVendor=0a5c, idProduct=4500 Dec 14 10:34:46 belkin3 usb 3-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Dec 14 10:34:46 belkin3 usb 3-2: Product: BCM2045B2 Dec 14 10:34:46 belkin3 usb 3-2: Manufacturer: Broadcom Dec 14 10:34:46 belkin3 usb 3-2.1: new full speed USB device using uhci_hcd and address 15 Dec 14 10:34:46 belkin3 usb 3-2.1: configuration #1 chosen from 1 choice Dec 14 10:34:46 belkin3 usb 3-2.1: New USB device found, idVendor=413c, idProduct=8126 Dec 14 10:34:46 belkin3 usb 3-2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Dec 14 10:34:46 belkin3 usb 3-2.1: Product: BCM2045 Dec 14 10:34:46 belkin3 usb 3-2.1: Manufacturer: Broadcom Corp Dec 14 10:34:46 belkin3 usb 3-2.2: new full speed USB device using uhci_hcd and address 16 Dec 14 10:34:46 belkin3 hcid[23972]: Bluetooth HCI daemon Dec 14 10:34:46 belkin3 hcid[23972]: Parsing /etc/bluetooth/main.conf failed: No such file or directory Dec 14 10:34:46 belkin3 hcid[23972]: Starting SDP server Dec 14 10:34:46 belkin3 usb 3-2.2: configuration #1 chosen from 1 choice Dec 14 10:34:46 belkin3 hcid[23972]: Unix socket created: 11 Dec 14 10:34:46 belkin3 hcid[23972]: Registered manager path:/org/bluez/audio Dec 14 10:34:46 belkin3 hcid[23972]: Registered manager path:/org/bluez/serial Dec 14 10:34:46 belkin3 pan0: Dropping NETIF_F_UFO since no NETIF_F_HW_CSUM feature. Dec 14 10:34:46 belkin3 input: Broadcom Corp as /devices/pci0000:00/0000:00:1a.0/usb3/3-2/3-2.2/3-2.2:1.0/input/input19 Dec 14 10:34:46 belkin3 hcid[23972]: bridge pan0 created Dec 14 10:34:46 belkin3 hcid[23972]: Registered manager path:/org/bluez/network Dec 14 10:34:46 belkin3 hcid[23972]: Registered server path:/org/bluez/network/nap Dec 14 10:34:46 belkin3 hcid[23972]: Registered server path:/org/bluez/network/gn Dec 14 10:34:46 belkin3 hcid[23972]: Registered server path:/org/bluez/network/panu Dec 14 10:34:46 belkin3 input,hidraw1: USB HID v1.11 Keyboard [Broadcom Corp] on usb-0000:00:1a.0-2.2 Dec 14 10:34:46 belkin3 usb 3-2.2: New USB device found, idVendor=0a5c, idProduct=4502 Dec 14 10:34:46 belkin3 usb 3-2.2: New USB device strings: Mfr=1, Product=0, SerialNumber=0 Dec 14 10:34:46 belkin3 usb 3-2.2: Manufacturer: Broadcom Corp Dec 14 10:34:46 belkin3 hcid[23972]: Registered input manager path:/org/bluez/input Dec 14 10:34:46 belkin3 hcid[23972]: HCI dev 0 registered Dec 14 10:34:46 belkin3 hcid[23972]: Default passkey agent (:1.102, /org/bluez/passkey) registered Dec 14 10:34:46 belkin3 hcid[23972]: Default authorization agent (:1.102, /org/bluez/auth) registered Dec 14 10:34:46 belkin3 hcid[23972]: HCI dev 0 up Dec 14 10:34:46 belkin3 hcid[23972]: Device hci0 has been added Dec 14 10:34:46 belkin3 hcid[23972]: Starting security manager 0 Dec 14 10:34:46 belkin3 hcid[23972]: Device hci0 has been activated Dec 14 10:34:47 belkin3 usb 3-2.3: new full speed USB device using uhci_hcd and address 17 Dec 14 10:34:47 belkin3 usb 3-2.3: configuration #1 chosen from 1 choice Dec 14 10:34:47 belkin3 input: Broadcom Corp as /devices/pci0000:00/0000:00:1a.0/usb3/3-2/3-2.3/3-2.3:1.0/input/input20 Dec 14 10:34:47 belkin3 input,hidraw2: USB HID v1.11 Mouse [Broadcom Corp] on usb-0000:00:1a.0-2.3 Dec 14 10:34:47 belkin3 usb 3-2.3: New USB device found, idVendor=0a5c, idProduct=4503 Dec 14 10:34:47 belkin3 usb 3-2.3: New USB device strings: Mfr=1, Product=0, SerialNumber=0 Dec 14 10:34:47 belkin3 usb 3-2.3: Manufacturer: Broadcom Corp Dec 14 10:34:47 belkin3 NetworkManager: <info> Wireless now enabled by radio killswitch Dec 14 10:34:47 belkin3 NetworkManager: <WARN> nm_device_wifi_set_enabled(): not in expected unavailable state! Dec 14 10:34:47 belkin3 NetworkManager: <info> (wlan0): bringing up device. Dec 14 10:34:47 belkin3 ACPI: PCI Interrupt 0000:0c:00.0[A] -> GSI 17 (level, low) -> IRQ 17 Dec 14 10:34:48 belkin3 Registered led device: iwl-phy0:radio Dec 14 10:34:48 belkin3 Registered led device: iwl-phy0:assoc Dec 14 10:34:48 belkin3 Registered led device: iwl-phy0:RX Dec 14 10:34:48 belkin3 Registered led device: iwl-phy0:TX Dec 14 10:34:48 belkin3 wlan0: Initial auth_alg=0 Dec 14 10:34:48 belkin3 wlan0: authenticate with AP 00:13:f7:2c:fb:b5 Dec 14 10:34:48 belkin3 NetworkManager: <info> (wlan0): device state change: 2 -> 3 Dec 14 10:34:48 belkin3 NetworkManager: <info> (wlan0): supplicant interface state: starting -> ready Dec 14 10:34:48 belkin3 wlan0: authenticate with AP 00:13:f7:2c:fb:b5 Dec 14 10:34:48 belkin3 wlan0: authenticate with AP 00:13:f7:2c:fb:b5 Dec 14 10:34:48 belkin3 wlan0: authentication with AP 00:13:f7:2c:fb:b5 timed out Here, I have to wait, Why is NetworkManager wanting to use this AP when I have a different one configured in /etc/NetworkManager/system-connections/conexion ? After waiting, NetworkManager connects to proper one finally: Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) starting connection 'conexion' Dec 14 10:35:12 belkin3 NetworkManager: <info> (wlan0): device state change: 3 -> 4 Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Dec 14 10:35:12 belkin3 NetworkManager: <info> (wlan0): device state change: 4 -> 5 Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0/wireless): connection 'conexion' has security, and secrets exist. No new secrets needed. Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'ssid' value 'OOurnet' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'scan_ssid' value '1' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'bssid' value '00:0c:f6:1d:c9:e8' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'key_mgmt' value 'NONE' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'auth_alg' value 'OPEN' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'wep_key0' value '<omitted>' Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: added 'wep_tx_keyidx' value '0' Dec 14 10:35:12 belkin3 NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Dec 14 10:35:12 belkin3 NetworkManager: <info> Config: set interface ap_scan to 1 Dec 14 10:35:12 belkin3 NetworkManager: <info> (wlan0): supplicant connection state: scanning -> disconnected Dec 14 10:35:13 belkin3 NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning Dec 14 10:35:14 belkin3 NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associating Dec 14 10:35:14 belkin3 wlan0: Initial auth_alg=0 Dec 14 10:35:14 belkin3 wlan0: authenticate with AP 00:0c:f6:1d:c9:e8 Dec 14 10:35:14 belkin3 wlan0: RX authentication from 00:0c:f6:1d:c9:e8 (alg=0 transaction=2 status=0) Dec 14 10:35:14 belkin3 wlan0: authenticated Dec 14 10:35:14 belkin3 wlan0: associate with AP 00:0c:f6:1d:c9:e8 Dec 14 10:35:14 belkin3 wlan0: RX AssocResp from 00:0c:f6:1d:c9:e8 (capab=0x431 status=0 aid=1) Dec 14 10:35:14 belkin3 wlan0: associated Dec 14 10:35:14 belkin3 wlan0: switched to short barker preamble (BSSID=00:0c:f6:1d:c9:e8) Dec 14 10:35:14 belkin3 NetworkManager: <info> (wlan0): supplicant connection state: associating -> associated Dec 14 10:35:14 belkin3 NetworkManager: <info> (wlan0): supplicant connection state: associated -> completed Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'OOurnet'. Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... Dec 14 10:35:14 belkin3 NetworkManager: <info> (wlan0): device state change: 5 -> 7 Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled... Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP Configure Get) started... Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete. Dec 14 10:35:14 belkin3 NetworkManager: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... Dec 14 10:35:15 belkin3 NetworkManager: <info> (wlan0): device state change: 7 -> 8 Dec 14 10:35:15 belkin3 NetworkManager: <info> Policy set 'conexion' (wlan0) as default for routing and DNS. Steps to reproduce: Actual results: NetworkManager tries to connect to unproper AP at first Expected results: NetworkManager should try to connect to AP defined in /etc/NetworkManager/system-connections/* before all others for connecting faster Does this happen every time? Yes, for example, at boot, NetworkManager takes so long that ntp doesn't work at boot because of network still not working. I know that maybe I could add a delay for ntp, but I didn't need it when simply using wpa_supplicant for networking Other information: I am using NetworkManager-0.7 with Hal-0.5.11, consolekit-0.2.10, kernel-2.6.26, under Gentoo Thanks a lot!
I have posted all messages shown, some of them are unrelated with NetworkManager (like bluez ones) but I postes all of them for ensuring you have enough information, if you want a summarize please ask
Which kernel is this with? Also, what specific version of NetworkManager?
I have networkmanager-0.7.0 and, now, kernel-2.6.28 (with iwlagn driver instead of iwl4965), but the problem is the same: at first it tries to autenticate with AP 00:13:f7:2c:fb:b5 and, when it refuses to do it, it tries with AP 00:0c:f6:1d:c9:e8
And I get the same with iwl3945 driver on a different laptop :-(
Maybe connected: Ubuntu 9.04 RC: Booting with 2.6.28-11's iwl3945 module I have to wait about 60 seconds before I'm connected. Using the newer compat-wireless module it takes about 15 seconds. Subsequent connections however work properly. I purged NetworkManager from the system, set up a minimalistic wpa_supplicant.conf and experienced the same. With some help from Intel devs I've changed the wpa_supplicant.conf to be more complete and the system connected within seconds. Bottom line: Booting (I guess that's comparable to switching the device off and on) with NetworkManager leads to a delay, booting with a properly set up wpa_supplicant works fine, so I guess NetworkManager is the culprit. See http://www.intellinuxwireless.org/bugzilla/show_bug.cgi?id=1857 for further details.
Any messages starting "wlan0: authenticate with AP 00:13:f7:2c:fb:b5" are solely produced from the *driver*, and are not caused by anything NetworkManager is doing. It sounds like your driver is silently denying scan requests, which is a know kernel driver problem with Intel wireless drivers. Try loading the driver module with "disable_hw_scan=1" to see if that helps reconnection latency. You can confirm that you have loaded the driver correctly if you get "1" from this: (iwl3945) cat /sys/module/iwl3945/parameters/disable_hw_scan (iwl4965/iwl5xxx) cat /sys/module/iwlagn/parameters/disable_hw_scan
I am already loading the driver with it and: cat /sys/module/iwlagn/parameters/disable_hw_scan reports "1", but I get exactly the same behavior, maybe driver is not honouring the option and I should sent this to iwlagn upstream, What do you think? Thanks
I used this wpa_supplicant.conf to do a little test: ap_scan=1 network={ scan_ssid=1 proto=WPA key_mgmt=WPA-PSK pairwise=CCMP TKIP group=CCMP TKIP ssid="MYSSID" psk=MYKEY } 20/20 times the connection was there immediately after the boot when using only the wpa_supplicant. With NetworkManager this rate dropped to 3/20. 17 times I had to wait about a minute before the connection was available. If NetworkManager uses a similar configuration, how can this be an Intel driver only problem?
I already reported this to driver bugtracker, but seems that this is a wpa_supplicant/networkmanager problem: http://www.intellinuxwireless.org/bugzilla/show_bug.cgi?id=1984#c26 I have tried to add "disabled=1" to wpa_supplicant.conf without success :-( Thanks for your help
NM no longer tries to clear the drivers association: http://bugzilla.intellinuxwireless.org/show_bug.cgi?id=1984#c36 thus it shouldn't be allowing drivers to interpret blank SSIDs as connections to any AP anymore. Thanks for the report!