Dropped packet causing 1 second delay in 4-way handshake

Hello,

I am using wpa_supplicant-0.5.7 with madwifi-0.9.2.1.  My
test setup has 4
access points and one client.  All are configured for WPA2.
Two of the
access points are capable of preauthorization.  My
configuration file has 5
networks defined, all using the same SSID.  Four of the
networks have BSSID
defined to limit connection to a specific access point.  The
fifth network
is not restrained to a specific MAC address.  When I use the
command
"wpa_cli select_network 4" to select one of the
preauthorized access points
the system switches access points after just the 4 handshake
messages. There
is a 1 second delay in this process that I would like to
eliminate.  When
the access point sends the first handshake message,
wpa_supplicant processes
it and generates the response. I have followed this response
message to the
sendto call in l2_packet_send() in l2_packet_linux.c. This
message doesn't
lease the machine, but sendto returns the byte count not an
error code.
After about one second, the access point resends the first
handshake message
and the handshake completes without any further delay.  I
monitor the
network traffic with tcpdump and see the handshake messages
just as
described.  Switching to the other preauthorized AP results
in the same 1
second delay and re-transmission of handshake message number
one.  Switching
to one of the non-preauthorized APs is very slow due to the
interaction with
the RADIUS server. I would like to determine why the
handshake message
number 2 is dropped and am open to suggestions.

I've added some printf lines to the source so that I can
follow the process
better.  The ones that I added do not have a time stamp. 
This is from the
log showing the processing of message 1 and the generation
of response
message 2.  The last line is the AP resending message 1,
about 1 second
after the original message.

1176913024.451588: State: ASSOCIATED -> 4WAY_HANDSHAKE
1176913024.451597: WPA: RX message 1 of 4-Way Handshake
from
00:13:10:45:5e:d7 (ver=2)
1176913024.451612: RSN: msg 1/4 key data - hexdump(len=22):
dd 14 00 0f ac
04 eb 26 03 8c 05 ad 63 f8 db d7 da ac 21 62 0c a8
1176913024.451652: RSN: PMKID from Authenticator -
hexdump(len=16): eb 26 03
8c 05 ad 63 f8 db d7 da ac 21 62 0c a8
1176913024.451682: RSN: matched PMKID - hexdump(len=16): eb
26 03 8c 05 ad
63 f8 db d7 da ac 21 62 0c a8
1176913024.451713: RSN: PMK from PMKSA cache -
hexdump(len=32): [REMOVED]
1176913024.457810: WPA: Renewed SNonce - hexdump(len=32): 7d
7a 6d 3d 62 93
13 94 96 e1 43 b7 cb 4c 9e 0e 11 df 3a 88 46 b1 cb 5b 6d 29
e3 21 61 37 65
ce
1176913024.457936: WPA: PMK - hexdump(len=32): [REMOVED]
1176913024.457946: WPA: PTK - hexdump(len=64): [REMOVED]
1176913024.457956: WPA: WPA IE for msg 2/4 -
hexdump(len=40): 30 26 01 00 00
0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00 01 00 eb
26 03 8c 05 ad
63 f8 db d7 da ac 21 62 0c a8
1176913024.458025: WPA: Sending EAPOL-Key 2/4
bb-weks: Call to wpa_eapol_key_send
bb-weks: sm=0x8089960 kck=0x80899c4 ver=2 dest=0x8089aa8
bb-weks: proto=34958 msg=0x80a3700 msg_len=139
key_mic=0x80a3751
1176913024.458063: WPA: TX EAPOL-Key - hexdump(len=139): 01
03 00 87 02 01
0a 00 00 00 00 00 00 00 00 00 08 7d 7a 6d 3d 62 93 13 94 96
e1 43 b7 cb 4c
9e 0e 11 df 3a 88 46 b1 cb 5b 6d 29 e3 21 61 37 65 ce 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
81 32 f8 9d 12 08 87 68 2c f2 67 8a b3 38 ec 57 00 28 30 26
01 00 00 0f ac
04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00 01 00 eb 26 03
8c 05 ad 63 f8
db d7 da ac 21 62 0c a8
bb-wes: Call to wpa_ether_send
bb-wes: Calling l2_packet_send
bb-weks: wpa_sm_ether_send returned: 139
bb_weks: frame count 1: 9 msg: 0x80a3700
bb_weks: frame count 2: 10 msg: 0x80a3700
Call to wpa_driver_wext_event_rtm_newlink
1176913025.194097: RTM_NEWLINK: operstate=0 ifi_flags=0x1043
([UP][RUNNING])
Call to wpa_driver_wext_event_link
1176913025.194119: RTM_NEWLINK, IFLA_IFNAME: Interface
'ath0' added
1176913025.427123: RX EAPOL from 00:13:10:45:5e:d7

Robert Borger
Navigation Corporation
740 Spirit 40 Park Drive 
Chesterfield, MO 63005
636-530-6046 x1004
bborgernavcorp.com
_______________________________________________
HostAP mailing list
HostAPshmoo.com
http:/
/lists.shmoo.com/mailman/listinfo/hostap

On Wed, Apr 18, 2007 at 05:06:15PM -0500, Robert Borger
wrote:

> is not restrained to a specific MAC address.  When I
use the command
> "wpa_cli select_network 4" to select one of
the preauthorized access points
> the system switches access points after just the 4
handshake messages. There
> is a 1 second delay in this process that I would like
to eliminate.  When
> the access point sends the first handshake message,
wpa_supplicant processes
> it and generates the response. I have followed this
response message to the
> sendto call in l2_packet_send() in l2_packet_linux.c.
This message doesn't
> lease the machine, but sendto returns the byte count
not an error code.

As far as wpa_supplicant is concerned, that message was sent
out
correctly, so this sounds like a driver and/or network stack
issue..
Have you used a wireless sniffer to verify that the message
is not sent?
I would recommend enabling some debug information in the
driver to show
transmitted packets. There could be some kind of race
condition in the
driver that ends up dropping the first outgoing packet which
is sent
more or less immediately after the association has been
completed.

> 1176913024.458025: WPA: Sending EAPOL-Key 2/4
> bb-weks: Call to wpa_eapol_key_send
> bb-weks: sm=0x8089960 kck=0x80899c4 ver=2
dest=0x8089aa8
> bb-weks: proto=34958 msg=0x80a3700 msg_len=139
key_mic=0x80a3751

This looks like a successfully completed sendto() operation,
so I don't
see any problems here from wpa_supplicant view point.. If it
is able to
receive a frame, it should be able to send one, but
something in kernel
is dropping it in this case.

-- 
Jouni Malinen                                            PGP
id EFC895FA
_______________________________________________
HostAP mailing list
HostAPshmoo.com
http:/
/lists.shmoo.com/mailman/listinfo/hostap