Networkmanager 0.6.4 takes long time to connect

TedyBear · 04-08-2007, 11:33 AM

I have a problem with the gnome networkmanager applet 0.6.4 in Ubuntu.
I have a WPA-PSK enabled wireless network and when I try to connect to it through the networkmanager it takes several retries and every retry takes a long time before it's able to connect to the network and log on.

Once it has logged on there's no problems. Has anyone else experienced the same?

Yours,
Matthias Andersson

Centinul · 04-09-2007, 05:51 AM

I've experienced a similar problem. I have a WPA-PSK setup with a hidden SSID. Some times it connects on the first try, other times I have to enter my password in about 5 times before it will connect. I don't know what version it is using, but this is on SuSe 10.2

It would be nice to fix this problem.

Thanks,

Centinul

pugsley · 04-27-2007, 11:53 PM

I am experiencing the same slow connection under Suse10.2 - worked very nucely on Suse10.1. A look at the log shows:

Apr 27 19:09:27 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:32 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:37 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:41 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:45 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:50 laptop NetworkManager: <WARN> request_and_convert_scan_results(): card took too much time scanning. Get a better one.
Apr 27 19:09:50 laptop NetworkManager: <info> Activation (eth1/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'WLAN'.

Looks like networkmanager is not giving the card enough time to initialise.

Have not found solution yet!

TedyBear · 04-28-2007, 09:00 AM

That seems like a very helpful comment from the developers of Networkmanager. I haven't checked my logs but I'll post that content as soon as I do.

MikeyCarter · 05-22-2007, 09:57 PM

Any one found a solution yet? I get the same problem.

TedyBear · 05-23-2007, 12:09 AM

The reason why I haven't posted my log is the fact that I haven't found a log. I've looked and looked but found no references to what's going on during the search for the wireless router.

deadkenny · 09-17-2007, 02:44 AM

Similar problem here with 0.6.5 on Fedora 7. After a lot of hassle trying to work out how to get wireless working at all (thinking everthing in Fedora 7 would just work out of the box... d'oh!), I got it to work with ndiswrapper, the ndis drivers for the IPN2220 on my Acer laptop, messed about with wpa_supplement which didn't work and finally got NetworkManager to work. All looked great.

However if I shut down, when I next boot the machine and log in it can be 10 to 15 minutes before it eventually connects. For a long time it just doesn't show any wireless network, and then sometimes it will show my neighbour's networks but not mine (and yet I don't hide my SSID as I know that's a big problem anyway). Eventually I get a prompt for the password to my keyring which contains the key for my WPA secured wlan.

Here's all the wlan stuff snipped from my last boot...

Code:

Sep 17 07:35:54 ludovico kernel: ndiswrapper version 1.46 loaded (smp=yes)
Sep 17 07:35:54 ludovico kernel: ndiswrapper: driver neti2220 (LanExpress,03/29/2004,2.10.03.2004) loaded
Sep 17 07:35:54 ludovico kernel: ndiswrapper: using IRQ 18
Sep 17 07:35:54 ludovico kernel: wlan0: ethernet device XXXXXXXXXXXXXXXXX using NDIS driver: neti2220, version: 0x2000a, NDIS version: 0x501, vendor: 'INPROCOMM IPN2220 Wireless LAN Adapter', 17FE:2220.5.conf
Sep 17 07:35:54 ludovico kernel: wlan0: encryption modes supported: WEP; TKIP with WPA; AES/CCMP with WPA
Sep 17 07:36:11 ludovico NetworkManager: <info>  starting... 
Sep 17 07:36:11 ludovico kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep 17 07:36:11 ludovico NetworkManager: <info>  wlan0: Device is fully-supported using driver 'ndiswrapper'. 
Sep 17 07:36:12 ludovico NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start 
Sep 17 07:36:12 ludovico NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing. 
Sep 17 07:36:12 ludovico NetworkManager: <info>  Now managing wireless (802.11) device 'wlan0'. 
Sep 17 07:36:12 ludovico NetworkManager: <info>  Deactivating device wlan0. 
Sep 17 07:36:13 ludovico NetworkManager: <WARN>  nm_device_802_11_wireless_set_essid(): error setting ESSID to '' for device wlan0: Invalid argument 
Sep 17 07:36:13 ludovico kernel: eth0: link down
Sep 17 07:36:13 ludovico kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sep 17 07:36:13 ludovico NetworkManager: <info>  eth0: Device is fully-supported using driver 'via-rhine'. 
Sep 17 07:36:13 ludovico NetworkManager: <info>  nm_device_init(): waiting for device's worker thread to start 
Sep 17 07:36:13 ludovico NetworkManager: <info>  nm_device_init(): device's worker thread started, continuing. 
Sep 17 07:36:13 ludovico NetworkManager: <info>  Now managing wired Ethernet (802.3) device 'eth0'. 
Sep 17 07:36:13 ludovico NetworkManager: <info>  Deactivating device eth0. 
Sep 17 07:36:13 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0 
Sep 17 07:36:13 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0 
Sep 17 07:36:13 ludovico NetworkManager: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper 
Sep 17 07:36:14 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0 
Sep 17 07:36:14 ludovico NetworkManager: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE 
Sep 17 07:36:14 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0 
Sep 17 07:36:14 ludovico NetworkManager: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper 
Sep 17 07:36:14 ludovico NetworkManager: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE 
Sep 17 07:36:43 ludovico NetworkManager: <info>  Updating allowed wireless network lists. 
Sep 17 07:39:08 ludovico NetworkManager: <info>  User request to disable wireless. 
Sep 17 07:39:08 ludovico NetworkManager: <info>  Deactivating device wlan0. 
Sep 17 07:39:08 ludovico NetworkManager: <WARN>  nm_device_802_11_wireless_set_essid(): error setting ESSID to '' for device wlan0: Invalid argument 
Sep 17 07:39:08 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0 
Sep 17 07:39:14 ludovico NetworkManager: <info>  User request to enable wireless. 
Sep 17 07:40:21 ludovico kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep 17 07:40:21 ludovico NetworkManager: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0 
Sep 17 07:42:50 ludovico NetworkManager: <info>  starting... 
Sep 17 07:42:50 ludovico NetworkManager: <WARN>  nm_error_monitoring_device_link_state(): error monitoring wired ethernet link state: received data from unexpected sender  
Sep 17 07:42:50 ludovico NetworkManager: <WARN>  nm_dbus_init(): nm_dbus_init() could not acquire the NetworkManager service as it is already taken (ret=3). Is the daemon already running? 
Sep 17 07:42:50 ludovico NetworkManager: <ERROR>	[1190011370.399194] main (): nm_dbus_init() failed, exiting. Either dbus is not running, or the NetworkManager dbus security policy was not loaded. 
Sep 17 07:42:50 ludovico NetworkManager: traceback: 
Sep 17 07:42:50 ludovico NetworkManager: 	NetworkManager(main+0x789) [0x8069019] 
Sep 17 07:42:50 ludovico NetworkManager: 	/lib/libc.so.6(__libc_start_main+0xe0) [0x4baf70] 
Sep 17 07:42:50 ludovico NetworkManager: 	NetworkManager [0x8053091] 
Sep 17 07:44:15 ludovico kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Sep 17 07:44:15 ludovico dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Sep 17 07:44:16 ludovico avahi-daemon[2476]: Joining mDNS multicast group on interface wlan0.IPv6 with address XXXXXXXXXXXXXXXXXXXXXXX.
Sep 17 07:44:16 ludovico avahi-daemon[2476]: New relevant interface wlan0.IPv6 for mDNS.
Sep 17 07:44:16 ludovico avahi-daemon[2476]: Registering new address record for XXXXXXXXXXXXXXXXXXXXXXX on wlan0.*.
Sep 17 07:44:21 ludovico dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Sep 17 07:44:31 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Sep 17 07:44:36 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Sep 17 07:44:42 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 13
Sep 17 07:44:55 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 14
Sep 17 07:45:09 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 17
Sep 17 07:45:21 ludovico NetworkManager: <info>  SWITCH: no current connection, found better connection 'wlan0'. 
Sep 17 07:45:21 ludovico dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.reason
Sep 17 07:45:21 ludovico NetworkManager: <info>  Will activate connection 'wlan0/18029W2'. 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Device wlan0 activation scheduled... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) started... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0/wireless): access point 'XXXXXXX' is encrypted, but NO valid key exists.  New key needed. 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) New wireless user key requested for network 'XXXXXXX'. 
Sep 17 07:45:21 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Sep 17 07:45:26 ludovico dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) New wireless user key for network 'XXXXXXX' received. 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Sep 17 07:45:28 ludovico NetworkManager: <info>  Activation (wlan0/wireless): access point '18029W2' is encrypted, and a key exists.  No new key needed. 
Sep 17 07:45:29 ludovico NetworkManager: <info>  SUP: sending command 'INTERFACE_ADD wlan0		wext	/var/run/wpa_supplicant	' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'AP_SCAN 1' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'ADD_NETWORK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was '0' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 ssid 31383032395732' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 proto WPA' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 key_mgmt WPA-PSK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 psk <key>' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: sending command 'ENABLE_NETWORK 0' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  SUP: response was 'OK' 
Sep 17 07:45:30 ludovico NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Sep 17 07:45:30 ludovico NetworkManager: <info>  nm-device.c - nm_device_set_active_link (596) device wlan0 link state set to 1 
Sep 17 07:45:30 ludovico NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to access point '18029W2'. 
Sep 17 07:45:30 ludovico NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. 
Sep 17 07:45:30 ludovico NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction. 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. 
Sep 17 07:45:31 ludovico NetworkManager: <info>  DHCP daemon state is now 12 (successfully started) for interface wlan0 
Sep 17 07:45:31 ludovico NetworkManager: <info>  DHCP daemon state is now 1 (starting) for interface wlan0 
Sep 17 07:45:31 ludovico dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Sep 17 07:45:31 ludovico dhclient: DHCPACK from 192.168.1.2
Sep 17 07:45:31 ludovico NetworkManager: <info>  DHCP daemon state is now 4 (reboot) for interface wlan0 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled... 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started... 
Sep 17 07:45:31 ludovico dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.host_name
Sep 17 07:45:31 ludovico dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.nis_domain
Sep 17 07:45:31 ludovico dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.nis_servers
Sep 17 07:45:31 ludovico NetworkManager: <info>  Retrieved the following IP4 configuration from the DHCP daemon: 
Sep 17 07:45:31 ludovico NetworkManager: <info>    address 192.168.1.138 
Sep 17 07:45:31 ludovico NetworkManager: <info>    netmask 255.255.255.0 
Sep 17 07:45:31 ludovico NetworkManager: <info>    broadcast 192.168.1.255 
Sep 17 07:45:31 ludovico NetworkManager: <info>    gateway 192.168.1.1 
Sep 17 07:45:31 ludovico NetworkManager: <info>    nameserver 192.168.1.2 
Sep 17 07:45:31 ludovico NetworkManager: <info>    domain name 'inet' 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled... 
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete. 
Sep 17 07:45:31 ludovico dhclient: bound to 192.168.1.138 -- renewal in 19538 seconds.
Sep 17 07:45:31 ludovico NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started... 
Sep 17 07:45:31 ludovico avahi-daemon[2476]: Withdrawing address record for fe80::20e:9bff:fe78:ba55 on wlan0.
Sep 17 07:45:31 ludovico avahi-daemon[2476]: Leaving mDNS multicast group on interface wlan0.IPv6 with address XXXXXXXXXXXXXXXXXXXXXXXX.
Sep 17 07:45:31 ludovico avahi-daemon[2476]: Interface wlan0.IPv6 no longer relevant for mDNS.
Sep 17 07:45:31 ludovico avahi-daemon[2476]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.138.
Sep 17 07:45:31 ludovico avahi-daemon[2476]: New relevant interface wlan0.IPv4 for mDNS.
Sep 17 07:45:31 ludovico avahi-daemon[2476]: Registering new address record for 192.168.1.138 on wlan0.IPv4.
Sep 17 07:45:32 ludovico NetworkManager: <info>  Activation (wlan0) Finish handler scheduled. 
Sep 17 07:45:32 ludovico NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete. 
Sep 17 07:45:32 ludovico NetworkManager: <info>  Activation (wlan0) successful, device activated. 
Sep 17 07:45:33 ludovico avahi-daemon[2476]: Joining mDNS multicast group on interface wlan0.IPv6 with address XXXXXXXXXXXXXXXXXXXXXXXX.
Sep 17 07:45:33 ludovico avahi-daemon[2476]: New relevant interface wlan0.IPv6 for mDNS.
Sep 17 07:45:33 ludovico avahi-daemon[2476]: Registering new address record for XXXXXXXXXXXXXXXXXXXXXXXX on wlan0.*.