Ubuntu
network-manager package

WLAN connection activation is too slow

Bug #247381 reported by Alexander Jones
14
Affects Status Importance Assigned to Milestone
network-manager (Ubuntu)
Invalid
Undecided
Unassigned

Bug Description

Binary package hint: network-manager

It takes about 15 seconds for my network connection to activate here. I had unloaded my drivers and reloaded them to test this, as I always notice when I resume from S3 standby that my network connection isn't up yet. In Mac OS, I have barely even typed any of my password before the network connection is up and I hear iChat events happening.

/var/log/daemon.log:

Jul 10 21:05:46 fizz NetworkManager: <info> SWITCH: no current connection, found better connection 'ath0'.
Jul 10 21:05:46 fizz NetworkManager: <info> Will activate connection 'ath0/lsw'.
Jul 10 21:05:46 fizz NetworkManager: <info> Device ath0 activation scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) started...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0/wireless): access point 'lsw' is encrypted, and a key exists. No new key needed.
Jul 10 21:05:47 fizz NetworkManager: <info> retry to connect to global supplicant socket (try=1)
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'INTERFACE_ADD ath0^I^Iwext^I/var/run/wpa_supplicant0^I'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'AP_SCAN 1'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'ADD_NETWORK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was '0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 ssid 6c7377'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 key_mgmt NONE'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_key0 <key>'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_tx_keyidx 0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'ENABLE_NETWORK 0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:49 fizz avahi-daemon[4845]: Registering new address record for fe80::21c:b3ff:fec6:b769 on ath0.*.
Jul 10 21:05:50 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Jul 10 21:05:56 fizz NetworkManager: <info> Supplicant state changed: 1
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'lsw'.
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) scheduled.
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) started...
Jul 10 21:05:58 fizz NetworkManager: <info> Activation (ath0) Beginning DHCP transaction.
Jul 10 21:05:58 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) complete.
Jul 10 21:05:58 fizz NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface ath0
Jul 10 21:05:58 fizz dhclient: wifi0: unknown hardware address type 801
Jul 10 21:05:59 fizz NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface ath0
Jul 10 21:05:59 fizz dhclient: wifi0: unknown hardware address type 801
Jul 10 21:06:00 fizz dhclient: DHCPREQUEST of 192.168.0.5 on ath0 to 255.255.255.255 port 67
Jul 10 21:06:00 fizz dhclient: DHCPACK of 192.168.0.5 from 192.168.0.1
Jul 10 21:06:00 fizz avahi-daemon[4845]: Joining mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: New relevant interface ath0.IPv4 for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Registering new address record for 192.168.0.5 on ath0.IPv4.
Jul 10 21:06:00 fizz NetworkManager: <info> DHCP daemon state is now 4 (reboot) for interface ath0
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) scheduled...
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) started...
Jul 10 21:06:00 fizz dhclient: bound to 192.168.0.5 -- renewal in 2147483648 seconds.
Jul 10 21:06:00 fizz NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:
Jul 10 21:06:00 fizz NetworkManager: <info> address 192.168.0.5
Jul 10 21:06:00 fizz NetworkManager: <info> netmask 255.255.255.0
Jul 10 21:06:00 fizz NetworkManager: <info> broadcast 192.168.0.255
Jul 10 21:06:00 fizz NetworkManager: <info> gateway 192.168.0.1
Jul 10 21:06:00 fizz NetworkManager: <info> nameserver 194.168.4.100
Jul 10 21:06:00 fizz NetworkManager: <info> nameserver 194.168.8.100
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) scheduled...
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) complete.
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) started...
Jul 10 21:06:00 fizz avahi-daemon[4845]: Withdrawing address record for 192.168.0.5 on ath0.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Leaving mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Interface ath0.IPv4 no longer relevant for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Withdrawing address record for fe80::21c:b3ff:fec6:b769 on ath0.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Joining mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: New relevant interface ath0.IPv4 for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Registering new address record for 192.168.0.5 on ath0.IPv4.
Jul 10 21:06:01 fizz NetworkManager: <info> Clearing nscd hosts cache.
Jul 10 21:06:01 fizz NetworkManager: <WARN> nm_spawn_process(): nm_spawn_process('/usr/sbin/nscd -i hosts'): could not spawn process. (Failed to execute child process "/usr/sbin/nscd" (No such file or directory))
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) Finish handler scheduled.
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) complete.
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) successful, device activated.
Jul 10 21:06:01 fizz ntpdate[10862]: no servers can be used, exiting
Jul 10 21:06:02 fizz dnsmasq[5174]: reading /etc/resolv.conf
Jul 10 21:06:02 fizz dnsmasq[5174]: using nameserver 194.168.8.100#53
Jul 10 21:06:02 fizz dnsmasq[5174]: using nameserver 194.168.4.100#53
Jul 10 21:06:02 fizz avahi-daemon[4845]: Registering new address record for fe80::21c:b3ff:fec6:b769 on ath0.*.

