Steps to reproduce:
network={
ssid="MNHS"
key_mgmt=NONE
proto=RSN
key_mgmt=WPA-PSK
pairwise=CCMP
group=CCMP
psk="99999999"
scan_freq=2412
}
network={
ssid="MNFUNK"
key_mgmt=NONE
wep_key0="99999"
scan_freq=2412
}
Also two APs, MNHS/WPA2 and MNFUNK/WEP.
Current wireless-testing from GIT + patch "cfg80211: don't
overwrite privacy setting"
Current wpa_supplicant from GIT.
Command: ./wpa_supplicant -i eth1 -D nl80211 -t -c mnhs.conf -d
First, it associates to the MNHS-AP:
...
1253526128.147011: selected based on RSN IE
1253526128.147024: selected WPA AP 00:13:19:80:da:30 ssid='MNHS'
...
1253526128.436265: Associated to a new BSS: BSSID=00:13:19:80:da:30
1253526128.436280: No keys have been configured - skip key clearing
1253526128.436297: Associated with 00:13:19:80:da:30
...
1253526128.470149: CTRL-EVENT-CONNECTED - Connection to 00:13:19:80:da:30 completed (auth) [id=0 id_str=]
...
Fine so far.
Next I turn of the AP where I'm associated to. wpa_supplicant
successfully associates to the WEP-based AP:
...
1253526139.247356: Setting scan request: 0 sec 100000 usec
1253526139.247373: Added BSSID 00:13:19:80:da:30 into blacklist
...
1253526139.727196: selected non-WPA AP 00:1b:53:11:dc:40 ssid='MNFUNK'
...
1253526140.025300: Associated to a new BSS: BSSID=00:1b:53:11:dc:40
1253526140.025320: Associated with 00:1b:53:11:dc:40
...
1253526140.025654: CTRL-EVENT-CONNECTED - Connection to 00:1b:53:11:dc:40 completed (reauth) [id=1 id_str=]
...
Now I turn on again the MNHS AP. And then I issue a scan
from the cmdline: "iw eth1 scan trigger freq 2412"
And now it's getting interesting:
...
1253526175.739000: Received scan results (3 BSSes)
...
1253526175.739064: 0: 00:13:19:80:da:30 ssid='MNHS' wpa_ie_len=0 rsn_ie_len=20 caps=0x11
1253526175.739087: selected based on RSN IE
1253526175.739098: selected WPA AP 00:13:19:80:da:30 ssid='MNHS'
1253526175.739115: Automatic auth_alg selection: 0x1
1253526175.739133: RSN: using IEEE 802.11i/D9.0
1253526175.739144: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
1253526175.739160: WPA: clearing AP WPA IE
1253526175.739171: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 28 00
1253526175.739206: WPA: using GTK CCMP
1253526175.739219: WPA: using PTK CCMP
1253526175.739231: WPA: using KEY_MGMT WPA-PSK
1253526175.739243: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1253526175.739280: Cancelling scan request
1253526175.739298: Trying to authenticate with 00:13:19:80:da:30 (SSID='MNHS' freq=2412 MHz)
1253526175.739312: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=0 set_tx=0 seq_len=0 key_len=0
1253526175.739370: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=1 set_tx=0 seq_len=0 key_len=0
1253526175.739420: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=2 set_tx=0 seq_len=0 key_len=0
1253526175.739466: nl_set_encr: ifindex=34 alg=0 addr=0x8092a8e key_idx=3 set_tx=0 seq_len=0 key_len=0
1253526175.739512: nl_set_encr: ifindex=34 alg=0 addr=0x84e1b34 key_idx=0 set_tx=0 seq_len=0 key_len=0
1253526175.739537: addr=00:13:19:80:da:30
1253526175.739575: State: COMPLETED -> AUTHENTICATING
1253526175.739593: EAPOL: External notification - EAP success=0
1253526175.739609: EAPOL: External notification - EAP fail=0
1253526175.739622: EAPOL: External notification - portControl=Auto
1253526175.739634: EAPOL: SUPP_PAE entering state DISCONNECTED
1253526175.739646: EAPOL: Supplicant port status: Unauthorized
1253526175.739713: EAPOL: SUPP_BE entering state INITIALIZE
1253526175.739732: EAPOL: SUPP_PAE entering state CONNECTING
1253526175.739744: EAPOL: enable timer tick
1253526175.739757: EAPOL: SUPP_BE entering state IDLE
1253526175.739773: nl80211: Authenticate (ifindex=34)
1253526175.739787: * bssid=00:13:19:80:da:30
1253526175.739802: * freq=2412
1253526175.739813: * SSID - hexdump_ascii(len=4):
4d 4e 48 53 MNHS
1253526175.739845: * IEs - hexdump(len=0): [NULL]
1253526175.739858: * Auth Type 0
1253526175.739899: nl80211: Authentication request send successfully
1253526175.739918: RSN: Ignored PMKID candidate without preauth flag
1253526175.739936: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1253526175.739954: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253526175.954553: nl80211: Event message available
1253526175.954592: nl80211: MLME event 37
1253526175.954608: SME: Authentication response: peer=00:13:19:80:da:30 auth_type=0 status_code=0
1253526175.954635: Trying to associate with 00:13:19:80:da:30 (SSID='MNHS' freq=2412 MHz)
1253526175.954649: State: AUTHENTICATING -> ASSOCIATING
1253526175.954662: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
1253526175.954677: nl80211: Operstate: linkmode=-1, operstate=5
1253526175.955294: nl80211: Associate (ifindex=34)
1253526175.955312: * bssid=00:13:19:80:da:30
1253526175.955327: * freq=2412
1253526175.955338: * SSID - hexdump_ascii(len=4):
4d 4e 48 53 MNHS
1253526175.955370: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1253526175.955456: nl80211: MLME command failed: ret=-114 (Operation already in progress)
1253526175.955479: Association request to the driver failed
1253526175.955512: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1253526175.955530: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
1253526178.742658: EAPOL: startWhen --> 0
1253526178.742678: EAPOL: disable timer tick
1253526178.742690: EAPOL: SUPP_PAE entering state CONNECTING
1253526178.742701: EAPOL: enable timer tick
1253526178.742714: EAPOL: txStart
1253526178.742725: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
1253526208.774009: EAPOL: startWhen --> 0
1253526208.774043: EAPOL: disable timer tick
1253526208.774055: EAPOL: SUPP_PAE entering state CONNECTING
1253526208.774066: EAPOL: enable timer tick
1253526208.774079: EAPOL: txStart
1253526208.774090: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
1253526238.805764: EAPOL: startWhen --> 0
1253526238.805790: EAPOL: disable timer tick
1253526238.805802: EAPOL: SUPP_PAE entering state CONNECTING
1253526238.805814: EAPOL: enable timer tick
1253526238.805827: EAPOL: txStart
1253526238.805838: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
1253526268.837109: EAPOL: startWhen --> 0
1253526268.837130: EAPOL: disable timer tick
1253526268.837143: EAPOL: SUPP_PAE entering state HELD
1253526268.837154: EAPOL: enable timer tick
1253526268.837166: EAPOL: Supplicant port status: Unauthorized
1253526268.837296: EAPOL authentication completed unsuccessfully
1253526268.837322: Setting authentication timeout: 2 sec 0 usec
1253526270.838400: Authentication with 00:13:19:80:da:30 timed out.
1253526270.838421: BSSID 00:13:19:80:da:30 blacklist count incremented to 2
1253526270.838440: No keys have been configured - skip key clearing
1253526270.838453: State: ASSOCIATING -> DISCONNECTED
1253526270.838466: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
1253526270.838481: nl80211: Operstate: linkmode=-1, operstate=5
1253526270.838506: EAPOL: External notification - portEnabled=0
1253526270.838520: EAPOL: SUPP_PAE entering state DISCONNECTED
1253526270.838532: EAPOL: Supplicant port status: Unauthorized
1253526270.838600: EAPOL: SUPP_BE entering state INITIALIZE
1253526270.838619: EAPOL: Supplicant port status: Unauthorized
1253526270.838679: EAPOL: External notification - portValid=0
1253526270.838697: EAPOL: Supplicant port status: Unauthorized
1253526270.838755: EAPOL: External notification - EAP success=0
1253526270.838772: EAPOL: Supplicant port status: Unauthorized
1253526270.838837: Setting scan request: 0 sec 0 usec
1253526270.838867: EAPOL: Supplicant port status: Unauthorized
1253526270.838936: State: DISCONNECTED -> SCANNING
1253526270.838959: Starting AP scan for wildcard SSID
1253526270.839130: Scan requested (ret=0) - scan timeout 30 seconds
1253526270.839165: nl80211: Event message available
1253526270.839193: nl80211: Ignored unknown event (cmd=33)
1253526271.839909: EAPOL: Supplicant port status: Unauthorized
1253526272.840948: EAPOL: Supplicant port status: Unauthorized
1253526273.841988: EAPOL: Supplicant port status: Unauthorized
1253526274.843028: EAPOL: Supplicant port status: Unauthorized
1253526275.844068: EAPOL: Supplicant port status: Unauthorized
1253526276.845110: EAPOL: Supplicant port status: Unauthorized
1253526277.846150: EAPOL: Supplicant port status: Unauthorized
1253526278.847174: EAPOL: Supplicant port status: Unauthorized
1253526279.848214: EAPOL: Supplicant port status: Unauthorized
1253526280.849255: EAPOL: Supplicant port status: Unauthorized
1253526281.850294: EAPOL: Supplicant port status: Unauthorized
1253526282.851334: EAPOL: Supplicant port status: Unauthorized
1253526283.852374: EAPOL: Supplicant port status: Unauthorized
1253526284.853414: EAPOL: Supplicant port status: Unauthorized
1253526285.854454: EAPOL: Supplicant port status: Unauthorized
1253526286.855495: EAPOL: Supplicant port status: Unauthorized
1253526287.856534: EAPOL: Supplicant port status: Unauthorized
1253526288.857574: EAPOL: Supplicant port status: Unauthorized
1253526289.858613: EAPOL: Supplicant port status: Unauthorized
1253526290.859653: EAPOL: Supplicant port status: Unauthorized
1253526291.860693: EAPOL: Supplicant port status: Unauthorized
1253526292.861733: EAPOL: Supplicant port status: Unauthorized
1253526293.862773: EAPOL: Supplicant port status: Unauthorized
1253526294.863813: EAPOL: Supplicant port status: Unauthorized
1253526295.864853: EAPOL: Supplicant port status: Unauthorized
... AD INIFINITUM ...
--
http://www.holgerschurig.de
On Tue, 2009-09-22 at 11:23 +0200, Holger Schurig wrote:
> Maybe some state isn't clear at the implicit "ifdown XXX down"
> that wpa_supplicant does when terminating?
The SSID is kept and then re-applied during ifup, so that would cause a
scan, but shouldn't cause any timeouts.
johannes
> script -c "./wpa_supplicant -i eth1 -D wext -t -c mnfunk.conf -d" 1
> Wait till "ping" works
Ctrl-C
> script -c "./wpa_supplicant -i eth1 -D wext -t -c mnfunk.conf -d" 2
I cannot reproduce this anymore, dunny why.
--
http://www.holgerschurig.de
Another thing that might be related:
Start with freshly loaded modules (ath5k, mac80211, ath, cfg80211).
script -c "./wpa_supplicant -i eth1 -D wext -t -c mnfunk.conf -d" 1
Wait till "ping" works
script -c "./wpa_supplicant -i eth1 -D wext -t -c mnfunk.conf -d" 2
On the second try, it takes 15 seconds till
I'm connected and ping works again.
Maybe some state isn't clear at the implicit "ifdown XXX down"
that wpa_supplicant does when terminating?
--
http://www.holgerschurig.de
Johannes asked me off-list for dmesg output:
> First, it associates to the MNHS-AP:
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=112)
eth1: associate
> Next I turn of the AP where I'm associated to. wpa_supplicant
> successfully associates to the WEP-based AP:
eth1: deauthenticated from 00:13:19:80:da:30 (Reason: 1)
eth1: direct probe to AP 00:1b:53:11:dc:40 (try 1)
eth1 direct probe responded
eth1: authenticate with AP 00:1b:53:11:dc:40 (try 1)
eth1: authenticated
eth1: associate with AP 00:1b:53:11:dc:40 (try 1)
eth1: RX AssocResp from 00:1b:53:11:dc:40 (capab=0x11 status=0
aid=91)
eth1: associated
> Now I turn on again the MNHS AP. And then I issue a scan
> from the cmdline: "iw eth1 scan trigger freq 2412"
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
Also the output of "iw eth1 info":
iw eth1 link
Connected to 00:1b:53:11:dc:40 (on eth1)
SSID: MNFUNK
freq: 2412
Authenticated with 00:13:19:80:da:30 (on eth1)
RX: 78173 bytes (722 packets)
TX: 144 bytes (4 packets)
signal: -67 dBm
tx bitrate: 11.0 MBit/s
If I understand this right, then mac80211 thinks it's connected,
even before the 4-way key exchange?
--
http://www.holgerschurig.de
On Mon, 2009-09-21 at 17:22 +0200, Holger Schurig wrote:
> iw eth1 link
> Connected to 00:1b:53:11:dc:40 (on eth1)
> SSID: MNFUNK
> freq: 2412
> Authenticated with 00:13:19:80:da:30 (on eth1)
> RX: 78173 bytes (722 packets)
> TX: 144 bytes (4 packets)
> signal: -67 dBm
> tx bitrate: 11.0 MBit/s
This is very odd, I'll look into it.
> If I understand this right, then mac80211 thinks it's connected,
> even before the 4-way key exchange?
Umm, it is supposed to think so.
johannes
On Thu, 2009-09-24 at 09:20 +0200, Johannes Berg wrote:
> On Mon, 2009-09-21 at 17:22 +0200, Holger Schurig wrote:
>
> > iw eth1 link
> > Connected to 00:1b:53:11:dc:40 (on eth1)
> > SSID: MNFUNK
> > freq: 2412
> > Authenticated with 00:13:19:80:da:30 (on eth1)
> > RX: 78173 bytes (722 packets)
> > TX: 144 bytes (4 packets)
> > signal: -67 dBm
> > tx bitrate: 11.0 MBit/s
>
> This is very odd, I'll look into it.
Actually, it's not odd. It looks like wpa_supplicant never
deauthenticated, since :30 was the AP you connected to _first_.
I suspect it'll all work better if you make wpa_supplicant deauth
instead of disassoc.
johannes