Debugging WPA auth issues

[Bill Moseley <moseley hank org>]

I'm running Ubuntu 8.10 with Atheros ath9k driver on a Thinkpad T60p.

Sorry for the mundane question, but I'm visiting family and they have
an older Linksys Wireless-B router (AP).


The AP has WPA Pre-Shared Key with TKIP (other options are  WPA
RADIUS, RADIUS, and WEP option).

When I enable WPA Pre-Shared and enter a key like 1212121212 then
nm-applet just keeps asking form my pass phrase.  I've tried a few
other pass phrases, just for fun.

If I disable wireless security on the router I can easily connect
(nm-applet ends up showing the ssid twice, once with security and once
without).

I've only been able to connect one time with security enabled, so I
know it is possible to connect.


Can someone suggest debugging tips to try and find out where the
connection is failing and why?

Here's NM logs when trying to connect:


Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) starting connection 'Auto whmlan2' 
Feb 13 15:49:59 tiger NetworkManager: <info>  (wlan0): device state change: 3 -> 4 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Feb 13 15:49:59 tiger NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0/wireless): access point 'Auto whmlan2' has security, but secrets are required. 
Feb 13 15:49:59 tiger NetworkManager: <info>  (wlan0): device state change: 5 -> 6 
Feb 13 15:49:59 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Feb 13 15:50:01 tiger /USR/SBIN/CRON[6313]: (root) CMD ([ -x /usr/sbin/update-motd ] && /usr/sbin/update-motd 2>/dev/null)


nm-applet requests password

Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Feb 13 15:50:19 tiger NetworkManager: <info>  (wlan0): device state change: 6 -> 4 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Feb 13 15:50:19 tiger NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto whmlan2' has security, and secrets exist.  No new secrets needed. 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'ssid' value 'whmlan2' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'psk' value '<omitted>' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'proto' value 'WPA RSN' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'pairwise' value 'TKIP CCMP' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: added 'group' value 'WEP40 WEP104 TKIP CCMP' 
Feb 13 15:50:19 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Feb 13 15:50:19 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:50:19 tiger NetworkManager: <info>  Config: set interface ap_scan to 1 
Feb 13 15:50:19 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:50:20 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 3 
Feb 13 15:50:22 tiger kernel: [  172.001625] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:22 tiger kernel: [  172.002895] wlan0: authenticated
Feb 13 15:50:22 tiger kernel: [  172.002902] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:50:22 tiger kernel: [  172.005154] wlan0: RX AssocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=7)
Feb 13 15:50:22 tiger kernel: [  172.005162] wlan0: associated
Feb 13 15:50:22 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:50:32 tiger kernel: [  182.016261] wlan0: disassociating by local choice (reason=3)
Feb 13 15:50:32 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:50:32 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:50:32 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:50:33 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 3 
Feb 13 15:50:33 tiger kernel: [  183.582909] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:33 tiger kernel: [  183.582992] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:33 tiger kernel: [  183.584923] wlan0: authenticated
Feb 13 15:50:33 tiger kernel: [  183.584928] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:50:33 tiger kernel: [  183.589043] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=8)
Feb 13 15:50:33 tiger kernel: [  183.589054] wlan0: associated
Feb 13 15:50:33 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:50:34 tiger NetworkManager: <info>  wlan0: link timed out. 
Feb 13 15:50:43 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:50:43 tiger kernel: [  193.600238] wlan0: disassociating by local choice (reason=3)
Feb 13 15:50:43 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:50:43 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:50:45 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 3 
Feb 13 15:50:45 tiger kernel: [  195.203518] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:45 tiger kernel: [  195.203630] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:45 tiger kernel: [  195.204865] wlan0: authenticated
Feb 13 15:50:45 tiger kernel: [  195.204877] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:50:45 tiger kernel: [  195.208618] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=9)
Feb 13 15:50:45 tiger kernel: [  195.208628] wlan0: associated
Feb 13 15:50:45 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:50:55 tiger kernel: [  205.221243] wlan0: disassociating by local choice (reason=3)
Feb 13 15:50:55 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:50:55 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:50:55 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:50:56 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 3 
Feb 13 15:50:57 tiger kernel: [  206.820864] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:57 tiger kernel: [  206.820981] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:50:57 tiger kernel: [  206.822126] wlan0: authenticated
Feb 13 15:50:57 tiger kernel: [  206.822130] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:50:57 tiger kernel: [  206.825947] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=10)
Feb 13 15:50:57 tiger kernel: [  206.825955] wlan0: associated
Feb 13 15:50:57 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:50:58 tiger NetworkManager: <info>  wlan0: link timed out. 
Feb 13 15:51:07 tiger kernel: [  216.837241] wlan0: disassociating by local choice (reason=3)
Feb 13 15:51:07 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:51:07 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:07 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:51:08 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 3 
Feb 13 15:51:08 tiger kernel: [  218.447601] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:08 tiger kernel: [  218.447721] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:08 tiger kernel: [  218.449936] wlan0: authenticated
Feb 13 15:51:08 tiger kernel: [  218.449942] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:51:08 tiger kernel: [  218.452932] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=11)
Feb 13 15:51:08 tiger kernel: [  218.452942] wlan0: associated
Feb 13 15:51:08 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:51:18 tiger kernel: [  228.465237] wlan0: disassociating by local choice (reason=3)
Feb 13 15:51:18 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:51:18 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:18 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:51:19 tiger NetworkManager: <info>  Activation (wlan0/wireless): association took too long. 
Feb 13 15:51:19 tiger NetworkManager: <info>  (wlan0): device state change: 5 -> 6 
Feb 13 15:51:19 tiger NetworkManager: <info>  Activation (wlan0/wireless): asking for new secrets 
Feb 13 15:51:20 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 3 
Feb 13 15:51:20 tiger kernel: [  229.954252] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:20 tiger kernel: [  229.954320] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:20 tiger kernel: [  230.152169] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:20 tiger kernel: [  230.352172] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:20 tiger kernel: [  230.552508] wlan0: authentication with AP 00:0f:66:21:87:43 timed out