/var/log/syslog:

Jul 10 21:05:46 fizz NetworkManager: <info> SWITCH: no current connection, found better connection 'ath0'.
Jul 10 21:05:46 fizz NetworkManager: <info> Will activate connection 'ath0/lsw'.
Jul 10 21:05:46 fizz NetworkManager: <info> Device ath0 activation scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) started...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) started...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) scheduled...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 1 of 5 (Device Prepare) complete.
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) starting...
Jul 10 21:05:46 fizz NetworkManager: <info> Activation (ath0/wireless): access point 'lsw' is encrypted, and a key exists. No new key needed.
Jul 10 21:05:47 fizz NetworkManager: <info> retry to connect to global supplicant socket (try=1)
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'INTERFACE_ADD ath0^I^Iwext^I/var/run/wpa_supplicant0^I'
Jul 10 21:05:48 fizz kernel: [12793.180648] ADDRCONF(NETDEV_CHANGE): ath0: link becomes ready
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'AP_SCAN 1'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'ADD_NETWORK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was '0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 ssid 6c7377'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 key_mgmt NONE'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_key0 <key>'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'SET_NETWORK 0 wep_tx_keyidx 0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: sending command 'ENABLE_NETWORK 0'
Jul 10 21:05:48 fizz NetworkManager: <info> SUP: response was 'OK'
Jul 10 21:05:49 fizz avahi-daemon[4845]: Registering new address record for fe80::21c:b3ff:fec6:b769 on ath0.*.
Jul 10 21:05:50 fizz NetworkManager: <info> Activation (ath0) Stage 2 of 5 (Device Configure) complete.
Jul 10 21:05:56 fizz NetworkManager: <info> Supplicant state changed: 1
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to access point 'lsw'.
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) scheduled.
Jul 10 21:05:56 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) started...
Jul 10 21:05:58 fizz NetworkManager: <info> Activation (ath0) Beginning DHCP transaction.
Jul 10 21:05:58 fizz NetworkManager: <info> Activation (ath0) Stage 3 of 5 (IP Configure Start) complete.
Jul 10 21:05:58 fizz NetworkManager: <info> DHCP daemon state is now 12 (successfully started) for interface ath0
Jul 10 21:05:58 fizz dhclient: wifi0: unknown hardware address type 801
Jul 10 21:05:58 fizz kernel: [12803.763104] ath0: no IPv6 routers present
Jul 10 21:05:59 fizz NetworkManager: <info> DHCP daemon state is now 1 (starting) for interface ath0
Jul 10 21:05:59 fizz dhclient: wifi0: unknown hardware address type 801
Jul 10 21:06:00 fizz dhclient: DHCPREQUEST of 192.168.0.5 on ath0 to 255.255.255.255 port 67
Jul 10 21:06:00 fizz dhclient: DHCPACK of 192.168.0.5 from 192.168.0.1
Jul 10 21:06:00 fizz avahi-daemon[4845]: Joining mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: New relevant interface ath0.IPv4 for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Registering new address record for 192.168.0.5 on ath0.IPv4.
Jul 10 21:06:00 fizz dhcdbd: dhco_input_option: Value 4294967295 cannot be converted to type L
Jul 10 21:06:00 fizz dhcdbd: dhco_parse_option_settings: bad option setting: new_dhcp_lease_time = 4294967295
Jul 10 21:06:00 fizz NetworkManager: <info> DHCP daemon state is now 4 (reboot) for interface ath0
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) scheduled...
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) started...
Jul 10 21:06:00 fizz dhclient: bound to 192.168.0.5 -- renewal in 2147483648 seconds.
Jul 10 21:06:00 fizz dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.host_name
Jul 10 21:06:00 fizz dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.domain_name
Jul 10 21:06:00 fizz dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.nis_domain
Jul 10 21:06:00 fizz dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.nis_servers
Jul 10 21:06:00 fizz NetworkManager: <info> Retrieved the following IP4 configuration from the DHCP daemon:
Jul 10 21:06:00 fizz NetworkManager: <info> address 192.168.0.5
Jul 10 21:06:00 fizz NetworkManager: <info> netmask 255.255.255.0
Jul 10 21:06:00 fizz NetworkManager: <info> broadcast 192.168.0.255
Jul 10 21:06:00 fizz NetworkManager: <info> gateway 192.168.0.1
Jul 10 21:06:00 fizz NetworkManager: <info> nameserver 194.168.4.100
Jul 10 21:06:00 fizz NetworkManager: <info> nameserver 194.168.8.100
Jul 10 21:06:00 fizz dhcdbd: message_handler: message handler not found under /com/redhat/dhcp/ath0 for sub-path ath0.dbus.get.interface_mtu
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) scheduled...
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 4 of 5 (IP Configure Get) complete.
Jul 10 21:06:00 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) started...
Jul 10 21:06:00 fizz avahi-daemon[4845]: Withdrawing address record for 192.168.0.5 on ath0.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Leaving mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Interface ath0.IPv4 no longer relevant for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Withdrawing address record for fe80::21c:b3ff:fec6:b769 on ath0.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Joining mDNS multicast group on interface ath0.IPv4 with address 192.168.0.5.
Jul 10 21:06:00 fizz avahi-daemon[4845]: New relevant interface ath0.IPv4 for mDNS.
Jul 10 21:06:00 fizz avahi-daemon[4845]: Registering new address record for 192.168.0.5 on ath0.IPv4.
Jul 10 21:06:01 fizz NetworkManager: <info> Clearing nscd hosts cache.
Jul 10 21:06:01 fizz NetworkManager: <WARN> nm_spawn_process(): nm_spawn_process('/usr/sbin/nscd -i hosts'): could not spawn process. (Failed to execute child process "/usr/sbin/nscd" (No such file or directory))
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) Finish handler scheduled.
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) Stage 5 of 5 (IP Configure Commit) complete.
Jul 10 21:06:01 fizz NetworkManager: <info> Activation (ath0) successful, device activated.
Jul 10 21:06:01 fizz ntpdate[10862]: no servers can be used, exiting
Jul 10 21:06:02 fizz dnsmasq[5174]: reading /etc/resolv.conf
Jul 10 21:06:02 fizz dnsmasq[5174]: using nameserver 194.168.8.100#53
Jul 10 21:06:02 fizz dnsmasq[5174]: using nameserver 194.168.4.100#53
Jul 10 21:06:02 fizz avahi-daemon[4845]: Registering new address record for fe80::21c:b3ff:fec6:b769 on ath0.*.
Jul 10 21:06:11 fizz kernel: [12816.934366] ath0: no IPv6 routers present

