Re: [Orinoco-devel] Agere PCMCIA sometimes takes very long time to associate with 9.48 FW

[Andrey Borzenkov <arvidjaar@mail.ru>]

[-- Attachment #1: Type: text/plain, Size: 3399 bytes --]

On Monday 17 November 2008, Dave wrote:

> > Looking at wpa_supplicant log intersting part is
> > 
> > Wireless event: cmd=0x8c07 len=32
> > AssocReq IE wireless event - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
> > RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
> > RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
> > Wireless event: cmd=0x8b15 len=20
> > Wireless event: new AP: 00:60:b3:ca:91:b0
> > Association info event
> > req_ies - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
> > WPA: set own WPA/RSN IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
> > State: ASSOCIATING -> ASSOCIATED
> > wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
> > WEXT: Operstate: linkmode=-1, operstate=5
> > Associated to a new BSS: BSSID=44:44:44:44:44:44
> 
> > in other words, wpa_drv_get_bssid() returns 44:... BSSID. I could not find
> > any place in kernel or wpa_supplicant that would set it, so I can only assume
> > that firmware returns it for watever reason.
> 
> It is a firmware value, but I don't know what the it means. I know
> hostap checks for it in hostap_main:prism2_sta_deauth.
> 

In some place wpa_supplicant is using this to mark invalid BSSID; I
do not think it leaks it into the driver now though.

And it is value that is use by Hermes to indicate invalid BSSID. It is even
documents in iwconfig.c :)

/*
 * Display an Wireless Access Point Socket Address in readable format.
 * Note : 0x44 is an accident of history, that's what the Orinoco/PrismII
 * chipset report, and the driver doesn't filter it.
 */

Anyway I now have Yet Another Theory that actually fits quite well into
what I have seen in wpa_supplicant logs and explains 44:... BSSID as well.

Mandriva is using approximately the following sequence to start wireless:

ifconfig eth1 up
iwconfig eth1 whatever-is-set-for-it
wpa_supplicant eth1

Now I had these parameters for eth1:

### WIRELESS_MODE=Managed
### WIRELESS_ESSID="Home, sweet home"
WIRELESS_WPA_DRIVER=wext
### WIRELESS_POWER=on
### WIRELESS_SENS=3

Notice WIRELESS_ESSID. So what happened was apparently this

iwcofnig eth1 ESSID
                      driver starts associating
wpa_supplicant starts
                      driver associated and send IWEVASSOCREQIE
wpa_supplicant calls SIOCSIWESSID  |
         +-------------------------+
         |
         |            driver *again* starts associating
        /
wpa_supplicant receives SIOCSIWESSID
wpa_supplicant calls SIOCGIWAP
                      at this point driver has not yet
                        completed *second* association
                        so it returns invalid BSSID
                        (44:44:44:44:44:44)


So it looks like user space issue after all. There is little driver can
do (except returning "officially blessed" indication for invalid BSSID).
As it is now, wpa_supplicant does not seem to check for invalid BSSID
from SIOCGIWAP in wpa_supplicant_event_assoc() at all. It enters quite a
long retry loop using invalid value until it finally decides to trigger
association again.

It also explains why nobody was able to reproduce it - it is really
quite unique timing issue. Any change in scheduling could have "fixed" it.

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 197 bytes --]