madwifi(cvs), wpa_supp v0.2.5 and linksys router problem

Jouni Malinen jkmaline at cc.hut.fi
Sat Nov 27 20:24:58 EST 2004


On Fri, Nov 26, 2004 at 02:19:28PM +0100, Andreas Schuldei wrote:

> ok, here are some logs with debugging in the madwifi driver
> activated (by echo 1 > /proc/sys/dev/ath0/debug)

Thanks. This is starting to point towards being something to do with the
driver and not wpa_supplicant, so I cc'ed madwifi-devel mailing list
which is probably a more suitable forum for this question.


Summary:

WPA key handshake completes successfully, ar521x generates beacon miss
interrupt after about 90 seconds, scans fail for some reason during
following couple of minutes.

In other words, it is the client driver that decides that the connection
is down. It is unclear to me why this is happening, though. One
explanation would be that the AP and client get out of sync with
beacons, but that should not really happen since the client is supposed
to do time sync based on the beacon frames in the first place..
Alternatively, the AP could have indeed stopped sending beacons which
should be obvious if you can run a wireless sniffer to capture what
packets are being sent.

If the AP is still up, but the client just misses couple of beacons, I
would prefer the driver to try a bit harder before reporting this as a
lost connection. I haven't looked into madwifi code to see how many
beacons need to be missed. Anyway, I would at least try to probe the AP
first (e.g., send ProbeReq for its BSSID) and only report disconnection
if no reply is received.


Details:

Here's the driver debug for association:

Nov 26 13:47:07 localhost kernel: NODS
00:05:4e:4a:47:44->00:0f:66:45:e2:ad(00:0f:66:45:e2:ad) auth 1M
Nov 26 13:47:07 localhost kernel:  b000 3a01 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 0000 0000 0100 0000
Nov 26 13:47:07 localhost kernel: NODS
00:05:4e:4a:47:44->00:0f:66:45:e2:ad(00:0f:66:45:e2:ad) assoc_req 1M
Nov 26 13:47:07 localhost kernel:  0000 3a01 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 1000 3104 6400 000c 4163 6365 7373 5f50 6f69 6e74
0108 8284 8b0c 1296 1824 3204 3048 606c dd16 0050 f201 0100 0050 f202
0100 0050 f204 0100 0050 f202
Nov 26 13:47:07 localhost kernel: ath_tx_start:
link[3](edf9c86c)=2df9c898 (edf9c898)

This triggered association event to wpa_supplicant:

Wireless event: cmd=0x8b1a len=25
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:0f:66:45:e2:ad
Association event - clear replay counter
Associated to a new BSS: BSSID=00:0f:66:45:e2:ad

Followed by RX of msg 1/4

WPA: RX message 1 of 4-Way Handshake from 00:0f:66:45:e2:ad (ver=2)

and reply msg 2/4:

WPA: Sending EAPOL-Key 2/4
WPA: TX EAPOL-Key 2/4 - hexdump(len=137): 00 0f 66 45 e2 ad 00 05 4e 4a
47 44 88 8e 01 03 00 77 fe 01 0a 00 10 00 00 00 00 00 00 00 00 12 7c 68
7c d0 e6 d0 c2 be e0 15 eb 30 f2 72 d6 7d f4 f9 42 aa 05 6d 23 82 66 cd
fa a0 9b 16 4b 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 17 9a 49 c1 f5 59 be 16 6f c9 a3
d5 b8 53 2e 9c 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2
04 01 00 00 50 f2 02

in the driver:

Nov 26 13:47:07 localhost kernel: TODS
00:05:4e:4a:47:44->00:0f:66:45:e2:ad(00:0f:66:45:e2:ad) data 36M
Nov 26 13:47:07 localhost kernel:  0801 2c00 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 2000 aaaa 0300 0000 888e 0103 0077 fe01 0a00 1000
0000 0000 0000 0012 7c68 7cd0 e6d0 c2be e015 eb30 f272 d67d f4f9 42aa
056d 2382 66cd faa0 9b16 4b00 0000 0000 0000 0000 0000 0000 0000 0000
0000 0000 0000 0000 0000 0000 0000 0017 9a49 c1f5 59be 166f c9a3 d5b8
532e 9c00 18dd 1600 50f2 0101 0000 50f2 0201 0000 50f2 0401 0000 50f2 02

