wpa-supplicant v0.7.2 stops roaming after a while

Wed Apr 28 14:37:47 PDT 2010

On Wed, 2010-04-28 at 22:56 +0200, Michel Marti wrote:
> On 04/28/2010 09:03 PM, Dan Williams wrote:
> > On Wed, 2010-04-28 at 17:36 +0200, Michel Marti wrote:
> >> Later on:
> >> 1272466857.040626: 0: 00:18:39:d4:63:a4 ssid='4YEO' wpa_ie_len=28 rsn_ie_len=24 caps=0x11
> >> 1272466857.040711:    skip - blacklisted
> >> What could be the reason for the blacklisting of the AP?
> >
> > A number of reasons:
> <...snip...>
> > 3) authentication to the AP timed out.  This looks like:
> >
> > Authentication with 00:22:33:44:d9:28 timed out.
> >
> >
> > I'd guess your issue is case #1.  Can you provide more of the logs?
> The log indicates that the AP gets banned due to an authentication 
> timeout - which raises the next question: who's causing the timeout (AP 
> or client)?

Probably a driver bug.  The supplicant requests that the driver auth to
the AP, and the driver does not report successful auth in the time
allowed.  This is almost always a driver bug, though it could also be
misconfiguration on either side of the air.

> Also, do I understand this correctly, that when an AP gets blacklisted, 
> the supplicant will not try reassociating with it until there are no 
> other suitable Access Points left?

Correct. Since the AP was reported as unusable by the driver (it could
not be contacted or successfully authenticated with) then the supplicant
won't use that AP until it has no other choice.  That's reasonable; if
you can't connect to an AP, why would that connection work 10 seconds
from now?

In the end, if there are driver bugs, those  bugs should be fixed
instead of hacking up the supplicant to work around them.

I'd also suggest you try using the ath5k driver and see if that works
better for you?  madwifi is a dead-end for most use-cases as ath5k and
ath9k is the preferred upstream driver for that hardware, and Atheros is
actively involved in both drivers, but not in madwifi.

More below...

> 1272466627.774847: WPA: Key negotiation completed with 00:18:39:d4:63:a4 
> [PTK=CCMP GTK=TKIP]
> 1272466627.774959: Cancelling authentication timeout
> 1272466627.775176: Removed BSSID 00:18:39:d4:63:a4 from blacklist
> 1272466627.775262: State: GROUP_HANDSHAKE -> COMPLETED
> 1272466627.775377: CTRL-EVENT-CONNECTED - Connection to 
> 00:18:39:d4:63:a4 completed (reauth) [id=0 id_str=]
> 1272466627.775452: wpa_driver_wext_set_operstate: operstate 0->1 (UP)
> 1272466627.775696: netlink: Operstate: linkmode=-1, operstate=6
> 1272466627.776171: EAPOL: External notification - portValid=1
> 1272466627.776287: EAPOL: External notification - EAP success=1
> 1272466627.776351: EAPOL: SUPP_PAE entering state AUTHENTICATING
> 1272466627.776411: EAPOL: SUPP_BE entering state SUCCESS
> 1272466627.776469: EAP: EAP entering state DISABLED
> 1272466627.776525: EAPOL: SUPP_PAE entering state AUTHENTICATED
> 1272466627.776580: EAPOL: Supplicant port status: Authorized
> 1272466627.776642: EAPOL: SUPP_BE entering state IDLE
> 1272466627.776703: EAPOL authentication completed successfully
> 1272466627.776875: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 
> ([UP][RUNNING][LOWER_UP])
> 1272466627.776990: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
> 1272466629.259555: EAPOL: startWhen --> 0
> 1272466629.259670: EAPOL: disable timer tick
> 1272466629.992468: RTM_NEWLINK: operstate=1 ifi_flags=0x1043 ([UP][RUNNING])
> 1272466629.992604: Wireless event: cmd=0x8b15 len=20
> 1272466629.992664: Wireless event: new AP: 00:00:00:00:00:00

Here's a problem.  Why did the driver drop the connection?  It was
successfully connected 2 seconds ago (1272466627.775377) and now it
signals that it's lost sync or been disconnected with from the AP.  For
this you'd need to enable driver debugging.

This sort of thing does sometimes just happen, but it's usually
indicative of a buggy driver if it happens this quickly after a
successful connection.