ProblemType: Bug
Architecture: amd64
Date: Thu Jul 10 21:07:07 2008
DistroRelease: Ubuntu 8.10
NonfreeKernelModules: nvidia
Package: network-manager 0.6.6-0ubuntu7
PackageArchitecture: amd64
ProcEnviron:
 PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/home/username/.local/bin
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: network-manager
Uname: Linux 2.6.26-3-generic x86_64

Tags: apport-bug
Revision history for this message
Alexander Jones (alex-weej) wrote :
Revision history for this message
Bjorn (bjorn-nostvold) wrote :

I can confirm this. It can take anywhere from 15-30 seconds before networks are discovered and Network Manager attempts to connect after resuming from S3. This happens almost instantaneously on OS X.

Revision history for this message
Adam Porter (alphapapa) wrote :

After I removed some outdated kernel module packages that were causing an older version of the iwlagn driver to be loaded, the newer 2.3.5 iwlagn driver was used, and that's significantly helped this problem. I don't know if it's as fast as OS X, but it's a lot faster than it used to be. Now I can resume from suspend and be connected quickly.

Revision history for this message
Thomas Hood (jdthood) wrote :

I observed the same problem originally reported. Since I upgraded to Jaunty (4 March 2009) the problem has gone away.

<pre>
# lspci |grep 802.11
03:00.0 Ethernet controller: Atheros Communications Inc. AR5212 802.11abg NIC (rev 01)
</pre>

Revision history for this message
Mathieu Trudel-Lapierre (cyphermox) wrote :

@Alexander Jones:

Please confirm whether you still notice Network Manager to be slow to detect wireless networks, in a recent version of Ubuntu (Jaunty) and NetworkManager. In light of comments #3 and #4 and my own testing, I think this would no longer be an issue.

Changed in network-manager (Ubuntu):
status: New → Incomplete
Revision history for this message
Alexander Jones (alex-weej) wrote :

Still very slow on MacBook Pro 5.4 with Broadcom "wl" on Karmic

Changed in network-manager (Ubuntu):
status: Incomplete → New
Revision history for this message
Alexander Sack (asac) wrote :

this is a driver issue. I dont think it makes much sense to move this to linux package as broadcom (wl) driver cannot be fixed by us afaik.

Changed in network-manager (Ubuntu):
status: New → Invalid
Revision history for this message
Alexander Sack (asac) wrote :

same for all the other drivers. slow association is 99% driver related nowadays.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.