madwifi WPA

Thu Jul 8 05:08:43 PDT 2004

I sent this message yesterday, but it's still waiting in the moderation queue,
so I'm splitting it off from the attachments and sending again. There will be 
another email with just the attachments. Apologies if you get this twice.

Jouni wrote:
> > Either the AP does not receive the 2/2 message from the client (e.g.,
> > because of decryption failing) or it does not like something in the
> > message. If possible, I would like to see some debug/event log
> > information from the AP. If not possible, I would at least need to know
> > which AP this was (vendor, model, firmware version).
>
I wrote:
> This is a Cisco AP1200, with IOS version 12.2(15)JA. I'll enable some
> debugging on the AP today and have a look. It may take some unraveling, as
> the authentication is handled by a different AP than the one I'm
> associating to (with Cisco's Wireless Domain Services), but I may disable
> that for now.
>

I ran some debugs on ?sucessful auths with the hostap driver, and also with 
madwifi. I have debugs on the authenticating AP 
(again, not the same as the associating AP), and a few also on the associating 
AP. Looking at the EAP logs on the authenticating AP, they are exactly the 
same for both clients, as far as I can tell, except for the madwifi auth 
repeating itself. 
Looking at the associating AP, I think I may have found something interesting:
Here is an excerpt from the debug on the AP, at this point the EAP auth has been successful and they key handshake is about to take place.

Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75875: Jul ?7 18:09:34.358: dot11_mgr_disp_wlccp_receive: Received DOT11_AAA_SUCCESS from Remote Authenticator
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75876: Jul ?7 18:09:34.358: dot11_mgr_sm_run_machine: Executing Action(BRIDGE,AUTHENTICATOR_PASS) for 0040.96a1.bc2f
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75877: Jul ?7 18:09:34.358: dot11_mgr_disp_wlccp_ap_send_pre_reg: sending pre reg request 0040.96a1.bc2f, reassoc 0
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75878: Jul ?7 18:09:34.358: wlccp_ap_mn: Pre Reg Req: Association for 0040.96a1.bc2f
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75879: Jul ?7 18:09:34.358: wlccp_ap_mn: Pre Reg Req: sent ksc 1 *
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75880: Jul ?7 18:09:34.359: wlccp_ap_mn: Pre Reg Req: bssid 000c.8560.f1f1 key type 1
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75881: Jul ?7 18:09:34.359: wlccp_ap_mn: Pre Reg Req: ssid ornlwpa
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75882: Jul ?7 18:09:34.359: wlccp_ap_mn: Pre Reg Req: sent msc 3C *
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75883: Jul ?7 18:09:34.359: dot11_mgr_sm_send_pre_reg_req: Sent pre_reg request 0040.96a1.bc2f to authenticator
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75884: Jul ?7 18:09:34.366: wlccp_ap_mn: PreReg Reply: eap_server_type 25
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75885: Jul ?7 18:09:34.366: wlccp_ap_mn: ap_proc_prereg_reply assoc for 0040.96a1.bc2f
Jul ?7 14:09:34 apcsb-4.ens.ornl.gov 75886: Jul ?7 18:09:34.367: wlccp_ap_mn: PreReg Reply: got MSC 3D *
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75887: Jul ?7 18:09:34.367: dot11_mgr_disp_wlccp_process_pre_reg_resp: found nsk (btk), len 32
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75888: Jul ?7 18:09:34.367: dot11_mgr_disp_wlccp_process_pre_reg_resp: found auth key, len 32
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75889: Jul ?7 18:09:34.367: dot11_mgr_sm_run_machine: Executing Action(PRE_REG,PRE_REG_PASS) for 0040.96a1.bc2f
---------------> here's PTK msg 1
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75890: Jul ?7 18:09:34.367: dot11_dot1x_build_ptk_handshake: building PTK msg 1 for 0040.96a1.bc2f
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75891: Jul ?7 18:09:35.548: dot11_mgr_disp_client_send_eapol: sending eapol to client 0040.96a1.bc2f
Jul ?7 14:09:35 apcsb-4.ens.ornl.gov 75892: Jul ?7 18:09:35.548: dot11_mgr_sm_send_ptk_msg1: [1] Sent PTK msg 1 to 0040.96a1.bc2f
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75893: Jul ?7 18:09:36.327: dot11_mgr_sm_parse_client_pak: Received EAPOL packet from 0040.96a1.bc2f
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75894: Jul ?7 18:09:36.914: EAPOL pak dump rx
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75895: Jul ?7 18:09:36.914: EAPOL Version: 0x1 ?type: 0x3 ?length: 0x0077
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75896: Jul ?7 18:09:36.915: EAP code: 0xFE id: 0x1 ?length: 0x0900 type: 0x20
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75897: 00E0FF50: ? ? ? ? ?01030077 FE010900 20000000 ? ? ?...w~... ...
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75898: 00E0FF60: 00000000 0182B1D7 FF439963 5116F7B7 ?......1W.C.cQ.w7
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75899: 00E0FF70: BC93F070 D321558E 816C0EFC E2141FC9 ?<.ppS!U..l.|b..I
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75900: 00E0FF80: E0C90E34 40000000 00000000 00000000 ?`I.4 at ...........
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75901: 00E0FF90: 00000000 00000000 00000000 00000000 ?................
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75902: 00E0FFA0: 00000000 00D0C69B 06589654 1E92916D ?.....PF..X.T...m
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75903: 00E0FFB0: 5B451F80 D80018DD 160050F2 01010000 ?[E..X..]..Pr....
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75904: 00E0FFC0: 50F20201 000050F2 02010000 50F201 ? ?Pr....Pr....Pr.
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75905: Jul ?7 18:09:36.916: dot11_mgr_sm_run_machine: Executing Action(PTK_MSG2_WAIT,RECV_EAPOL_KEY_RSP) for 0040.96a1.bc2f
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75906: Jul ?7 18:09:36.916: dot11_mgr_sm_recv_ptk_msg2:
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75907: Jul ?7 18:09:36.917: dot11_mgr_sm_recv_ptk_msg2: got ptk msg2

-----------------> it just got PTK msg 2 from the client, but the key info was apparently invalid?
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75908: Jul ?7 18:09:36.917: dot11_dot1x_verify_ptk_handshake: verifying PTK msg 2 from 0040.96a1.bc2f
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75909: Jul ?7 18:09:36.917: dot11_dot1x_verify_eapol_header: Warning: Invalid key info (exp=0x381, act=0x109
Jul ?7 14:09:36 apcsb-4.ens.ornl.gov 75910: Jul ?7 18:09:36.918: dot11_dot1x_build_ptk_handshake: building PTK msg 3 for 0040.96a1.bc2f
Jul ?7 14:09:37 apcsb-4.ens.ornl.gov 75911: Jul ?7 18:09:36.919: dot11_mgr_disp_client_send_eapol: sending eapol to client 0040.96a1.bc2f
Jul ?7 14:09:37 apcsb-4.ens.ornl.gov 75912: Jul ?7 18:09:36.920: dot11_mgr_sm_send_ptk_msg3: [1] Sent PTK msg 3 to 0040.96a1.bc2f
Jul ?7 14:09:37 apcsb-4.ens.ornl.gov 75913: Jul ?7 18:09:37.801: dot11_mgr_sm_parse_client_pak: Received EAPOL packet from 0040.96a1.bc2f
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75914: Jul ?7 18:09:39.252: EAPOL pak dump rx
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75915: Jul ?7 18:09:39.253: EAPOL Version: 0x1 ?type: 0x3 ?length: 0x005F
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75916: Jul ?7 18:09:39.253: EAP code: 0xFE id: 0x1 ?length: 0x0900 type: 0x20
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75917: 00E0B820: 0103005F FE010900 20000000 00000000 ?..._~... .......
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75918: 00E0B830: 0282B1D7 FF439963 5116F7B7 BC93F070 ?..1W.C.cQ.w7<.pp
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75919: 00E0B840: D321558E 816C0EFC E2141FC9 E0C90E34 ?S!U..l.|b..I`I.4
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75920: 00E0B850: 40000000 00000000 00000000 00000000 ?@...............
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75921: 00E0B860: 00000000 00000000 00000000 00000000 ?................
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75922: 00E0B870: 00DC222A 2010E8C3 29D5C978 F6B174B9 ?.\"* .hC)UIxv1t9
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75923: 00E0B880: 190000 ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ...
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75924: Jul ?7 18:09:39.254: dot11_mgr_sm_run_machine:
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75925: Executing Action(PTK_MSG4_WAIT,RECV_EAPOL_KEY_RSP) for 0040.96a1.bc2f

----------> same with PTK msg 4 from the client
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75926: Jul ?7 18:09:39.254: dot11_dot1x_verify_ptk_handshake: verifying PTK msg 4 from 0040.96a1.bc2f
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75927: Jul ?7 18:09:39.254: dot11_dot1x_verify_eapol_header: Warning: Invalid key info (exp=0x381, act=0x109
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75928: Jul ?7 18:09:39.255: DOT11 EVENT: Freeing packets with previous MIC
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75929: Jul ?7 18:09:39.255: DOT11 EVENT: Set client session key
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75930: Jul ?7 18:09:39.855: dot11_mgr_sm_run_machine: Executing Action(GTK_MSG2_WAIT,TIMEOUT) for 0040.96a1.bc2f
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75931: Jul ?7 18:09:39.855: dot11_dot1x_build_gtk_handshake: building GTK msg 1 for 0040.96a1.bc2f
Jul ?7 14:09:39 apcsb-4.ens.ornl.gov 75932: Jul ?7 18:09:39.855: dot11_dot1x_build_gtk_handshake:
Jul ?7 14:09:40 apcsb-4.ens.ornl.gov 75933: dot11_dot1x_get_multicast_key len 32 index 1
Jul ?7 14:09:40 apcsb-4.ens.ornl.gov 75934: Jul ?7 18:09:39.856: dot11_dot1x_hex_dump: GTK: 38 FD 59 49 46 1F FF 68 50 37 0A E0 B0 93 E5 D0 DC 45 E7 BC 52 B7 65 FE AA C8 1B 3F D6 22 5C 30
Jul ?7 14:09:40 apcsb-4.ens.ornl.gov 75935: Jul ?7 18:09:40.702: dot11_dot1x_build_gtk_handshake:
Jul ?7 14:09:40 apcsb-4.ens.ornl.gov 75936: Jul ?7 18:09:40.702: reg_invoke_dot11_drv_get_xmit_replay: return false
Jul ?7 14:09:42 apcsb-4.ens.ornl.gov 75937: Jul ?7 18:09:42.119: dot11_mgr_disp_client_send_eapol: sending eapol to client 0040.96a1.bc2f

---------------------> here it sends GTK msg 1 from the client, but the reply is not encrypted (i guess it's supposed to be) and so it's discarded. 
it retries a couple times and gives up
Jul ?7 14:09:42 apcsb-4.ens.ornl.gov 75938: Jul ?7 18:09:42.120: dot11_mgr_sm_send_gtk_msg1: [1] Sent GTK msg 1 to 0040.96a1.bc2f
Jul ?7 14:09:42 apcsb-4.ens.ornl.gov 75939: Jul ?7 18:09:42.123: *** Not encrypted dot1x packet from 0040.96a1.bc2f has been discarded
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75940: Jul ?7 18:09:43.851: dot11_mgr_sm_run_machine: Executing Action(GTK_MSG2_WAIT,TIMEOUT) for 0040.96a1.bc2f
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75941: Jul ?7 18:09:43.851: dot11_dot1x_build_gtk_handshake: building GTK msg 1 for 0040.96a1.bc2f
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75942: Jul ?7 18:09:43.852: dot11_dot1x_build_gtk_handshake: dot11_dot1x_get_multicast_key len 32 index 1
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75943: Jul ?7 18:09:43.852: dot11_dot1x_hex_dump: GTK: 38 FD 59 49 46 1F FF 68 50 37 0A E0 B0 93 E5 D0 DC 45 E7 BC 52 B7 65 FE AA C8 1B 3F D6 22 5C 30
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75944: Jul ?7 18:09:43.856: dot11_dot1x_build_gtk_handshake:
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75945: Jul ?7 18:09:43.856: reg_invoke_dot11_drv_get_xmit_replay: return false
Jul ?7 14:09:44 apcsb-4.ens.ornl.gov 75946: Jul ?7 18:09:44.442: dot11_mgr_disp_client_send_eapol: sending eapol to client 0040.96a1.bc2f
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75947: Jul ?7 18:09:44.442: dot11_mgr_sm_send_gtk_msg1: [2] Sent GTK msg 1 to 0040.96a1.bc2f
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75948: Jul ?7 18:09:44.605: *** Not encrypted dot1x packet from 0040.96a1.bc2f has been discarded
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75949: Jul ?7 18:09:45.442: dot11_mgr_sm_run_machine: Executing Action(GTK_MSG2_WAIT,TIMEOUT) for 0040.96a1.bc2f
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75950: Jul ?7 18:09:45.442: dot11_dot1x_build_gtk_handshake: building GTK msg 1 for 0040.96a1.bc2f
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75951: Jul ?7 18:09:45.442: dot11_dot1x_build_gtk_handshake: dot11_dot1x_get_multicast_key len 32 index 1
Jul ?7 14:09:45 apcsb-4.ens.ornl.gov 75952: Jul ?7 18:09:45.442: dot11_dot1x_hex_dump: GTK: 38 FD 59 49 46 1F FF 68 50 37 0A E0 B0 93 E5 D0 DC 45 E7 BC 52 B7 65 FE AA C8 1B 3F D6 22 5C 30
Jul ?7 14:09:46 apcsb-4.ens.ornl.gov 75953: Jul ?7 18:09:45.888: dot11_dot1x_build_gtk_handshake:
Jul ?7 14:09:46 apcsb-4.ens.ornl.gov 75954: Jul ?7 18:09:45.888: reg_invoke_dot11_drv_get_xmit_replay: return false
Jul ?7 14:09:46 apcsb-4.ens.ornl.gov 75955: Jul ?7 18:09:45.890: dot11_mgr_disp_client_send_eapol: sending eapol to client 0040.96a1.bc2f
Jul ?7 14:09:46 apcsb-4.ens.ornl.gov 75956: Jul ?7 18:09:45.890: dot11_mgr_sm_send_gtk_msg1: [3] Sent GTK msg 1 to 0040.96a1.bc2f
Jul ?7 14:09:46 apcsb-4.ens.ornl.gov 75957: Jul ?7 18:09:45.892: *** Not encrypted dot1x packet from 0040.96a1.bc2f has been discarded
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75958: Jul ?7 18:09:47.641: dot11_mgr_sm_run_machine: Executing Action(GTK_MSG2_WAIT,TIMEOUT) for 0040.96a1.bc2f
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75959: Jul ?7 18:09:47.641: dot11_mgr_sm_handshake_fail: Handshake failure for 0040.96a1.bc2f
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75960: Jul ?7 18:09:47.641: dot11_aaa_send_response: Sending response: 0 for: 0040.96a1.bc2f
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75961: Jul ?7 18:09:47.641: dot11_mgmt_sta_ref(ref=2,sta_ptr=0x9ABC2C,mac=0040.96a1.bc2f)
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75962:
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75963: Jul ?7 18:09:47.641: dot11_mgmt_sta_del_all_children sta_ptr 0x9ABC2C
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75964:
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75965: Jul ?7 18:09:47.641: dot11_mgmt_sta_tree_cont_cleanup, 0x9ABC2C
Jul ?7 14:09:47 apcsb-4.ens.ornl.gov 75966: Jul ?7 18:09:47.641: dot11_mgmt: finish remove 0040.96a1.bc2f and its children

so there seems to be a problem with the PTK key handshake. I've attached (gzipped) the full log from the AP and also the log from wpa_supplicant,
which was (hopefully) from the same run. I'm not sure if this is a wpa_supplicant or a madwifi issue, but maybe someone who knows more than me
can shed some light on it.
Thanks again!

A related (but OT for this list I guess) note is that because my AP beacons an 
SSID without WEP but also has an SSID with WEP, (as well as one with WPA) the 
madwifi driver cannot associate to the WEP SSID with WEP enabled. (It will 
associate to the WEP ssid without wep enabled, but as soon as you do iwconfig 
ath0 key xxxx it won't associate at all, presumably because it thinks the AP 
has WEP disabled). I assume this is an issue for the madwifi mailing list, if 
there is one.

A third unrelated issue:
Jouni wrote:
> > Did I understand correctly that the same AP is actually working with
> > another client that is using Host AP driver? Would it be possible for
> > you to try the exact same wpa_supplicant version with these two drivers
> > to verify that the problem is indeed in the driver or driver interface
> > code of wpa_supplicant and not in some generic code that may have
> > changed during the last few weeks?
>
I found out what was happening. It wasn't actually the driver; instead, it was 
because the hostap driver comes up by default in master mode. if the card is 
in master mode, wpa_supplicant gets this error:
?
Starting AP scan (specific SSID)
Scan SSID - hexdump_ascii(len=7):
? ? ?6f 72 6e 6c 77 70 61 ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?ornlwpa
? ? ?ioctl[PRISM2_IOCTL_HOSTAPD]: Operation not supported
? ? ?Failed to initiate AP scan.

Once you use iwconfig to change to managed mode, it works.
I don't know if it makes sense or is possible for wpa_supplicant to try to put 
the card in managed mode (i assume you could do this for any card using 
wireless extensions) but that might be something to consider, or at perhaps 
at least check the mode and give some clue to the user as to what might be 
going on.

Regards,

Derek