Can connect, but not reconnect, to WPA2 network
Todd Pytel
tppytel
Wed Jun 18 09:58:48 PDT 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