NM connects once, but cannot reconnect later

[Todd Pytel <tppytel sophrosune org>]

Hi all,

I've been having this issue with NM for some time and would kill to get
it solved. My laptop (a Dell E1505) has an Intel 3945 device and wants
to connect to a Cisco Aironet 1130AG access point using WPA2-Personal
with AES CCMP. The distro is a fully updated Debian Sid, running the
2.6.25 kernel. NM version is 0.6.6.

When I set up the connection "from scratch" (entering the key,
specifying the security settings, etc.) everything works fine. I
associate, DHCP fires up, all is good. However, once the connection is
brought down (say, by disabling wireless through the NM applet) I cannot
reassociate without going through the initial configuration all over
again. There appears to be some kind of key problem going on. I'm
including the output of /var/log/messages below for each case. The
sticking point appears to be this step:

NetworkManager: <info>  SUP: sending command 'SET_NETWORK 0 psk <key>' 

In the first case (starting from scratch), this returns OK. When
attempting to reconnect, it returns FAIL. I am not enough of a wifi guru
to know whether this problem is likely to stem from NM, from
wpa-supplicant, from the drivers, from my AP, or from the moon. I tried
a bit of searching here, but couldn't find the right term to narrow
things down. Any pointers in the right direction would be tremendously
appreciated. If there's any other information I can provide, I would be
eager to do so.

Thanks,
Todd

/var/log/messages - Initial Connection (works)

