Please note: This project is no longer active. The website is kept online for historic purposes only.
If you´re looking for a Linux driver for your Atheros WLAN device, you should continue here .

Ticket #942 (new defect)

Opened 16 years ago

Last modified 15 years ago

immidiate disconnection on scan request (using wpa_supplicant)

Reported by: marek Assigned to:
Priority: major Milestone:
Component: madwifi: driver Version:
Keywords: Cc:
Patch is attached: 0 Pending:

Description

I'm using madwifi 0.9.2 (although i have also tried latest snapshot 1747) With wpa_supplicant (0.4.9, 0.5.4 and 0.5.5). everything works fine in unencrypted mode, however when i try to use WPA or WPA2, the connection is broken just after its completed. Below is the output of wpa_supplicant -dd -i ath0: 

...
State: GROUP_HANDSHAKE -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:0e:2e:90:50:34 completed (reauth) [id=0 id_str=]
WEXT: Operstate: linkmode=-1, operstate=6
EAPOL: External notification - portValid=1
EAPOL: External notification - EAP success=1
EAPOL: SUPP_PAE entering state AUTHENTICATING
EAPOL: SUPP_BE entering state SUCCESS
EAP: EAP entering state DISABLED
EAPOL: SUPP_PAE entering state AUTHENTICATED
EAPOL: SUPP_BE entering state IDLE
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
EAPOL: startWhen --> 0
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
Setting scan request: 0 sec 100000 usec
Added BSSID 00:0e:2e:90:50:34 into blacklist
State: COMPLETED -> DISCONNECTED

as you can see, it connects to the AP, but then after producing "Setting scan request..." almost instantly the connection is terminated.

i have found some info in track about race conditions related to scanning but as far as i understand, they were supposed to be solved in 0.9.2, thats why i decided to fill in this bug.

Please let me know if i could be of any assistance - maybe supplying additional debug info or so.

cheers, marek

Change History

10/10/06 16:08:40 changed by anonymous

I have the same problem since the new hal in r1711. However r1710 works fine.

10/10/06 17:05:18 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

Hmm, r1742 on PC, linux 2.6.18/2.6.19-rc1, wpasupplicant 0.5.5/cvs snapshot works here just fine. No races whatsoever - scans, authenticates WPA-PSK(TKIP/TKIP, CCMP/TKIP, CCMP/CCMP) just fine. Hmm, don't know if this is related to any changes. :\

10/10/06 17:12:03 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

What kind of AP (vendor) are you using ? It looks like AP is kicking client out , reason unknown. It might be MIC failures (on AP side), AP failed to setup keys (???) - result client is kicked. :\ I think you could try enabling debugging on client and look for mgmt frames to find out the reason.

10/10/06 20:56:57 changed by Marek

My AP is another linux box with Atheros and madwifi-ng drivers :) actually its madwifi-ng-0.9.2 with hostapd 0.4.9. the AP is working fine with windows client. i'll try r1710 tomorrow and will let you know

10/10/06 23:25:04 changed by Marek

just checked r1710, but this one fails even earlier - during the 4-way handshake phase, additionaly supplying various strange messages. It complains about PSK, but the key IS right, as it is the same key (and same wpa_supplicant.conf that has been used with previous version and sucesful connection). Still however there seem to be an issue with scanning (AP blacklisted just after scan started) 

...
State: ASSOCIATED -> 4WAY_HANDSHAKE
WPA: RX message 1 of 4-Way Handshake from 00:0e:2e:90:50:34 (ver=1)
RSN: msg 1/4 key data - hexdump(len=0):
WPA: Renewed SNonce - hexdump(len=32): 9d 72 f5 08 61 08 cb df 5d 7d 2a 1d 17 1c 77 32 47 41 60 f4 fd 9b 7a b7 76 60 2c ad eb 4a d6 1a
WPA: PMK - hexdump(len=32): [REMOVED]
WPA: PTK - hexdump(len=64): [REMOVED]
WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 02 01 00 00 0f ac 02 00 00
WPA: Sending EAPOL-Key 2/4
WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 09 00 00 00 00 00 00 00 00 00 02 9d 72 f5 08 61 08 cb df 5d 7d 2a 1d 17 1c 77 32 47 41 60 f4 fd 9b 7a b7 76 60 2c ad eb 4a d6 1a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ed 43 d9 7a 6d cd 52 ea 18 b5 53 1b b9 4b d7 29 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac 02 01 00 00 0f ac 02 00 00
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
WPA: 4-Way Handshake failed - pre-shared key may be incorrect
Setting scan request: 0 sec 100000 usec
BSSID 00:0e:2e:90:50:34 blacklist count incremented to 2
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
State: 4WAY_HANDSHAKE -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: SUPP_BE entering state INITIALIZE
EAPOL: External notification - portValid=0
EAPOL: External notification - EAP success=0
RTM_NEWLINK: operstate=0 ifi_flags=0x1002 ()
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
l2_packet_receive - recvfrom: Network is down
State: DISCONNECTED -> SCANNING
Starting AP scan (broadcast SSID)
Trying to get current scan results first without requesting a new scan to speed up initial association
ioctl[SIOCGIWSCAN]: No such device
Scan results: -1
Failed to get scan results
Failed to get scan results - try scanning again
Setting scan request: 0 sec 0 usec
RTM_DELLINK, IFLA_IFNAME: Interface 'ath0' removed
Configured interface was removed.
State: SCANNING -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
EAPOL: External notification - EAP success=0
State: DISCONNECTED -> SCANNING
Starting AP scan (broadcast SSID)
ioctl[SIOCSIWSCAN]: No such device
Failed to initiate AP scan.
Setting scan request: 10 sec 0 usec
Ignore event for foreign ifindex 215
RTM_DELLINK, IFLA_IFNAME: Interface 'wifi0' removed
Ignore event for foreign ifindex 217
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 217
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 217
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
Ignore event for foreign ifindex 218
EAPOL: startWhen --> 0
RTM_DELLINK, IFLA_IFNAME: Interface 'ath0' removed
Configured interface was removed.
State: SCANNING -> DISCONNECTED