followed by msg 3/4

WPA: RX message 3 of 4-Way Handshake from 00:0f:66:45:e2:ad (ver=2)

and reply, msg 4/4

WPA: Sending EAPOL-Key 4/4
WPA: TX EAPOL-Key 4/4 - hexdump(len=113): 00 0f 66 45 e2 ad 00 05 4e 4a
47 44 88 8e 01 03 00 5f fe 01 0a 00 10 00 00 00 00 00 00 00 01 12 7c 68
7c d0 e6 d0 c2 be e0 15 eb 30 f2 72 d6 7d f4 f9 42 aa 05 6d 23 82 66 cd
fa a0 9b 16 4b 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 e6 35 f0 27 f8 b2 9a c5 0b 17 a6
cb df af d0 e8 00 00

Nov 26 13:47:07 localhost kernel: ath_tx_start: Q1: 00000000 37f8d830
013c009f 0000009b 22240000 000db92d
Nov 26 13:47:07 localhost kernel: TODS
00:05:4e:4a:47:44->00:0f:66:45:e2:ad(00:0f:66:45:e2:ad) data 36M
Nov 26 13:47:07 localhost kernel:  0801 2c00 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 3000 aaaa 0300 0000 888e 0103 005f fe01 0a00 1000
0000 0000 0000 0112 7c68 7cd0 e6d0 c2be e015 eb30 f272 d67d f4f9 42aa
056d 2382 66cd faa0 9b16 4b00 0000 0000 0000 0000 0000 0000 0000 0000
0000 0000 0000 0000 0000 0000 0000 00e6 35f0 27f8 b29a c50b 17a6 cbdf
afd0 e800 00

keys configured

RX msg 1/2 (encrypted)

Reply:

WPA: Sending EAPOL-Key 2/2
WPA: TX EAPOL-Key 2/2 - hexdump(len=113): 00 0f 66 45 e2 ad 00 05 4e 4a
47 44 88 8e 01 03 00 5f fe 03 12 00 20 00 00 00 00 00 00 00 02 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 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 b5 87 22 4c 6b 01 a7 bf 71 5b 9e
e8 51 48 1e 43 00 00

Nov 26 13:47:07 localhost kernel:  0841 2c00 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 4000 0100 0020 0000 0000 aaaa 0300 0000 888e 0103
005f fe03 1200 2000 0000 0000 0000 0200 0000 0000 0000 0000 0000 0000
0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000
0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 00b5 8722 4c6b
01a7 bf71 5b9e e851 481e 4300 00
Nov 26 13:47:07 localhost kernel: ath_tx_start: Q1: 00000000 019e6e28
413c0097 0000008b 22240000 000db92d
Nov 26 13:47:07 localhost kernel: ath_tx_start:
link[1](edf9c8f0)=2df9c91c (edf9c91c)


At this point, connection is up and everything is done as far as
wpa_supplicant is concerned:

WPA: Key negotiation completed with 00:0f:66:45:e2:ad
Cancelling authentication timeout

Next things happening is driver reporting that the hardware reported
beacon miss:

Nov 26 13:48:41 localhost kernel: ath_bmiss_tasklet
Nov 26 13:48:41 localhost kernel: NODS
00:05:4e:4a:47:44->00:0f:66:45:e2:ad(00:0f:66:45:e2:ad) assoc_req 1M
Nov 26 13:48:41 localhost kernel:  0000 3a01 000f 6645 e2ad 0005 4e4a
4744 000f 6645 e2ad 5000 1104 6400 000c 4163 6365 7373 5f50 6f69 6e74
0108 0204 0b0c 1216 1824 3204 3048 606c dd16 0050 f201 0100 0050 f202
0100 0050 f204 0100 0050 f202

I don't know what that assoc_req is; maybe the driver tries to associate
back with the AP in case of beacon miss

This beacon miss is reported to wpa_supplicant as disconnect event:

Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
Disconnect event - remove keys

This triggers wpa_supplicant to start scanning. madwifi debug shows lots
of probe_req being sent, but all the scan results are empty (0 BSSes).
It seems to take minutes before getting real scan results. After this,
the same process seems to be repeated; this time with 128 seconds of
connection uptime before getting ath_bmiss_tasklet.

-- 
Jouni Malinen                                            PGP id EFC895FA



More information about the HostAP mailing list