wpa-supplicant v0.7.2 stops roaming after a while

Wed Apr 28 13:56:00 PDT 2010

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)?

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?

- Michel

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
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)
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
1272466637.496245: Setting authentication timeout: 5 sec 0 usec
1272466637.496335: EAPOL: External notification - EAP success=0
1272466637.496411: EAPOL: Supplicant port status: Unauthorized
1272466637.496487: EAPOL: External notification - EAP fail=0
1272466637.496550: EAPOL: Supplicant port status: Unauthorized
1272466637.496617: EAPOL: External notification - portControl=Auto
1272466637.496680: EAPOL: Supplicant port status: Unauthorized
1272466637.496797: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1272466637.496890: Wireless event: cmd=0x8b1a len=12
1272466642.499346: Authentication with 00:18:39:d4:63:a4 timed out.
1272466642.499455: BSSID 00:18:39:d4:63:a4 blacklist count incremented to 2