NetworkManager/WPA Authentication Wedged - how to debug?

[David Abrahams <dave boost-consulting com>]

[multi-posted (sorry, didn't know about this list) to
 gmane.linux.ubuntu.user]

Hi,

I've got nm-applet and wpa_supplicant installed.  Most of the time
they work great (although the time it takes to connect when I unplug a
network cable is a bit long).  However, sometimes it gets into a state
where it just won't authenticate until I reboot.  The syslog shows the
computer talking to the access point, and then... nothing (see
enclosed).  I used to think this could only happen when I start out
with a wired connection and unplug the cable, but this last time, it
was after a fresh reboot with no wired connection.

BTW, I have lots more log data showing other WPA connection failures
which I can supply on request.  I've been unable to find a consistent
pattern in the log messages, though.  How can I debug this when it
happens?  I don't know where else to look for information.

Thanks very much in advance...

10:50:23...wpa_supplicant(5818): proto: 0x1 
10:50:23...wpa_supplicant(5818): RX ctrl_iface - hexdump_ascii(len=30): 
10:50:23...wpa_supplicant(5818):      53 45 54 5f 4e 45 54 57 4f 52 4b 20 30 20 6b 65   SET_NETWORK 0 ke 
10:50:23...wpa_supplicant(5818):      79 5f 6d 67 6d 74 20 57 50 41 2d 50 53 4b         y_mgmt WPA-PSK   
10:50:23...wpa_supplicant(5818): CTRL_IFACE: SET_NETWORK id=0 name='key_mgmt' value='WPA-PSK' 
10:50:23...wpa_supplicant(5818): key_mgmt: 0x2 
10:50:23...wpa_supplicant(5818): RX ctrl_iface - hexdump_ascii(len=82): [REMOVED] 
10:50:23...wpa_supplicant(5818): CTRL_IFACE: SET_NETWORK id=0 name='psk' value='90876285a82cab6d914bb1c1d1e04b23ac3e7b9215cd56372eb782af19b30d03' 
10:50:23...wpa_supplicant(5818): PSK - hexdump(len=32): [REMOVED] 
10:50:23...wpa_supplicant(5818): trl_iface - hexdump_ascii(len=27): 
10:50:23...wpa_supplicant(5818):      53 45 54 5f 4e 45 54 57 4f 52 4b 20 30 20 70 61   SET_NETWORK 0 pa 
10:50:23...wpa_supplicant(5818):      69 72 77 69 73 65 20 54 4b 49 50                  irwise TKIP      
10:50:23...wpa_supplicant(5818): CTRL_IFACE: SET_NETWORK id=0 name='pairwise' value='TKIP' 
10:50:23...wpa_supplicant(5818): pairwise: 0x8 
10:50:23...wpa_supplicant(5818): RX ctrl_iface - hexdump_ascii(len=24): 
10:50:23...wpa_supplicant(5818):      53 45 54 5f 4e 45 54 57 4f 52 4b 20 30 20 67 72   SET_NETWORK 0 gr 
10:50:23...wpa_supplicant(5818):      6f 75 70 20 54 4b 49 50                           oup TKIP         
10:50:23...wpa_supplicant(5818): CTRL_IFACE: SET_NETWORK id=0 name='group' value='TKIP' 
10:50:23...wpa_supplicant(5818): group: 0x8 
10:50:23...wpa_supplicant(5818): RX ctrl_iface - hexdump_ascii(len=16): 
10:50:23...wpa_supplicant(5818):      45 4e 41 42 4c 45 5f 4e 45 54 57 4f 52 4b 20 30   ENABLE_NETWORK 0 
10:50:23...wpa_supplicant(5818): CTRL_IFACE: ENABLE_NETWORK id=0 
10:50:23...wpa_supplicant(5818): Setting scan request: 0 sec 0 usec 
10:50:23...wpa_supplicant(5818): State: DISCONNECTED -> SCANNING 
10:50:23...wpa_supplicant(5818): Trying to associate with SSID 'peloton' 
10:50:23...wpa_supplicant(5818): Cancelling scan request 
10:50:23...wpa_supplicant(5818): WPA: clearing own WPA/RSN IE 
10:50:23...wpa_supplicant(5818): Automatic auth_alg selection: 0x1 
10:50:23...wpa_supplicant(5818): WPA: No WPA/RSN IE available from association info 
10:50:23...wpa_supplicant(5818): WPA: Set cipher suites based on configuration 
10:50:23...wpa_supplicant(5818): WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 
10:50:23...wpa_supplicant(5818): WPA: clearing AP WPA IE 
10:52:23...Activation (eth1/wireless): association took too long (>120s), failing activation. 
10:52:23...Activation (eth1) failure scheduled... 
10:52:23...Activation (eth1) failed for access point (peloton) 
10:52:23...Activation (eth1) failed. 
10:52:23...Deactivating device eth1. 
10:52:25...match 
10:52:27...match 
10:54:28...match 
10:54:28...match 

-- 
Dave Abrahams
Boost Consulting
www.boost-consulting.com