Bugzilla – Bug 10836
WPA/AES wireless setup fails
Last modified: 2009-09-08 09:28:26 UTC
Created attachment 4710 [details] syslog output during attempt to connect to WPA network factory reset r3932 Fab4 Linksys WRT-54GL running Tomato v1.23 wifi configured as WPA Personal w/AES connecting to this network fails. Reported first by peterw in forum, then reproduced by mysefl. Log attached
data point: exact same setup but using WPA2/TKIP-AES works
all methods of WPA Personal (TKIP, AES, TKIP+AES) fail for me all methods of WPA2 Personal (TKIP, AES, TKIP+AES) work for me Tomato also supports a WPA/WPA2 mode. These also work. I'll take a directed look at the code for WPA Personal next.
configured router for WPA personal AES with passphrase 'aaaaaaaa'. wpa_supplicant looks to be written correctly while trying to connect, though connect still fails ctrl_interface=/var/run/wpa_supplicant update_config=1 network={ ssid="squeezewifi" psk="aaaaaaaa" proto=WPA key_mgmt=WPA-PSK }
current thinking is a router interop problem with the Fab4 Marvell driver pasted from campfire ----------- Felix M. Ben: Try another AP with WPA. My Linksys works fine with WPA whereas the Netgear fails with WPA. Ben K. I'm using a linksys for my WPA test Felix M. Hmm Ben K. but it's a linksys with Tomato firmware, which is what might be the issue the original issue was reported by someone on the fab4 forum using the same firmware I'd previously tested on the same linksys with DD-WRT and WPA worked i've got a third wireless AP here (older netgear) which I'll try 12:45 PM Felix M. looks like a compatibility issue then Ben K. yeah, could be Felix M. does the same AP with WPA work with Jive? Ben K. good question. will try that now Felix M. we are using a different marvell driver on Fab4 than Jive Felix M. Jive seems to connect fine to the Netgear using WPA. Looks like an issue in the different Marvell driver. Ben K. linksys+tomato+wpa also connects with jive Felix M. Richard: Are you aware of WPA issues with the Fab4 Marvell driver? That is the open source one, isn't it?
added a debug.dump(status) in Networking:t_wpaStatus(). This is the output during a failed connection: { --[[table: 0xe1a428]] wpa_state = "ASSOCIATING", } { --[[table: 0xe1ec80]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "ASSOCIATED", group_cipher = "CCMP", } { --[[table: 0xe28f58]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "ASSOCIATED", group_cipher = "CCMP", } { --[[table: 0xe2e498]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "ASSOCIATED", group_cipher = "CCMP", } { --[[table: 0xe359c0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 vl{ --[[table: 0xe3b438]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xe42e48]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xe47c90]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xe4d4a8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xe527b0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xe57be8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xdd5ea0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xe11088]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xe20b78]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xe4cc80]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xd0fe58]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x730670]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x741760]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x8277a8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x7dea48]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x798338]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x88f768]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xc148a8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xd633c8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 { --[[table: 0xd0d630]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x834008]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xde7780]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 NOHZ: local_softirq_pending 08 { --[[table: 0xd77bf0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0xd66988]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } { --[[table: 0x97c0f8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", }
same test, with syslog printed inline to console during connection attempt Jan 5 00:14:50 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN Jan 5 00:14:50 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SCAN Jan 5 00:14:50 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:744) - remove network squeezewifi Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags for LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN_RESULTS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags for LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:638) - add network squeezewifi Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:744) - remove network squeezewifi Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid / frequency / signal level / flags / ssid 00:30:1b:da:e7:dd 2447 228 [WPA-PSK-CCMP] squeezewifi 00:1f:33:25:a0:2b 2437 216[WPS] NTGR_6f3Q4ePdI3NtrqgS2U 00:09:5b:53:91:58 2432 194 bkbroiler f Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags for LIST_NETWORKS Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:651) - Connect to squeezewifi Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: ADD_NETWORK Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:0 for ADD_NETWORK Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SET_NETWORK 0 ssid "squeezewifi" Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SET_NETWORK 0 ssid "squeezewifi" Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:669) - encryption WPA Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SET_NETWORK 0 key_mgmt WPA-PSK Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SET_NETWORK 0 key_mgmt WPA-PSK Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SET_NETWORK 0 proto WPA Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SET_NETWORK 0 proto WPA Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SET_NETWORK 0 psk "aaaaaaaa" Jan 5 00:14:51 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SELECT_NETWORK 0 Jan 5 00:14:52 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:52 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SELECT_NETWORK 0 Jan 5 00:14:52 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: REASSOCIATE Jan 5 00:14:52 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for REASSOCIATE Jan 5 00:14:52 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SAVE_CONFIG { --[[table: 0x7a3ad8]] wpa_state = "SCANNING", } Jan 5 00:14:53 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:53 SqueezeboxController daemon.notice wpa_supplicant[848]: Trying to associate with 00:30:1b:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Jan 5 00:14:53 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:wpa_state=SCANNING for STATUS Jan 5 00:14:54 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:54 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SAVE_CONFIG Jan 5 00:14:54 SqueezeboxController user.info jive: (Networking.lua:796) - select network squeezewifi Jan 5 00:14:54 SqueezeboxController user.info jive: (Networking.lua:927) - ifdown eth0=eth0 Jan 5 00:14:55 SqueezeboxController local0.info udhcpc[904]: Received SIGTERM Jan 5 00:14:55 SqueezeboxController local0.info udhcpc[904]: Unicasting a release of 192.168.1.100 to 192.168.1.1 Jan 5 00:14:55 SqueezeboxController local0.info udhcpc[904]: Sending release... Jan 5 00:14:55 SqueezeboxController user.notice root: udhcpc_action eth0 deconfig ip= Jan 5 00:14:55 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS Jan 5 00:14:55 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:56 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:56 SqueezeboxController daemon.notice wpa_supplicant[848]: Associated with 00:30:1b:da:e7:dd Jan 5 00:14:56 SqueezeboxController daemon.notice wpa_supplicant[848]: Trying to associate with 00:30:1b:da:e7:dd (SSID='squeezewifi' freq=2447 MHz) Jan 5 00:14:56 SqueezeboxController local0.info udhcpc[904]: Entering released state Jan 5 00:14:56 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for LIST_NETWORKS Jan 5 00:14:56 SqueezeboxController user.warn jive: (Networking.lua:876) - can't find network squeezewifi { --[[table: 0x99ffe0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:00:00:00:00:00", wpa_state = "4WAY_HANDSHAKE", group_cipher = "CCMP", } { --[[table: 0xd00fb0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "4WAY_HANDSHAKE", group_cipher = "CCMP", } { --[[table: 0xcc9770]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "4WAY_HANDSHAKE", group_cipher = "CCMP", } { --[[table: 0x9379b0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "GROUP_HANDSHAKE", group_cipher = "CCMP", } { --[[table: 0x94e858]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:57 SqueezeboxController daemon.notice wpa_supplicant[848]: Associated with 00:30:1b:da:e7:dd Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:00:00:00:00:00 ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=4WAY_HANDSHAKE for STATUS Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=4WAY_HANDSHAKE for STATUS Jan 5 00:14:57 SqueezeboxController user.warn jive: (Task.lua:74) - task error networkSelect: cannot resume dead coroutine Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=4WAY_HANDSHAKE for STATUS Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=GROUP_HANDSHAKE for STATUS Jan 5 00:14:57 SqueezeboxController daemon.notice wpa_supplicant[848]: WPA: Key negotiation completed with 00:30:1b:da:e7:dd [PTK=CCMP GTK=CCMP] Jan 5 00:14:57 SqueezeboxController daemon.notice wpa_supplicant[848]: CTRL-EVENT-CONNECTED - Connection to 00:30:1b:da:e7:dd completed (auth) [id=0 id_str=] Jan 5 00:14:57 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0x8ca0f0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:14:58 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:58 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xc15d68]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:14:59 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:14:59 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xde8098]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:00 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:00 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:00 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN Jan 5 00:15:00 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:00 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:00 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SCAN Jan 5 00:15:00 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS { --[[table: 0x89d050]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:01 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:01 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags 0 squeezewifi any [CURRENT] for LIST_NETWORKS Jan 5 00:15:01 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN_RESULTS Jan 5 00:15:01 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:01 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid / frequency / signal level / flags / ssid 00:30:1b:da:e7:dd 2447 220 [WPA-PSK-CCMP] squeezewifi 00:1f:33:25:a0:2b 2437 212[WPS] NTGR_6f3Q4ePdI3NtrqgS2U 00:09:5b:53:91:58 2432 193 bkbroiler f { --[[table: 0x756c40]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:02 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:02 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xc170b0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 Jan 5 00:15:03 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:03 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:03 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 { --[[table: 0xccd138]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:04 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:04 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xd034d0]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:05 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:05 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0x7cccf8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:06 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:06 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0x8f2f78]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:07 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:07 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xcfaa80]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:08 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:08 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xd27290]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:09 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:09 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xcd30d8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:10 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:10 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:10 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN Jan 5 00:15:10 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:10 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:10 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SCAN Jan 5 00:15:10 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS { --[[table: 0xcd5748]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMPNOHZ: local_softirq_pending 08 ", } Jan 5 00:15:11 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:11 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags 0 squeezewifi any [CURRENT] for LIST_NETWORKS Jan 5 00:15:11 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN_RESULTS Jan 5 00:15:11 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:11 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid / frequency / signal level / flags / ssid 00:30:1b:da:e7:dd 2447 219 [WPA-PSK-CCMP] squeezewifi 00:1f:33:25:a0:2b 2437 212[WPS] NTGR_6f3Q4ePdI3NtrqgS2U 00:09:5b:53:91:58 2432 193 bkbroiler f Jan 5 00:15:11 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 { --[[table: 0xcddd88]] pairwise_cipher = "CCMP", NOHZ: local_softirq_pending 08 key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:12 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:12 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLYNOHZ: local_softirq_pending 08 :bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:12 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 { --[[table: 0xd26880]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:13 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 Jan 5 00:15:13 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:13 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xd8d318]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 Jan 5 00:15:14 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:14 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:14 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 { --[[table: 0xe16770]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:15 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:15 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xd25530]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 Jan 5 00:15:16 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:16 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:16 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 { --[[table: 0xd57778]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:17 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:17 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xe0fb70]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:18 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:18 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xce9660]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:19 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:19 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS { --[[table: 0xcf9cc8]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } NOHZ: local_softirq_pending 08 Jan 5 00:15:20 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:20 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:20 SqueezeboxController user.err kernel: NOHZ: local_softirq_pending 08 Jan 5 00:15:20 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN Jan 5 00:15:20 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:20 SqueezeboxController user.err jive: (SocketUdp.lua:206) - SocketUdp:writePump:Network is unreachable Jan 5 00:15:20 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SCAN Jan 5 00:15:20 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS { --[[table: 0x7b8a70]] pairwise_cipher = "CCMP", key_mgmt = "WPA-PSK", ssid = "squeezewifi", id = "0", bssid = "00:30:1b:da:e7:dd", wpa_state = "COMPLETED", group_cipher = "CCMP", } Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags 0 squeezewifi any [CURRENT] for LIST_NETWORKS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN_RESULTS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:744) - remove network squeezewifi Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: LIST_NETWORKS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid / frequency / signal level / flags / ssid 00:30:1b:da:e7:dd 2447 228 [WPA-PSK-CCMP] squeezewifi 00:1f:33:25:a0:2b 2437 216[WPS] NTGR_6f3Q4ePdI3NtrqgS2U 00:09:5b:53:91:58 2432 192 bkbroiler f Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags 0 squeezewifi any [CURRENT] for LIST_NETWORKS Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: REMOVE_NETWORK 0 Jan 5 00:15:21 SqueezeboxController daemon.notice wpa_supplicant[848]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for REMOVE_NETWORK 0 Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SAVE_CONFIG Jan 5 00:15:21 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:OK for SAVE_CONFIG
on a subsequent, identical test, it connected successfully. One thing I notice in syslog is that after the key negotiation is complete, udhcpc starts and requests an IP for the interface. In the failed tests, the key negotiation message shows up but nothing from udhcpc excerpt from successful connection to WPA router: Jan 5 00:11:26 SqueezeboxController user.notice root: Found Jan 5 00:11:26 SqueezeboxController daemon.notice wpa_supplicant[846]: WPA: Key negotiation completed with 00:30:1b:da:e7:dd [PTK=CCMP GTK=CCMP] Jan 5 00:11:26 SqueezeboxController daemon.notice wpa_supplicant[846]: CTRL-EVENT-CONNECTED - Connection to 00:30:1b:da:e7:dd completed (reauth) [id=0 id_str=] Jan 5 00:11:26 SqueezeboxController local0.info udhcpc[957]: udhcpc (v1.7.0) started Jan 5 00:11:26 SqueezeboxController user.notice root: udhcpc_action wlan0 deconfig ip= Jan 5 00:11:26 SqueezeboxController local0.info udhcpc[957]: Sending discover... Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=ASSOCIATED for STATUS Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:network id / ssid / bssid / flags 0 squeezewifi any [CURRENT] for LIST_NETWORKS Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: SCAN_RESULTS Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=4WAY_HANDSHAKE for STATUS Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1370) - REQUEST: STATUS Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid / frequency / signal level / flags / ssid 00:30:1b:da:e7:dd 2447 220 [WPA-PSK-CCMP] squeezewifi 00:1f:33:25:a0:2b 2437 220[WPS] NTGR_6f3Q4ePdI3NtrqgS2U 00:09:5b:53:91:58 2432 194 bkbroiler f Jan 5 00:11:26 SqueezeboxController user.info jive: (Networking.lua:1400) - REPLY:bssid=00:30:1b:da:e7:dd ssid=squeezewifi id=0 pairwise_cipher=CCMP group_cipher=CCMP key_mgmt=WPA-PSK wpa_state=COMPLETED for STATUS Jan 5 00:11:26 SqueezeboxController local0.info udhcpc[957]: Sending select for 192.168.1.100... Jan 5 00:11:26 SqueezeboxController local0.info udhcpc[957]: Lease of 192.168.1.100 obtained, lease time 86400 Jan 5 00:11:26 SqueezeboxController user.notice root: udhcpc_action wlan0 bound ip=192.168.1.100
confirmed fixed in r3999