wpa_supplicant : Association request to the driver failed

Thu Apr 9 07:15:55 PDT 2009

On Thu, 2009-04-09 at 18:49 +0800, lijinlei1 wrote:
> 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.

So this time you'll want to enable driver debugging to find out why the
AP isn't being associated with.

Build the libertas driver with CONFIG_LIBERTAS_DEBUG enabled, modprobe
the libertas.ko module with "libertas_debug=0x43a7" and then try to
associate by running wpa_supplicant.  Keep another terminal open to
'killall -9 wpa_supplicant' so we can get the state without the
supplicant cleaning up afterwards.  Then grab output from 'dmesg', or,
hopefully, you're saving it somewhere else over an SSH or telnet or
serial session so we can get the whole log, since the kernel log buffer
is fixed size.

Dan

> 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