Jun 17 20:05:23 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.reason
Jun 17 20:05:23 hector NetworkManager: <info>  User
Switch: /org/freedesktop/NetworkManager/Devices/wlan0_5f_rename /
SOPHROSUNE 
Jun 17 20:05:23 hector NetworkManager: <info>  Deactivating device
wlan0_rename. 
Jun 17 20:05:23 hector NetworkManager: <info>  Device wlan0_rename
activation scheduled... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
started... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) scheduled... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) started... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) scheduled... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) complete. 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) starting... 
Jun 17 20:05:23 hector NetworkManager: <info>  Activation
(wlan0_rename/wireless): access point 'SOPHROSUNE' is encrypted, and a
key exists.  No new key needed. 
Jun 17 20:05:24 hector NetworkManager: <info>  SUP: sending command
'INTERFACE_ADD wlan0_rename^I^Iwext^I/var/run/wpa_supplicant^I' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'AP_SCAN 1' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'ADD_NETWORK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was '0' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 ssid 534f5048524f53554e45' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 proto WPA2' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 key_mgmt WPA-PSK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 psk <key>' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 pairwise CCMP' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 group CCMP' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: sending command
'ENABLE_NETWORK 0' 
Jun 17 20:05:25 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:05:25 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) complete. 
Jun 17 20:05:26 hector kernel: [  592.016419] ADDRCONF(NETDEV_CHANGE):
wlan0_rename: link becomes ready
Jun 17 20:05:27 hector kernel: [  592.516576] padlock: VIA PadLock not
detected.
Jun 17 20:05:27 hector modprobe: WARNING: Error inserting padlock_aes
(/lib/modules/2.6.25-2-686/kernel/drivers/crypto/padlock-aes.ko): No
such device 
Jun 17 20:05:27 hector NetworkManager: <info>  Supplicant state changed:
1 
Jun 17 20:05:27 hector NetworkManager: <info>  Activation
(wlan0_rename/wireless) Stage 2 of 5 (Device Configure) successful.
Connected to access point 'SOPHROSUNE'. 
Jun 17 20:05:27 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 3 of 5 (IP Configure Start) scheduled. 
Jun 17 20:05:27 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 3 of 5 (IP Configure Start) started... 
Jun 17 20:05:28 hector NetworkManager: <info>  Activation (wlan0_rename)
Beginning DHCP transaction. 
Jun 17 20:05:28 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 3 of 5 (IP Configure Start) complete. 
Jun 17 20:05:28 hector NetworkManager: <info>  DHCP daemon state is now
12 (successfully started) for interface wlan0_rename 
Jun 17 20:05:28 hector dhclient: eth1: unknown hardware address type 801
Jun 17 20:05:28 hector avahi-daemon[2437]: Joining mDNS multicast group
on interface wlan0_rename.IPv6 with address fe80::218:deff:fe83:1850.
Jun 17 20:05:28 hector avahi-daemon[2437]: New relevant interface
wlan0_rename.IPv6 for mDNS.
Jun 17 20:05:28 hector avahi-daemon[2437]: Registering new address
record for fe80::218:deff:fe83:1850 on wlan0_rename.*.
Jun 17 20:05:29 hector NetworkManager: <info>  DHCP daemon state is now
1 (starting) for interface wlan0_rename 
Jun 17 20:05:29 hector dhclient: eth1: unknown hardware address type 801
Jun 17 20:05:31 hector dhclient: DHCPDISCOVER on wlan0_rename to
255.255.255.255 port 67 interval 6
Jun 17 20:05:31 hector NetworkManager: <info>  Old device 'wlan0_rename'
activating, won't change. 
Jun 17 20:05:32 hector dhclient: DHCPOFFER from 192.168.1.1
Jun 17 20:05:32 hector dhclient: DHCPREQUEST on wlan0_rename to
255.255.255.255 port 67
Jun 17 20:05:32 hector dhclient: DHCPACK from 192.168.1.1
Jun 17 20:05:32 hector avahi-daemon[2437]: Joining mDNS multicast group
on interface wlan0_rename.IPv4 with address 192.168.0.62.
Jun 17 20:05:32 hector avahi-daemon[2437]: New relevant interface
wlan0_rename.IPv4 for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Registering new address
record for 192.168.0.62 on wlan0_rename.IPv4.
Jun 17 20:05:32 hector avahi-daemon[2437]: Withdrawing address record
for 192.168.0.62 on wlan0_rename.
Jun 17 20:05:32 hector avahi-daemon[2437]: Leaving mDNS multicast group
on interface wlan0_rename.IPv4 with address 192.168.0.62.
Jun 17 20:05:32 hector avahi-daemon[2437]: Interface wlan0_rename.IPv4
no longer relevant for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Joining mDNS multicast group
on interface wlan0_rename.IPv4 with address 192.168.0.62.
Jun 17 20:05:32 hector avahi-daemon[2437]: New relevant interface
wlan0_rename.IPv4 for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Registering new address
record for 192.168.0.62 on wlan0_rename.IPv4.
Jun 17 20:05:32 hector NetworkManager: <info>  DHCP daemon state is now
2 (bound) for interface wlan0_rename 
Jun 17 20:05:32 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 4 of 5 (IP Configure Get) scheduled... 
Jun 17 20:05:32 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 4 of 5 (IP Configure Get) started... 
Jun 17 20:05:32 hector dhclient: bound to 192.168.0.62 -- renewal in
35828 seconds.
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.host_name
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.domain_name
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.domain_search
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.nis_domain
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.nis_servers
Jun 17 20:05:32 hector NetworkManager: <info>  Retrieved the following
IP4 configuration from the DHCP daemon: 
Jun 17 20:05:32 hector NetworkManager: <info>    address 192.168.0.62 
Jun 17 20:05:32 hector NetworkManager: <info>    netmask 255.255.0.0 
Jun 17 20:05:32 hector NetworkManager: <info>    broadcast
192.168.255.255 
Jun 17 20:05:32 hector NetworkManager: <info>    gateway 192.168.1.1 
Jun 17 20:05:32 hector NetworkManager: <info>    nameserver
66.167.100.107 
Jun 17 20:05:32 hector dhcdbd: message_handler: message handler not
found under /com/redhat/dhcp/wlan0_rename for sub-path
wlan0_rename.dbus.get.interface_mtu
Jun 17 20:05:32 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 5 of 5 (IP Configure Commit) scheduled... 
Jun 17 20:05:32 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 4 of 5 (IP Configure Get) complete. 
Jun 17 20:05:32 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 5 of 5 (IP Configure Commit) started... 
Jun 17 20:05:32 hector avahi-daemon[2437]: Withdrawing address record
for 192.168.0.62 on wlan0_rename.
Jun 17 20:05:32 hector avahi-daemon[2437]: Leaving mDNS multicast group
on interface wlan0_rename.IPv4 with address 192.168.0.62.
Jun 17 20:05:32 hector avahi-daemon[2437]: Interface wlan0_rename.IPv4
no longer relevant for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Withdrawing address record
for fe80::218:deff:fe83:1850 on wlan0_rename.
Jun 17 20:05:32 hector avahi-daemon[2437]: Leaving mDNS multicast group
on interface wlan0_rename.IPv6 with address fe80::218:deff:fe83:1850.
Jun 17 20:05:32 hector avahi-daemon[2437]: Interface wlan0_rename.IPv6
no longer relevant for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Joining mDNS multicast group
on interface wlan0_rename.IPv4 with address 192.168.0.62.
Jun 17 20:05:32 hector avahi-daemon[2437]: New relevant interface
wlan0_rename.IPv4 for mDNS.
Jun 17 20:05:32 hector avahi-daemon[2437]: Registering new address
record for 192.168.0.62 on wlan0_rename.IPv4.
Jun 17 20:05:33 hector NetworkManager: <info>  DHCP returned name
servers but system has disabled dynamic modification! 
Jun 17 20:05:33 hector NetworkManager: <info>  Activation (wlan0_rename)
successful, device activated. 
Jun 17 20:05:33 hector NetworkManager: <info>  Activation (wlan0_rename)
Finish handler scheduled. 
Jun 17 20:05:33 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 5 of 5 (IP Configure Commit) complete. 
Jun 17 20:05:34 hector avahi-daemon[2437]: Joining mDNS multicast group
on interface wlan0_rename.IPv6 with address fe80::218:deff:fe83:1850.
Jun 17 20:05:34 hector avahi-daemon[2437]: New relevant interface
wlan0_rename.IPv6 for mDNS.
Jun 17 20:05:34 hector avahi-daemon[2437]: Registering new address
record for fe80::218:deff:fe83:1850 on wlan0_rename.*.