10/11/06 16:53:37 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

I see 

RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
WPA: 4-Way Handshake failed - pre-shared key may be incorrect
Setting scan request: 0 sec 100000 usec

According source code I think that AP is sending EVENT_DISASSOC. So wpasupplicant is saying that although 4x way handshake went through, I've got disassoc. Not much to do about this - as I told previously AP doesn't like the station (client) for some reason. Anything in host ap logs ? As to why does it send dissassoc event to station (client) ?

10/11/06 16:56:03 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

Do you have any process in background that does ifconfig ath0 down/up ? 

l2_packet_receive - recvfrom: Network is down
                              ^^^^^^^^^^^^^^^ ?????
State: DISCONNECTED -> SCANNING
Starting AP scan (broadcast SSID)
Trying to get current scan results first without requesting a new scan to speed up initial association
ioctl[SIOCGIWSCAN]: No such device
Scan results: -1

10/11/06 19:44:15 changed by Marek

Whoa! I got to the root of the problem...

Thanks Zilvinas for drawing my attention to the AP :) Although it still seems to be some race condition there.

The box with AP is running debian, and i have following lines in /etc/network/interfaces: 

iface ath0 inet static
        pre-up          wlanconfig ath0 create wlandev wifi0 wlanmode ap
        post-up         iwconfig ath0 channel 1; hostapd -B /etc/hostapd.conf
        pre-down        killall hostapd
        post-down       wlanconfig ath0 destroy

now, when i ran hostapd manually from command line, everythink worked. This was a surprise. So i addded "sleep 1" before running hostapd: 

        post-up         iwconfig ath0 channel 1; sleep 1; hostapd -B /etc/hostapd.conf

and voila! Everything works now... Seems like hostapd can't be run immidiately after change of the channel (maybe some other commands are affected as well)

i'll test it for a few more days and will let you know if this keeps running ;)

10/18/06 10:31:29 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

Hello Marek,

Good work, glad you have solved your problem.

Too pity though if wireless mode and ieee mode are set to zero (means auto?), on ifconfig ath0 madwifi-ng drivers are doing "background" scan, to find least used channel or so. It seems the problem is here that driver doesn't like to receive any ioctl(2) during scans or so (strace hostapd - perhaps that will show which ioctl(2) is killing the driver). I am not sure. Just a guess. 

hostapd -B /etc/hostapd.conf 

remove 1s delay and change to 

strace -o/tmp/hostap.log hostapd -B /etc/hostapd.conf

Although that might be too late, system might be already under panic and you will not see the content of /tmp/hostap.log. That could tell a lot if I could see the strace output.

10/18/06 10:35:22 changed by Žilvinas Valinskas <valins@soften.ktu.lt>

Marek, please ignore - nothing is crashing in your setup ;) I am/was chasing problems the #914 ... which is different story. *sighs*

11/04/06 15:42:17 changed by Marek

Well, seem this issue doesnt want to let go... the setup worked for a week, then started to break again - i experience disconnections at various intervals. I have set up an open access AP with no daemon running: 

iface ath0 inet static
        pre-up          wlanconfig ath0 create wlandev wifi0 wlanmode ap
        post-down       wlanconfig ath0 destroy
        address         10.0.1.1
        netmask         255.255.255.0
        wireless-mode   master
        wireless-channel 7
        wireless-essid  myssid

yet, when i try to connect to this AP with wpa_supplicant from another machine (both AP and client are using atheros/madwifi), i receive; 

...
Wireless event: cmd=0x8b1a len=17
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:0e:2e:90:50:34
State: ASSOCIATING -> ASSOCIATED
Associated to a new BSS: BSSID=00:0e:2e:90:50:34
Associated with 00:0e:2e:90:50:34
WPA: Association event - clear replay counter
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state S_FORCE_AUTH
EAPOL: SUPP_BE entering state IDLE
Cancelling authentication timeout
Removed BSSID 00:0e:2e:90:50:34 from blacklist
State: ASSOCIATED -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:0e:2e:90:50:34 completed (reauth)
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added

<<< and then after some time... >>>

Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
Setting scan request: 0 sec 100000 usec
Added BSSID 00:0e:2e:90:50:34 into blacklist
State: COMPLETED -> DISCONNECTED
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: SUPP_BE entering state INITIALIZE
EAPOL: External notification - portValid=0
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added
State: DISCONNECTED -> SCANNING

apparently it receives the new AP event with zeroed MAC (disconnection) but this must come from the madwifi driver, as like i said there is no daemon (like hostapd) running on the AP

i have tried various snapshots of madwifi-ng on the AP (including todays), but with no luck. any thoughts about how to find out the core of the problem? For the start, how to find out if this is really AP sending disconnection event or somehow the client genrates it on its own?

any help will be really aprreciated

12/08/06 14:39:09 changed by anonymous

Was there ever a solution put forward for this?

12/27/06 17:14:41 changed by Marek Zachara

None i'm aware of. I have reported this last issue as a separate ticket #1004