[Pkg-utopia-maintainers] Bug#361207: NetworkManager disconnection bug

Sat Mar 21 05:57:17 UTC 2009

I can corroborate this problem.  From the WPA-PSK network here I am
disconnected within a second of connecting, every time.  Setting up
wpa_supplicant manually works just fine.

Relevant (sanitized) log lines:

Mar 21 00:24:27 clayton NetworkManager: <debug> [1237609467.360592]
nm_device_802_11_wireless_get_activation_ap(): Forcing AP '***'
Mar 21 00:24:27 clayton NetworkManager: <info>  User Switch:
/org/freedesktop/NetworkManager/Devices/wlan0 / ***
Mar 21 00:24:27 clayton NetworkManager: <info>  Deactivating device wlan0.
Mar 21 00:24:27 clayton NetworkManager: <info>  Device wlan0
activation scheduled...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0) started...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) scheduled...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) started...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) scheduled...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) complete.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) starting...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation
(wlan0/wireless): access point '***' is encrypted, but NO valid key
exists.  New key needed.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0) New
wireless user key requested for network '***'.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) complete.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0) New
wireless user key for network '***' received.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) scheduled...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) started...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) scheduled...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 1 of 5 (Device Prepare) complete.
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) starting...
Mar 21 00:24:27 clayton NetworkManager: <info>  Activation
(wlan0/wireless): access point '***' is encrypted, and a key exists.
No new key needed.
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'INTERFACE_ADD wlan0^I^Iwext^I/var/run/wpa_supplicant^I'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'AP_SCAN 1'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'ADD_NETWORK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was '0'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 ssid ***'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 proto WPA'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 key_mgmt WPA-PSK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 psk <key>'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: sending command
'ENABLE_NETWORK 0'
Mar 21 00:24:28 clayton NetworkManager: <info>  SUP: response was 'OK'
Mar 21 00:24:28 clayton NetworkManager: <info>  Activation (wlan0)
Stage 2 of 5 (Device Configure) complete.
Mar 21 00:24:28 clayton NetworkManager: <info>  Supplicant state changed: 1
Mar 21 00:24:28 clayton NetworkManager: <info>  Activation
(wlan0/wireless) Stage 2 of 5 (Device Configure) successful.
Connected to access point '***'.
Mar 21 00:24:28 clayton NetworkManager: <info>  Activation (wlan0)
Stage 3 of 5 (IP Configure Start) scheduled.
Mar 21 00:24:28 clayton NetworkManager: <info>  Activation (wlan0)
Stage 3 of 5 (IP Configure Start) started...
Mar 21 00:24:29 clayton NetworkManager: <info>  Activation (wlan0)
Beginning DHCP transaction.
Mar 21 00:24:29 clayton NetworkManager: <info>  Activation (wlan0)
Stage 3 of 5 (IP Configure Start) complete.
Mar 21 00:24:29 clayton NetworkManager: <info>  DHCP daemon state is
now 12 (successfully started) for interface wlan0
Mar 21 00:24:30 clayton NetworkManager: <info>  DHCP daemon state is
now 1 (starting) for interface wlan0
Mar 21 00:24:33 clayton NetworkManager: <info>  DHCP daemon state is
now 2 (bound) for interface wlan0
Mar 21 00:24:33 clayton NetworkManager: <info>  Activation (wlan0)
Stage 4 of 5 (IP Configure Get) scheduled...
Mar 21 00:24:33 clayton NetworkManager: <info>  Activation (wlan0)
Stage 4 of 5 (IP Configure Get) started...
Mar 21 00:24:33 clayton NetworkManager: <info>  Retrieved the
following IP4 configuration from the DHCP daemon:
Mar 21 00:24:33 clayton NetworkManager: <info>    address x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    netmask x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    broadcast x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    gateway x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    nameserver x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    nameserver x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    nameserver x.x.x.x
Mar 21 00:24:33 clayton NetworkManager: <info>    domain name 'xx.xx.xx.'
Mar 21 00:24:33 clayton NetworkManager: <info>  Activation (wlan0)
Stage 5 of 5 (IP Configure Commit) scheduled...
Mar 21 00:24:33 clayton NetworkManager: <info>  Activation (wlan0)
Stage 4 of 5 (IP Configure Get) complete.
Mar 21 00:24:33 clayton NetworkManager: <info>  Activation (wlan0)
Stage 5 of 5 (IP Configure Commit) started...
Mar 21 00:24:34 clayton NetworkManager: <info>  DHCP returned name
servers but system has disabled dynamic modification!
Mar 21 00:24:34 clayton NetworkManager: <info>  Activation (wlan0)
successful, device activated.
Mar 21 00:24:34 clayton NetworkManager: <info>  Activation (wlan0)
Finish handler scheduled.
Mar 21 00:24:34 clayton NetworkManager: <info>  Activation (wlan0)
Stage 5 of 5 (IP Configure Commit) complete.
Mar 21 00:24:34 clayton NetworkManager: <debug> [1237609474.349382]
nm_dbus_signal_filter(): NetworkManagerInfo triggered update of
wireless network '***'
Mar 21 00:24:34 clayton NetworkManager: <info>  SWITCH: terminating
current connection 'wlan0' because it's no longer valid.
Mar 21 00:24:34 clayton NetworkManager: <info>  Deactivating device wlan0.
Mar 21 00:24:35 clayton NetworkManager: nm_device_is_802_3_ethernet:
assertion `dev != NULL' failed
Mar 21 00:24:35 clayton NetworkManager: nm_device_is_802_11_wireless:
assertion `dev != NULL' failed

As you can see, the disconnection happens almost immediately.  This is
on lenny, using network-manager 0.6.6-3.  IMO this is a major
usability problem and should be fixed in lenny, not delayed until
squeeze is released.

-- 
Chris Howie
http://www.chrishowie.com
http://en.wikipedia.org/wiki/User:Crazycomputers