Dropped packet causing 1 second delay in 4-way handshake

[Robert Borger]

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
bborger at navcorp.com