The following is an indication about yet another MLME problem:
Two APs, both set to the MNHS/WPA.
Let wpa_supplicant associate. Turn one AP off. wpa_supplicant
automatically associates to the second.
Now turn the first AP on again. Issue a manual scan command:
1253527140.577702: nl80211: Event message available
1253527140.577751: nl80211: Ignored unknown event (cmd=33)
1253527140.794448: nl80211: Event message available
1253527140.794490: nl80211: New scan results available
1253527140.794921: Received scan results (3 BSSes)
1253527140.794947: CTRL-EVENT-SCAN-RESULTS
1253527140.794960: Selecting BSS from priority group 0
1253527140.794972: Try to find WPA-enabled AP
1253527140.794984: 0: 00:13:19:80:da:30 ssid='MNWPA' wpa_ie_len=24 rsn_ie_len=0 caps=0x11
1253527140.795007: selected based on WPA IE
1253527140.795018: selected WPA AP 00:13:19:80:da:30 ssid='MNWPA'
1253527140.795035: Automatic auth_alg selection: 0x1
1253527140.795052: WPA: using IEEE 802.11i/D3.0
1253527140.795063: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 1
1253527140.795079: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 28 00
1253527140.795117: WPA: clearing AP RSN IE
1253527140.795129: WPA: using GTK TKIP
1253527140.795141: WPA: using PTK TKIP
1253527140.795154: WPA: using KEY_MGMT WPA-PSK
1253527140.795165: WPA: Set own WPA IE default - 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
1253527140.795203: Cancelling scan request
1253527140.795221: Trying to authenticate with 00:13:19:80:da:30 (SSID='MNWPA' freq=2412 MHz)
1253527140.795234: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=0 set_tx=0 seq_len=0 key_len=0
1253527140.795286: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=1 set_tx=0 seq_len=0 key_len=0
1253527140.795341: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=2 set_tx=0 seq_len=0 key_len=0
1253527140.795389: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=3 set_tx=0 seq_len=0 key_len=0
1253527140.795435: nl_set_encr: ifindex=34 alg=0 addr=0x91ce96c key_idx=0 set_tx=0 seq_len=0 key_len=0
1253527140.795460: addr=00:13:19:80:da:30
1253527140.795498: State: COMPLETED -> AUTHENTICATING
1253527140.795515: EAPOL: External notification - EAP success=0
1253527140.795530: EAPOL: External notification - EAP fail=0
1253527140.795542: EAPOL: External notification - portControl=Auto
1253527140.795559: nl80211: Authenticate (ifindex=34)
1253527140.795572: * bssid=00:13:19:80:da:30
1253527140.795587: * freq=2412
1253527140.795598: * SSID - hexdump_ascii(len=5):
4d 4e 57 50 41 MNWPA
1253527140.795630: * IEs - hexdump(len=0): [NULL]
1253527140.795643: * Auth Type 0
1253527140.795683: nl80211: Authentication request send successfully
1253527140.795707: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1253527140.795725: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253527140.953161: nl80211: Event message available
1253527140.953200: nl80211: MLME event 37
1253527140.953216: SME: Authentication response: peer=00:13:19:80:da:30 auth_type=0 status_code=0
1253527140.953243: Trying to associate with 00:13:19:80:da:30 (SSID='MNWPA' freq=2412 MHz)
1253527140.953257: State: AUTHENTICATING -> ASSOCIATING
1253527140.953270: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
1253527140.953284: nl80211: Operstate: linkmode=-1, operstate=5
1253527140.953901: nl80211: Associate (ifindex=34)
1253527140.953919: * bssid=00:13:19:80:da:30
1253527140.953934: * freq=2412
1253527140.953945: * SSID - hexdump_ascii(len=5):
4d 4e 57 50 41 MNWPA
1253527140.953977: * 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
1253527140.954064: nl80211: MLME command failed: ret=-114 (Operation already in progress)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
1253527140.954086: Association request to the driver failed
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
1253527140.954113: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1253527140.954131: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
The "Association request to the driver failed" will
be shown even without "-d". Also note that the association
seems to actually work, e.g. I can ping throught the
connection.
--
http://www.holgerschurig.de
Hmm, this seems to be racy. This morning I succeeded 3 times to
get that message, now I didn't on the first try. But now I
enabled verbose-mac80211-debugging ...
But on the second try, I succeeded again.
> Let wpa_supplicant associate.
phy10: Selected rate control algorithm 'minstrel'
ath5k phy10: Atheros AR5213A chip found (MAC: 0x59, PHY: 0x43)
ath5k phy10: RF2112B 2GHz radio found (0x46)
eth1: direct probe to AP 00:13:19:80:da:30 (try 1)
eth1 direct probe responded
eth1: authenticate with AP 00:13:19:80:da:30 (try 1)
eth1: authenticated
eth1: associate with AP 00:13:19:80:da:30 (try 1)
eth1: RX AssocResp from 00:13:19:80:da:30 (capab=0x11 status=0
aid=114)
eth1: associated
> Turn one AP off. wpa_supplicant automatically associates to the
> second.
eth1: deauthenticated from 00:13:19:80:da:30 (Reason: 1)
eth1: direct probe to AP 00:13:19:80:da:30 (try 1)
eth1: direct probe to AP 00:13:19:80:da:30 (try 2)
eth1: direct probe to AP 00:13:19:80:da:30 (try 3)
eth1: direct probe to AP 00:13:19:80:da:30 timed out
eth1: direct probe to AP 00:1b:d4:44:35:90 (try 1)
eth1 direct probe responded
eth1: authenticate with AP 00:1b:d4:44:35:90 (try 1)
eth1: authenticated
eth1: associate with AP 00:1b:d4:44:35:90 (try 1)
eth1: RX AssocResp from 00:1b:d4:44:35:90 (capab=0x11 status=0
aid=127)
eth1: associated
Side node: here mac80211 had stale scan data in the cache, thus
wpa_supplicant first asked it to authenticate to the
just-turned-off AP. You can see the three probes ...
> Now turn the first AP on again. Issue a manual scan command
eth1: direct probe to AP 00:13:19:80:da:30 (try 1)
eth1 direct probe responded
eth1: authenticate with AP 00:13:19:80:da:30 (try 1)
eth1: authenticate with AP 00:13:19:80:da:30 (try 2)
eth1: authenticated
--
http://www.holgerschurig.de
On Mon, 2009-10-12 at 10:15 +0300, Jouni Malinen wrote:
> Though, even in this case, there is actually a bug somewhere (in
> mac80211, I would assume).. The authentication attempt with the second
> AP times out because mac80211 ends up sending the direct probes to the
> MAC address of the old AP (which is now turned off). When wpa_supplicant
> tries to authenticate again, the direct probes are going to the correct
> destination and connection can be established.
I can't see that happen in mac80211 -- can somebody run this with some
printks in cfg80211 that tell us what exactly is being passed down to
mac80211's auth() call?
> I can reproduce this with the current wpa_supplicant (that has a
> workaround for this EALREADY for authentication case, but not for
> assoc) and the current wireless-testing. Roaming will get mac80211 into
> very odd state..
>
> Not only is this association failing (after the authentication with the
> same AP actually worked), but the scanning state will also get quite
> confused.. The next scan trigger after this is never completed (iw scan
> gets stuck). Or well, actually, once I wait long enough for the AP to
> deauthenticate the client, it looks like mac80211 can recover. The scan
> command returned after five minutes of waiting.. ;-)
Good hint. It looks like it gets stuck between assoc and auth for the
old AP?
> > The "Association request to the driver failed" will
> > be shown even without "-d". Also note that the association
> > seems to actually work, e.g. I can ping throught the
> > connection.
>
> mac80211 remains associated with the old AP (I think) and somehow
> remains in the state between authentication and association (with the
> new AP) which will block scans.
I think we need a cfg80211 event tracer :)
Actually, does wpa_supplicant _deauth_ from the AP, or does it just
disassoc? It's definitely supposed to deauth.
johannes
On Mon, Sep 21, 2009 at 01:09:40PM +0200, Holger Schurig wrote:
> The following is an indication about yet another MLME problem:
>
> Two APs, both set to the MNHS/WPA.
>
> Let wpa_supplicant associate. Turn one AP off. wpa_supplicant
> automatically associates to the second.
Though, even in this case, there is actually a bug somewhere (in
mac80211, I would assume).. The authentication attempt with the second
AP times out because mac80211 ends up sending the direct probes to the
MAC address of the old AP (which is now turned off). When wpa_supplicant
tries to authenticate again, the direct probes are going to the correct
destination and connection can be established.
> Now turn the first AP on again. Issue a manual scan command:
..
> 1253527140.953161: nl80211: Event message available
> 1253527140.953200: nl80211: MLME event 37
> 1253527140.953216: SME: Authentication response: peer=00:13:19:80:da:30 auth_type=0 status_code=0
> 1253527140.953243: Trying to associate with 00:13:19:80:da:30 (SSID='MNWPA' freq=2412 MHz)
> 1253527140.953257: State: AUTHENTICATING -> ASSOCIATING
> 1253527140.953270: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
> 1253527140.953284: nl80211: Operstate: linkmode=-1, operstate=5
> 1253527140.953901: nl80211: Associate (ifindex=34)
> 1253527140.953919: * bssid=00:13:19:80:da:30
> 1253527140.953934: * freq=2412
> 1253527140.953945: * SSID - hexdump_ascii(len=5):
> 4d 4e 57 50 41 MNWPA
> 1253527140.953977: * 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
> 1253527140.954064: nl80211: MLME command failed: ret=-114 (Operation already in progress)
> 1253527140.954086: Association request to the driver failed
I can reproduce this with the current wpa_supplicant (that has a
workaround for this EALREADY for authentication case, but not for
assoc) and the current wireless-testing. Roaming will get mac80211 into
very odd state..
Not only is this association failing (after the authentication with the
same AP actually worked), but the scanning state will also get quite
confused.. The next scan trigger after this is never completed (iw scan
gets stuck). Or well, actually, once I wait long enough for the AP to
deauthenticate the client, it looks like mac80211 can recover. The scan
command returned after five minutes of waiting.. ;-)
> The "Association request to the driver failed" will
> be shown even without "-d". Also note that the association
> seems to actually work, e.g. I can ping throught the
> connection.
mac80211 remains associated with the old AP (I think) and somehow
remains in the state between authentication and association (with the
new AP) which will block scans.
--
Jouni Malinen PGP id EFC895FA
Sorry to warm this up ...
> 1253527140.795498: State: COMPLETED -> AUTHENTICATING
> 1253527140.795515: EAPOL: External notification - EAP success=0
> 1253527140.795530: EAPOL: External notification - EAP fail=0
> 1253527140.795542: EAPOL: External notification - portControl=Auto
> 1253527140.795559: nl80211: Authenticate (ifindex=34)
> 1253527140.795572: * bssid=00:13:19:80:da:30
> 1253527140.795587: * freq=2412
> 1253527140.795598: * SSID - hexdump_ascii(len=5):
> 4d 4e 57 50 41 MNWPA
> 1253527140.795630: * IEs - hexdump(len=0): [NULL]
> 1253527140.795643: * Auth Type 0
> 1253527140.795683: nl80211: Authentication request send successfully
> 1253527140.795707: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
> 1253527140.795725: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
> 1253527140.953161: nl80211: Event message available
> 1253527140.953200: nl80211: MLME event 37
> 1253527140.953216: SME: Authentication response: peer=00:13:19:80:da:30 auth_type=0 status_code=0
> 1253527140.953243: Trying to associate with 00:13:19:80:da:30 (SSID='MNWPA' freq=2412 MHz)
> 1253527140.953257: State: AUTHENTICATING -> ASSOCIATING
> 1253527140.953270: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
> 1253527140.953284: nl80211: Operstate: linkmode=-1, operstate=5
> 1253527140.953901: nl80211: Associate (ifindex=34)
> 1253527140.953919: * bssid=00:13:19:80:da:30
> 1253527140.953934: * freq=2412
> 1253527140.953945: * SSID - hexdump_ascii(len=5):
> 4d 4e 57 50 41 MNWPA
> 1253527140.953977: * 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
> 1253527140.954064: nl80211: MLME command failed: ret=-114 (Operation already in progress)
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> 1253527140.954086: Association request to the driver failed
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> 1253527140.954113: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
> 1253527140.954131: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
>
>
> The "Association request to the driver failed" will
> be shown even without "-d". Also note that the association
> seems to actually work, e.g. I can ping throught the
> connection.
Could this be related to the problem Maxim has been seeing? I'm not sure
how else this could happen since you seem to auth but then assoc doesn't
work, but I can't see how that could possibly happen.
johannes
Sorry to warm this up ...
> 1253527140.795498: State: COMPLETED -> AUTHENTICATING
> 1253527140.795515: EAPOL: External notification - EAP success=0
> 1253527140.795530: EAPOL: External notification - EAP fail=0
> 1253527140.795542: EAPOL: External notification - portControl=Auto
> 1253527140.795559: nl80211: Authenticate (ifindex=34)
> 1253527140.795572: * bssid=00:13:19:80:da:30
> 1253527140.795587: * freq=2412
> 1253527140.795598: * SSID - hexdump_ascii(len=5):
> 4d 4e 57 50 41 MNWPA
> 1253527140.795630: * IEs - hexdump(len=0): [NULL]
> 1253527140.795643: * Auth Type 0
> 1253527140.795683: nl80211: Authentication request send successfully
> 1253527140.795707: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
> 1253527140.795725: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
> 1253527140.953161: nl80211: Event message available
> 1253527140.953200: nl80211: MLME event 37
> 1253527140.953216: SME: Authentication response: peer=00:13:19:80:da:30 auth_type=0 status_code=0
> 1253527140.953243: Trying to associate with 00:13:19:80:da:30 (SSID='MNWPA' freq=2412 MHz)
> 1253527140.953257: State: AUTHENTICATING -> ASSOCIATING
> 1253527140.953270: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
> 1253527140.953284: nl80211: Operstate: linkmode=-1, operstate=5
> 1253527140.953901: nl80211: Associate (ifindex=34)
> 1253527140.953919: * bssid=00:13:19:80:da:30
> 1253527140.953934: * freq=2412
> 1253527140.953945: * SSID - hexdump_ascii(len=5):
> 4d 4e 57 50 41 MNWPA
> 1253527140.953977: * 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
> 1253527140.954064: nl80211: MLME command failed: ret=-114 (Operation already in progress)
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> 1253527140.954086: Association request to the driver failed
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> 1253527140.954113: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
> 1253527140.954131: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
>
>
> The "Association request to the driver failed" will
> be shown even without "-d". Also note that the association
> seems to actually work, e.g. I can ping throught the
> connection.
Could this be related to the problem Maxim has been seeing? I'm not sure
how else this could happen since you seem to auth but then assoc doesn't
work, but I can't see how that could possibly happen.
johannes