wpa_supplicant : Association request to the driver failed

Thu Apr 9 03:49:26 PDT 2009

Hi Dan,

Below is the wpa_supplicant log using -dddt. I noticed a line "Authentication with 00:15:e9:0e:98:d2 timed out".
What could be the possible cause? I already set my wireless router to plaintext (No encryption).
I put wpa_supplicant to the background. I found that it successfully associated with ap after hundreds (maybe thousands) of retry.
I launch a ping request to the gateway (192.168.0.1), sometimes I can get response but most of the time the data packet is lost.
That means the network is extremely unstable.

root at onyx ~$ wpa_supplicant -dddt -Dwext -ieth0 -c/etc/none.conf &
946700137.317984: Initializing interface 'eth0' conf '/etc/none.conf' driver 'we
xt' ctrl_interface 'N/A' bridge 'N/A'
946700137.318393: Configuration file '/etc/none.conf' -> '/etc/none.conf'
946700137.318441: Reading configuration file '/etc/none.conf'
946700137.318703: ctrl_interface='/var/run/wpa_supplicant'
946700137.318756: Line: 5 - start of a new network block
946700137.318999: ssid - hexdump_ascii(len=5):
     74 69 67 65 72                                    tiger
946700137.319159: key_mgmt: 0x4
946700137.319335: Priority group 0
946700137.319377:    id=0 ssid='tiger'
946700137.319408: Initializing interface (2) 'eth0'
946700137.320135: Interface eth0 set UP - waiting a second for the driver to com
plete initialization
root at onyx ~$ 946700138.320429: SIOCGIWRANGE: WE(compiled)=22 WE(source)=15 enc_c
apa=0xf
946700138.320608:   capabilities: key_mgmt 0xf enc 0xf flags 0x0
946700138.320897: WEXT: Operstate: linkmode=1, operstate=5
946700138.348871: Own MAC address: 00:1a:6b:94:fb:58
946700138.349016: wpa_driver_wext_set_wpa
946700138.349088: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 ke
y_len=0
946700138.349201: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 ke
y_len=0
946700138.349264: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 ke
y_len=0
946700138.349321: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 ke
y_len=0
946700138.349376: wpa_driver_wext_set_countermeasures
946700138.349416: wpa_driver_wext_set_drop_unencrypted
946700138.349453: RSN: flushing PMKID list in the driver
946700138.349562: Setting scan request: 0 sec 100000 usec
946700138.359015: EAPOL: SUPP_PAE entering state DISCONNECTED
946700138.359089: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
946700138.359133: EAPOL: SUPP_BE entering state INITIALIZE
946700138.359166: EAP: EAP entering state DISABLED
946700138.359462: Added interface eth0
946700138.359679: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700138.359736: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
946700138.359801: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700138.359841: Wireless event: cmd=0x8b06 len=8
946700138.458846: State: DISCONNECTED -> SCANNING
946700138.458975: Starting AP scan (broadcast SSID)
946700138.459006: Trying to get current scan results first without requesting a
new scan to speed up initial association
946700138.459133: Received 169 bytes of scan results (1 BSSes)
946700138.459227: CTRL-EVENT-SCAN-RESULTS
946700138.459265: Selecting BSS from priority group 0
946700138.459294: Try to find WPA-enabled AP
946700138.459323: 0: 00:15:e9:0e:98:d2 ssid='tiger' wpa_ie_len=0 rsn_ie_len=0 ca
ps=0x1
946700138.459368:    skip - no WPA/RSN IE
946700138.459393: Try to find non-WPA AP
946700138.459419: 0: 00:15:e9:0e:98:d2 ssid='tiger' wpa_ie_len=0 rsn_ie_len=0 ca
ps=0x1
946700138.459464:    selected non-WPA AP 00:15:e9:0e:98:d2 ssid='tiger'
946700138.459526: Trying to associate with 00:15:e9:0e:98:d2 (SSID='tiger' freq=
2437 MHz)
946700138.459563: Cancelling scan request
946700138.459591: WPA: clearing own WPA/RSN IE
946700138.459657: Automatic auth_alg selection: 0x1
946700138.459707: WPA: clearing AP WPA IE
946700138.459737: WPA: clearing AP RSN IE
946700138.459762: WPA: clearing own WPA/RSN IE
946700138.459789: No keys have been configured - skip key clearing
946700138.459818: wpa_driver_wext_set_drop_unencrypted
946700138.459855: State: SCANNING -> ASSOCIATING
946700138.459883: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
946700138.459917: WEXT: Operstate: linkmode=-1, operstate=5
946700138.459984: wpa_driver_wext_associate
946700138.460065: wpa_driver_wext_set_psk
946700138.460177: Association request to the driver failed
946700138.460226: Setting authentication timeout: 5 sec 0 usec
946700138.460265: EAPOL: External notification - EAP success=0
946700138.460413: EAPOL: External notification - EAP fail=0
946700138.460449: EAPOL: External notification - portControl=ForceAuthorized
946700138.460546: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700138.460591: Wireless event: cmd=0x8b06 len=8
946700138.460629: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700138.460665: Wireless event: cmd=0x8b04 len=12
946700138.460700: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700138.460734: Wireless event: cmd=0x8b1a len=13
946700139.368847: EAPOL: disable timer tick
946700143.468888: Authentication with 00:15:e9:0e:98:d2 timed out.
946700143.469039: Added BSSID 00:15:e9:0e:98:d2 into blacklist
946700143.469084: No keys have been configured - skip key clearing
946700143.469114: State: ASSOCIATING -> DISCONNECTED
946700143.469142: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
946700143.469175: WEXT: Operstate: linkmode=-1, operstate=5
946700143.469245: EAPOL: External notification - portEnabled=0
946700143.469288: EAPOL: External notification - portValid=0
946700143.469335: Setting scan request: 0 sec 0 usec
946700143.469394: State: DISCONNECTED -> SCANNING
946700143.469426: Starting AP scan (broadcast SSID)
946700143.469480: Scan requested (ret=0) - scan timeout 5 seconds
946700144.118968: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700144.119119: Wireless event: cmd=0x8b19 len=8
946700144.119207: Received 0 bytes of scan results (0 BSSes)
946700144.119295: Cached scan results are empty - not posting
946700144.119331: Selecting BSS from priority group 0
946700144.119359: Try to find WPA-enabled AP
946700144.119384: Try to find non-WPA AP
946700144.119408: No APs found - clear blacklist and try again
946700144.119435: Removed BSSID 00:15:e9:0e:98:d2 from blacklist (clear)
946700144.119472: Selecting BSS from priority group 0
946700144.119498: Try to find WPA-enabled AP
946700144.119521: Try to find non-WPA AP
946700144.119544: No suitable AP found.
946700144.119579: Setting scan request: 0 sec 0 usec
946700144.119641: Starting AP scan (broadcast SSID)
946700144.119692: Scan requested (ret=0) - scan timeout 30 seconds
946700144.768951: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700144.769106: Wireless event: cmd=0x8b19 len=8
946700144.769223: Received 169 bytes of scan results (1 BSSes)
946700144.769276: CTRL-EVENT-SCAN-RESULTS
946700144.769308: Selecting BSS from priority group 0
946700144.769336: Try to find WPA-enabled AP
946700144.769363: 0: 00:15:e9:0e:98:d2 ssid='tiger' wpa_ie_len=0 rsn_ie_len=0 ca
ps=0x1
946700144.769408:    skip - no WPA/RSN IE
946700144.769431: Try to find non-WPA AP
946700144.769456: 0: 00:15:e9:0e:98:d2 ssid='tiger' wpa_ie_len=0 rsn_ie_len=0 ca
ps=0x1
946700144.769500:    selected non-WPA AP 00:15:e9:0e:98:d2 ssid='tiger'
946700144.769558: Trying to associate with 00:15:e9:0e:98:d2 (SSID='tiger' freq=
2437 MHz)
946700144.769595: Cancelling scan request
946700144.769623: WPA: clearing own WPA/RSN IE
946700144.769682: Automatic auth_alg selection: 0x1
946700144.769734: WPA: clearing AP WPA IE
946700144.769763: WPA: clearing AP RSN IE
946700144.769789: WPA: clearing own WPA/RSN IE
946700144.769816: No keys have been configured - skip key clearing
946700144.769845: wpa_driver_wext_set_drop_unencrypted
946700144.769884: State: SCANNING -> ASSOCIATING
946700144.769913: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
946700144.769946: WEXT: Operstate: linkmode=-1, operstate=5
946700144.770011: wpa_driver_wext_associate
946700144.770098: wpa_driver_wext_set_psk
946700144.770210: Association request to the driver failed
946700144.770257: Setting authentication timeout: 5 sec 0 usec
946700144.770295: EAPOL: External notification - EAP success=0
946700144.770333: EAPOL: External notification - EAP fail=0
946700144.770365: EAPOL: External notification - portControl=ForceAuthorized
946700144.770550: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700144.770597: Wireless event: cmd=0x8b06 len=8
946700144.770634: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700144.770668: Wireless event: cmd=0x8b04 len=12
946700144.770703: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
946700144.770737: Wireless event: cmd=0x8b1a len=13
946700149.778882: Authentication with 00:15:e9:0e:98:d2 timed out.