asks for password again

Feb 13 15:51:30 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 0 
Feb 13 15:51:30 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:31 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 3 
Feb 13 15:51:32 tiger kernel: [  241.731124] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:32 tiger kernel: [  241.731180] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:32 tiger kernel: [  241.732421] wlan0: authenticated
Feb 13 15:51:32 tiger kernel: [  241.732434] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:51:32 tiger kernel: [  241.736232] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=12)
Feb 13 15:51:32 tiger kernel: [  241.736243] wlan0: associated
Feb 13 15:51:32 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started... 
Feb 13 15:51:40 tiger NetworkManager: <info>  (wlan0): device state change: 6 -> 4 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting... 
Feb 13 15:51:40 tiger NetworkManager: <info>  (wlan0): device state change: 4 -> 5 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto whmlan2' has security, and secrets exist.  No new secrets needed. 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'ssid' value 'whmlan2' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'scan_ssid' value '1' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-PSK' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'psk' value '<omitted>' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'proto' value 'WPA RSN' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'pairwise' value 'TKIP CCMP' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: added 'group' value 'WEP40 WEP104 TKIP CCMP' 
Feb 13 15:51:40 tiger NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete. 
Feb 13 15:51:40 tiger kernel: [  250.589384] wlan0: disassociating by local choice (reason=3)
Feb 13 15:51:40 tiger NetworkManager: <info>  Config: set interface ap_scan to 1 
Feb 13 15:51:40 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 4 -> 0 
Feb 13 15:51:40 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:42 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 0 
Feb 13 15:51:42 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:42 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 3 
Feb 13 15:51:42 tiger kernel: [  252.047139] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:42 tiger kernel: [  252.047206] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:42 tiger kernel: [  252.244177] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:42 tiger kernel: [  252.444175] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:42 tiger kernel: [  252.644154] wlan0: authentication with AP 00:0f:66:21:87:43 timed out
Feb 13 15:51:52 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 0 
Feb 13 15:51:52 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:51:53 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 3 
Feb 13 15:51:54 tiger kernel: [  263.735022] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:54 tiger kernel: [  263.735089] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:54 tiger kernel: [  263.932122] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:54 tiger kernel: [  264.132119] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:51:54 tiger kernel: [  264.336117] wlan0: authentication with AP 00:0f:66:21:87:43 timed out
Feb 13 15:51:55 tiger NetworkManager: <info>  wlan0: link timed out. 
Feb 13 15:52:04 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 0 
Feb 13 15:52:04 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 0 -> 2 
Feb 13 15:52:05 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 2 -> 3 
Feb 13 15:52:05 tiger kernel: [  275.430381] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:52:05 tiger kernel: [  275.430477] wlan0: authenticate with AP 00:0f:66:21:87:43
Feb 13 15:52:05 tiger kernel: [  275.431676] wlan0: authenticated
Feb 13 15:52:05 tiger kernel: [  275.431684] wlan0: associate with AP 00:0f:66:21:87:43
Feb 13 15:52:05 tiger kernel: [  275.435540] wlan0: RX ReassocResp from 00:0f:66:21:87:43 (capab=0x5 status=0 aid=13)
Feb 13 15:52:05 tiger kernel: [  275.435551] wlan0: associated
Feb 13 15:52:05 tiger NetworkManager: <info>  (wlan0): supplicant connection state change: 3 -> 4 

-- 
Bill Moseley
moseley hank org
Sent from my iMutt