/var/log/messages - Resetting Connection (fails)

Jun 17 20:07:35 hector NetworkManager: <info>  User
Switch: /org/freedesktop/NetworkManager/Devices/wlan0_5f_rename /
SOPHROSUNE 
Jun 17 20:07:35 hector NetworkManager: <info>  Deactivating device
wlan0_rename. 
Jun 17 20:07:35 hector NetworkManager: <info>  Device wlan0_rename
activation scheduled... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
started... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) scheduled... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) started... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) scheduled... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) complete. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) starting... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation
(wlan0_rename/wireless): access point 'SOPHROSUNE' is encrypted, but NO
valid key exists.  New key needed. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
New wireless user key requested for network 'SOPHROSUNE'. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) complete. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
New wireless user key for network 'SOPHROSUNE' received. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) scheduled... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) started... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) scheduled... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 1 of 5 (Device Prepare) complete. 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) starting... 
Jun 17 20:07:35 hector NetworkManager: <info>  Activation
(wlan0_rename/wireless): access point 'SOPHROSUNE' is encrypted, and a
key exists.  No new key needed. 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'INTERFACE_ADD wlan0_rename^I^Iwext^I/var/run/wpa_supplicant^I' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'AP_SCAN 1' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'ADD_NETWORK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was '0' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 ssid 534f5048524f53554e45' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 proto WPA2' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 key_mgmt WPA-PSK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'OK' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 psk <key>' 
Jun 17 20:07:36 hector NetworkManager: <info>  SUP: response was 'FAIL' 
Jun 17 20:07:36 hector NetworkManager: <WARN>
nm_utils_supplicant_request_with_check(): real_write_supplicant_config:
supplicant error for 'SET_NETWORK 0 psk <key>'.  Response: 'FAIL' 
Jun 17 20:07:36 hector NetworkManager: <WARN>  real_act_stage2_config():
Activation (wlan0_rename/wireless): couldn't send wireless configuration
to the supplicant. 
Jun 17 20:07:36 hector NetworkManager: <info>  Activation (wlan0_rename)
failure scheduled... 
Jun 17 20:07:36 hector NetworkManager: <info>  Activation (wlan0_rename)
Stage 2 of 5 (Device Configure) complete. 
Jun 17 20:07:36 hector NetworkManager: <info>  Activation (wlan0_rename)
failed for access point (SOPHROSUNE) 
Jun 17 20:07:36 hector NetworkManager: <info>  Activation (wlan0_rename)
failed. 
Jun 17 20:07:36 hector NetworkManager: <info>  Deactivating device
wlan0_rename. 
Jun 17 20:07:37 hector kernel: [  719.839907] ACPI: PCI interrupt for
device 0000:0b:00.0 disabled
Jun 17 20:07:38 hector kernel: [  728.462010] ACPI: PCI Interrupt
0000:0b:00.0[A] -> GSI 16 (level, low) -> IRQ 16
Jun 17 20:07:38 hector kernel: [  728.512536] ADDRCONF(NETDEV_UP):
wlan0_rename: link is not ready