----- Original Message ----- 
From: "Dan Williams" <dcbw at redhat.com>
To: "lijinlei1" <lijinlei1 at 163.com>
Cc: <hostap at lists.shmoo.com>
Sent: Wednesday, April 08, 2009 9:56 PM
Subject: Re: wpa_supplicant : Association request to the driver failed

> On Tue, 2009-04-07 at 14:41 +0800, lijinlei1 wrote:
>> Hi Dan,
>> 
>> Thanks for your reply.
>> I am using the 2.6.24 stock kernel from kernel.org, and i.MX31L (3-stack) platform. I applied the freescale patch to get the SDIO working.
>> I tried 2 options: 2.6.24 libertas (from stock kernel) + v8.73 firmware (from Marvell), not work.
>>                    2.6.27 libertas (from stock kernel) + v9.70 firmware (from Marvell), still no luck.
>> 
>> The logs from wpa_supplicant 0.6.9 are the same for the 2 options above.
>> I traced the call sequences, I found in wpa_driver_wext_associate():
>> 
>> line 2096:
>>  if (wpa_driver_wext_set_auth_param(drv,
>>         IW_AUTH_PRIVACY_INVOKED, value) < 0)
>>   ret = -1;
>> and line 2111:
>>  if (wpa_driver_wext_set_auth_param(drv,
>>         IW_AUTH_RX_UNENCRYPTED_EAPOL,
>>         allow_unencrypted_eapol) < 0)
>> 
>> Those 2 calls failed. The libertas driver can't handle those 2 ioctls: IW_AUTH_PRIVACY_INVOKED and IW_AUTH_RX_UNENCRYPTED_EAPOL, with value 10 and 8 respectively.
>> Will this be the cause of the association failure?
> 
> Probably not, no.  These calls aren't really required in your situation.
> What happens _after_ the "association request to the driver failed" in
> the supplicant?  Can you also use "-dddt" as the debug options to the
> supplicant so we can get some more info about what's going on?
> 
> dan