2009-11-09 13:54:39

by Holger Schurig

[permalink] [raw]
Subject: still trouble with reassoc

Okay, now I can -- indivdually -- associate fine to both APs.


And so I'll associate to one AP, sitting on my desk:

1257770236.175400: 0: 00:13:19:80:da:30 ssid='MNWPA' wpa_ie_len=24 rsn_ie_len=0 caps=0x11
1257770236.175463: selected based on WPA IE
1257770236.175502: selected WPA AP 00:13:19:80:da:30 ssid='MNWPA'
1257770236.175552: Automatic auth_alg selection: 0x1
1257770236.175604: WPA: using IEEE 802.11i/D3.0
1257770236.175644: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 1
...
1257770236.189320: Associated to a new BSS: BSSID=00:13:19:80:da:30


Fine. Now I remove the antenna from this AP and do a "wpa_cli scan"
command. That makes the signal of a farther positioned AP become
larger. And yes, wpa_supplicant now selects this other AP:

1257770250.708767: RX ctrl_iface - hexdump_ascii(len=4):
53 43 41 4e SCAN
...
1257770251.247515: 0: 00:1b:d4:44:35:90 ssid='MNWPA' wpa_ie_len=24 rsn_ie_len=0 caps=0x11
1257770251.247565: selected based on WPA IE
1257770251.247603: selected WPA AP 00:1b:d4:44:35:90 ssid='MNWPA'
1257770251.247647: Automatic auth_alg selection: 0x1
1257770251.247692: WPA: using IEEE 802.11i/D3.0
1257770251.247731: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 1
...

And now the fun begins: wpa_supplicant/mac80211 can still
authenticate, but no longer associate.



Here's the authenticate:

1257770251.248107: Trying to authenticate with 00:1b:d4:44:35:90 (SSID='MNWPA' freq=2462 MHz)
1257770251.248147: nl_set_encr: ifindex=11 alg=0 addr=0x808bb61 key_idx=0 set_tx=0 seq_len=0 key_len=0
1257770251.248270: nl_set_encr: ifindex=11 alg=0 addr=0x808bb61 key_idx=1 set_tx=0 seq_len=0 key_len=0
1257770251.248389: nl_set_encr: ifindex=11 alg=0 addr=0x808bb61 key_idx=2 set_tx=0 seq_len=0 key_len=0
1257770251.249000: nl_set_encr: ifindex=11 alg=0 addr=0x808bb61 key_idx=3 set_tx=0 seq_len=0 key_len=0
1257770251.249123: nl_set_encr: ifindex=11 alg=0 addr=0x9b9698c key_idx=0 set_tx=0 seq_len=0 key_len=0
1257770251.249176: addr=00:1b:d4:44:35:90
1257770251.249284: State: COMPLETED -> AUTHENTICATING
1257770251.249329: EAPOL: External notification - EAP success=0
1257770251.249371: EAPOL: External notification - EAP fail=0
1257770251.249411: EAPOL: External notification - portControl=Auto
1257770251.249455: nl80211: Authenticate (ifindex=11)
1257770251.249496: * bssid=00:1b:d4:44:35:90
1257770251.249538: * freq=2462
1257770251.249577: * SSID - hexdump_ascii(len=5):
4d 4e 57 50 41 MNWPA
1257770251.249661: * IEs - hexdump(len=0): [NULL]
1257770251.249700: * Auth Type 0
1257770251.249821: nl80211: Authentication request send successfully
1257770251.249880: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1257770251.249926: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1257770251.359252: nl80211: Event message available
1257770251.359330: nl80211: MLME event 37
1257770251.359373: SME: Authentication response: peer=00:1b:d4:44:35:90 auth_type=0 status_code=0


And here's the failing associate:

