[jaunty] network manager fails to connect to any network

[Bogdan Butnaru]

Binary package hint: network-manager

Hello! I'm running up-to-date Jaunty on a Dell Latitude. A month or so ago the network manager stopped connecting to networks. (I haven't reported it before because I didn't have time to investigate, and I don't use this machine that often.)

As far as I can tell, everything goes on correctly, the connection is opened and DHCP successfully acquires an address, but NM doesn't notice, and deactivates the interface 45 seconds later due to timeout. Below this message is an example snippet of /var/log/daemons.log which exemplifies this behavior. Note that it happens exactly the same with wired networks, too.

In the short interval between acquiring an address and the timeout, the network works correctly (though the NM applet displays the swirling “connecting” icon). Also, I can just run dhclient by hand on the wired network and it works (though NM doesn't notice it). I've no idea how to turn on the wireless by hand (actually, the WPA part), so I didn't check.

As far as I can tell I had done no changes to any configuration before it stopped working; I suppose it must have been an update that triggered the bug. I also tried reconfiguring & reinstalling both NM and dhcp, to no effect. The network worked correctly on the machine for years before this.

Mar 12 21:55:50 arioch NetworkManager: <info> Waking up...
Mar 12 21:55:50 arioch NetworkManager: <info> (eth1): now managed
Mar 12 21:55:50 arioch NetworkManager: <info> (eth1): device state change: 1 -> 2
Mar 12 21:55:50 arioch NetworkManager: <info> (eth1): bringing up device.
Mar 12 21:55:50 arioch NetworkManager: <info> (eth1): preparing device.
Mar 12 21:55:50 arioch NetworkManager: <info> (eth1): deactivating device (reason: 2).
Mar 12 21:55:51 arioch NetworkManager: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Mar 12 21:55:51 arioch NetworkManager: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): now managed
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): device state change: 1 -> 2
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): bringing up device.
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): preparing device.
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): deactivating device (reason: 2).
Mar 12 21:55:51 arioch NetworkManager: <info> (wlan1): device state change: 2 -> 3
Mar 12 21:55:52 arioch NetworkManager: <info> (wlan1): supplicant interface state: starting -> ready
Mar 12 21:55:58 arioch NetworkManager: <info> (eth1): carrier now ON (device state 2)
Mar 12 21:55:58 arioch NetworkManager: <info> (eth1): device state change: 2 -> 3
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) starting connection 'Auto Vanishing Tower'
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): device state change: 3 -> 4
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): device state change: 4 -> 5
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1/wireless): access point 'Auto Vanishing Tower' has security, but secrets are required.
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): device state change: 5 -> 6
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) scheduled...
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) started...
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): device state change: 6 -> 4
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) scheduled...
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 1 of 5 (Device Prepare) complete.
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) starting...
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): device state change: 4 -> 5
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1/wireless): connection 'Auto Vanishing Tower' has security, and secrets exist. No new secrets needed.
Mar 12 21:56:17 arioch NetworkManager: <info> Config: added 'ssid' value 'Vanishing Tower'
Mar 12 21:56:17 arioch NetworkManager: <info> Config: added 'scan_ssid' value '1'
Mar 12 21:56:17 arioch NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Mar 12 21:56:17 arioch NetworkManager: <info> Config: added 'psk' value '<omitted>'
Mar 12 21:56:17 arioch NetworkManager: nm_setting_802_1x_get_pkcs11_engine_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
Mar 12 21:56:17 arioch NetworkManager: nm_setting_802_1x_get_pkcs11_module_path: assertion `NM_IS_SETTING_802_1X (setting)' failed
Mar 12 21:56:17 arioch NetworkManager: <info> Activation (wlan1) Stage 2 of 5 (Device Configure) complete.
Mar 12 21:56:17 arioch NetworkManager: <info> Config: set interface ap_scan to 1
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): supplicant connection state: scanning -> disconnected
Mar 12 21:56:17 arioch NetworkManager: <info> (wlan1): supplicant connection state: disconnected -> scanning
Mar 12 21:56:18 arioch NetworkManager: <info> (wlan1): supplicant connection state: scanning -> associating
Mar 12 21:56:18 arioch NetworkManager: <info> (wlan1): supplicant connection state: associating -> associated
Mar 12 21:56:19 arioch NetworkManager: <info> (wlan1): supplicant connection state: associated -> 4-way handshake
Mar 12 21:56:19 arioch NetworkManager: <info> (wlan1): supplicant connection state: 4-way handshake -> group handshake
Mar 12 21:56:19 arioch NetworkManager: <info> (wlan1): supplicant connection state: group handshake -> completed
Mar 12 21:56:19 arioch NetworkManager: <info> Activation (wlan1/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'Vanishing Tower'.
Mar 12 21:56:19 arioch NetworkManager: <info> Activation (wlan1) Stage 3 of 5 (IP Configure Start) scheduled.
Mar 12 21:56:19 arioch NetworkManager: <info> Activation (wlan1) Stage 3 of 5 (IP Configure Start) started...
Mar 12 21:56:19 arioch NetworkManager: <info> (wlan1): device state change: 5 -> 7
Mar 12 21:56:19 arioch NetworkManager: <info> Activation (wlan1) Beginning DHCP transaction.
Mar 12 21:56:19 arioch NetworkManager: <info> dhclient started with pid 25454
Mar 12 21:56:19 arioch NetworkManager: <info> Activation (wlan1) Stage 3 of 5 (IP Configure Start) complete.
Mar 12 21:56:19 arioch dhclient: Internet Systems Consortium DHCP Client V3.1.1
Mar 12 21:56:19 arioch dhclient: Copyright 2004-2008 Internet Systems Consortium.
Mar 12 21:56:19 arioch dhclient: All rights reserved.
Mar 12 21:56:19 arioch dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Mar 12 21:56:19 arioch dhclient:
Mar 12 21:56:19 arioch dhclient: wmaster0: unknown hardware address type 801
Mar 12 21:56:19 arioch dhclient: wmaster0: unknown hardware address type 801
Mar 12 21:56:19 arioch dhclient: Listening on LPF/wlan1/00:18:de:b2:c8:80
Mar 12 21:56:19 arioch dhclient: Sending on LPF/wlan1/00:18:de:b2:c8:80
Mar 12 21:56:19 arioch dhclient: Sending on Socket/fallback
Mar 12 21:56:19 arioch avahi-daemon[5107]: Registering new address record for fe80::218:deff:feb2:c880 on wlan1.*.
Mar 12 21:56:22 arioch dhclient: DHCPDISCOVER on wlan1 to 255.255.255.255 port 67 interval 8
Mar 12 21:56:22 arioch dhclient: DHCPOFFER of 192.168.1.75 from 192.168.1.254
Mar 12 21:56:22 arioch dhclient: DHCPREQUEST of 192.168.1.75 on wlan1 to 255.255.255.255 port 67
Mar 12 21:56:22 arioch dhclient: DHCPACK of 192.168.1.75 from 192.168.1.254
Mar 12 21:56:22 arioch dhclient: bound to 192.168.1.75 -- renewal in 35159 seconds.
Mar 12 21:57:05 arioch NetworkManager: <info> Device 'wlan1' DHCP transaction took too long (>45s), stopping it.
Mar 12 21:57:05 arioch NetworkManager: <info> wlan1: canceled DHCP transaction, dhcp client pid 25454
Mar 12 21:57:05 arioch NetworkManager: <info> Activation (wlan1) Stage 4 of 5 (IP Configure Timeout) scheduled...
Mar 12 21:57:05 arioch NetworkManager: <info> Activation (wlan1) Stage 4 of 5 (IP Configure Timeout) started...
Mar 12 21:57:05 arioch NetworkManager: <info> (wlan1): device state change: 7 -> 9
Mar 12 21:57:05 arioch NetworkManager: <info> Activation (wlan1) failed for access point (Vanishing Tower)
Mar 12 21:57:05 arioch NetworkManager: <info> Marking connection 'Auto Vanishing Tower' invalid.
Mar 12 21:57:05 arioch NetworkManager: <info> Activation (wlan1) failed.
Mar 12 21:57:05 arioch NetworkManager: <info> Activation (wlan1) Stage 4 of 5 (IP Configure Timeout) complete.
Mar 12 21:57:05 arioch NetworkManager: <info> (wlan1): device state change: 9 -> 3
Mar 12 21:57:05 arioch NetworkManager: <info> (wlan1): deactivating device (reason: 0).

[Pedro Villavicencio (pedro)]

Thank you for taking the time to report this bug and helping to make Ubuntu better. You reported this bug a while ago and there hasn't been any activity in it recently. We were wondering is this still an issue for you? Do you get the same with Karmic? Thanks in advance.

[Bogdan Butnaru (bogdanb)]

It seems to be working now, I'll re-open if it happens again. Thanks!