> 1272466629.992740: Disassociation notification
> 1272466629.992844: Setting scan request: 0 sec 100000 usec
> 1272466629.992936: Added BSSID 00:18:39:d4:63:a4 into blacklist
> 1272466629.993059: CTRL-EVENT-DISCONNECTED bssid=00:18:39:d4:63:a4 reason=0
> 1272466629.993124: Disconnect event - remove keys
> 1272466629.993185: wpa_driver_madwifi_del_key: keyidx=0
> 1272466630.004008: wpa_driver_madwifi_del_key: keyidx=1
> 1272466630.004168: wpa_driver_madwifi_del_key: keyidx=2
> 1272466630.004282: wpa_driver_madwifi_del_key: keyidx=3
> 1272466630.004391: wpa_driver_madwifi_del_key: keyidx=0
> 1272466630.004504: State: COMPLETED -> DISCONNECTED
> 1272466630.004584: wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT)
> 1272466630.004657: netlink: Operstate: linkmode=-1, operstate=5
> 1272466630.004796: EAPOL: External notification - portEnabled=0
> 1272466630.004883: EAPOL: SUPP_PAE entering state DISCONNECTED
> 1272466630.004940: EAPOL: Supplicant port status: Unauthorized
> 1272466630.005001: EAPOL: SUPP_BE entering state INITIALIZE
> 1272466630.005069: EAPOL: Supplicant port status: Unauthorized
> 1272466630.005137: EAPOL: External notification - portValid=0
> 1272466630.005202: EAPOL: Supplicant port status: Unauthorized
> 1272466630.005266: EAPOL: External notification - EAP success=0
> 1272466630.005327: EAPOL: Supplicant port status: Unauthorized
> 1272466630.005435: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
> 1272466630.005533: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
> 1272466630.095529: State: DISCONNECTED -> SCANNING
> 1272466630.095646: Starting AP scan for wildcard SSID
> 1272466630.096219: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
> 1272466630.096348: Wireless event: cmd=0x8b1a len=8
> 1272466637.491592: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
> 1272466637.491727: Wireless event: cmd=0x8b19 len=8
> 1272466637.492180: Received 1727 bytes of scan results (8 BSSes)
> 1272466637.492326: BSS: Start scan result update 69
> 1272466637.492447: New scan results available
> 1272466637.492569: RSN: Ignored PMKID candidate without preauth flag
> 1272466637.492653: Selecting BSS from priority group 0
> 1272466637.492712: Try to find WPA-enabled AP
> 1272466637.492766: 0: 00:18:39:d4:63:a4 ssid='4YEO' wpa_ie_len=28 
> rsn_ie_len=24 caps=0x11
> 1272466637.492861:    selected based on RSN IE
> 1272466637.492923:    selected WPA AP 00:18:39:d4:63:a4 ssid='4YEO'
> 1272466637.493068: Trying to associate with 00:18:39:d4:63:a4 
> (SSID='4YEO' freq=2462 MHz)

Good, we found the AP that we just got disconnected from and are trying
to reconnect to it.

> 1272466637.493156: FT: Stored MDIE and FTIE from (Re)Association 
> Response - hexdump(len=0):
> 1272466637.493253: Cancelling scan request
> 1272466637.493324: WPA: clearing own WPA/RSN IE
> 1272466637.493383: Automatic auth_alg selection: 0x1
> 1272466637.493478: RSN: using IEEE 802.11i/D9.0
> 1272466637.493553: WPA: Selected cipher suites: group 8 pairwise 24 
> key_mgmt 2 proto 2
> 1272466637.493631: WPA: set AP WPA IE - hexdump(len=30): dd 1c 00 50 f2 
> 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 00 00
> 1272466637.493812: WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 
> 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 00 00
> 1272466637.493993: WPA: using GTK TKIP
> 1272466637.494070: WPA: using PTK CCMP
> 1272466637.494146: WPA: using KEY_MGMT WPA-PSK
> 1272466637.494222: WPA: Set own WPA IE default - hexdump(len=22): 30 14 
> 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
> 1272466637.494383: No keys have been configured - skip key clearing
> 1272466637.494446: State: SCANNING -> ASSOCIATING
> 1272466637.494504: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
> 1272466637.494574: netlink: Operstate: linkmode=-1, operstate=5
> 1272466637.494717: wpa_driver_madwifi_associate
> ioctl[IEEE80211_IOCTL_SETMLME]: Invalid argument
> 1272466637.496026: wpa_driver_madwifi_associate: SETMLME[ASSOC] failed
> 1272466637.496153: Association request to the driver failed

This does indicate a driver bug.  It appears the madwifi supplicant
driver uses this command to tell the kernel driver to associate to the
AP, and this operation has just failed for some reason that only the
driver knows.  So it's not surprising that the association does not
succeed.

You now get to enable driver debugging to figure out why that request to
the driver fails.

Dan