Can connect, but not reconnect, to WPA2 network

Todd Pytel tppytel at sophrosune.org
Wed Jun 18 12:58:48 EDT 2008


Hi all,

I posted about the problem below to the Network Manager list, and one
responder suggested that the problem may be related to wpa_supplicant
and/or my wireless driver. I'm not so sure, but I would appreciate any
help in, at least, generating better debug info and narrowing down where
the problem is. One difficulty I'm having in producing useful debugging
information is that I only see this problem when using Network Manager -
running wpa_supplicant at the command line works fine. However, when
using Network Manager I don't know how to capture any debug output from
wpa_supplicant (as opposed to running wpa_supplicant directly in the
foreground). If someone could at least help me track down enough
information to figure out who the relevant devs are, I would
tremendously appreciate it. 

Thanks,
Todd

** Original message follows **

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. Network Manager version is 0.6.6, wpa_supplicant is
0.6.3.

When I set up the connection "from scratch" (entering the key,
specifying the security settings, etc. in the Network Manager GUI)
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. 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.


** wpa_supplicant.conf - This works fine running wpa_supplicant
independently of Network Manager **

ctrl_interface=/var/run/wpa_supplicant
ctrl_interface_group=0
ap_scan=1

network={
  ssid="SOPHROSUNE"
  proto=RSN
  key_mgmt=WPA-PSK
  pairwise=CCMP
  group=CCMP 
  psk="(mykey)"
}


** /var/log/messages - Showing successful association after configuring
connection from scratch **

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/message - Showing failed attempt to reassociate after
bringing down the initial connection **
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






More information about the HostAP mailing list