1257770251.359427: Trying to associate with 00:1b:d4:44:35:90 (SSID='MNWPA' freq=2462 MHz)
1257770251.359526: State: AUTHENTICATING -> ASSOCIATING
1257770251.359567: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
1257770251.359609: nl80211: Operstate: linkmode=-1, operstate=5
1257770251.360243: nl80211: Associate (ifindex=11)
1257770251.360289: * bssid=00:1b:d4:44:35:90
1257770251.360331: * freq=2462
1257770251.360369: * SSID - hexdump_ascii(len=5):
4d 4e 57 50 41 MNWPA
1257770251.360454: * 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
1257770251.360822: nl80211: MLME command failed: ret=-16 (Device or resource busy)
1257770251.360873: Association request to the driver failed
1257770251.360953: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1257770251.360999: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1257770253.751447: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1257770253.751502: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1257770253.752595: nl80211: Event message available
1257770253.752667: nl80211: MLME event 39
1257770253.752710: Added BSSID 00:1b:d4:44:35:90 into blacklist



All of this looks like this from "ie event":

wlan0 (phy #8): scan started
wlan0 (phy #8): scan finished: 2437 2462, "MNWPA" ""
wlan0 (phy #8): auth 00:13:19:80:da:30 -> 00:15:e9:84:1a:54 status: 0: Successful
wlan0 (phy #8): assoc 00:13:19:80:da:30 -> 00:15:e9:84:1a:54 status: 0: Successful
wlan0 (phy #8): connected to 00:13:19:80:da:30
wlan0 (phy #8): scan started
wlan0 (phy #8): scan finished: 2437 2462, "MNWPA" ""
wlan0 (phy #8): auth 00:1b:d4:44:35:90 -> 00:15:e9:84:1a:54 status: 0: Successful
wlan0 (phy #8): deauth 00:15:e9:84:1a:54 -> 00:13:19:80:da:30 reason 4: Disassociated due to inactivity
wlan0 (phy #8): disconnected (local request)

"iw wlan link" shows me:

Authenticated with 00:1b:d4:44:35:90 (on wlan0)
Not connected.



And after this, the situation stays like this. Even worse, when I now
run "iw wlan0 scan", I still see on "iw event" and on wpa_supplicant's
output that a scan has been triggered, but the "iw wlan0 scan" command
won't return, not even after 10 seconds (it should, the card is an
802.11b only card).

When I now Ctrl-C the "iw wlan0 scan" command, and do again an
"wpa_cli scan" command, I see an additional error message:

1257770806.464542: RX ctrl_iface - hexdump_ascii(len=4):
53 43 41 4e SCAN
1257770806.464651: Setting scan request: 0 sec 0 usec
1257770806.464748: State: DISCONNECTED -> SCANNING
1257770806.464791: Scan SSID - hexdump_ascii(len=5):
4d 4e 57 50 41 MNWPA
1257770806.464876: Starting AP scan for wildcard SSID
1257770806.465024: nl80211: Scan trigger failed: ret=-16 (Device or resource busy)
1257770806.465071: Failed to initiate AP scan.

And now wpa_supplicant starts to try to scan by itself every ten
seconds ... it didn't do this before.


I fear that I have to fight with not only one state-machine :-)

--
http://www.holgerschurig.de


2009-11-09 14:44:49

by Holger Schurig

[permalink] [raw]
Subject: Re: still trouble with reassoc

Okay, I changed wpa_supplicant a bit:

In events.c, wpa_supplicant_connect(), I changed the code like this:

if (wpa_s->reassociate ||
(os_memcmp(selected->bssid, wpa_s->bssid, ETH_ALEN) != 0 &&
(wpa_s->wpa_state != WPA_ASSOCIATING ||
os_memcmp(selected->bssid, wpa_s->pending_bssid, ETH_ALEN) !=
0))) {
if (wpa_supplicant_scard_init(wpa_s, ssid)) {
wpa_supplicant_req_new_scan(wpa_s, 10);
return;
}
+ wpa_supplicant_deauthenticate(wpa_s,
+ WLAN_REASON_DEAUTH_LEAVING);
wpa_supplicant_associate(wpa_s, selected, ssid);
} else {

But I'm not sure if this is the right position. Maybe
wpa_supplicant_associate() should do it based on wpa_s->state?

> --
> http://www.holgerschurig.de