Hostapd WPA2 and XP Supplicant

Andrew Tarabaras atp3 at optusnet.com.au
Sat Jul 12 20:17:14 EDT 2008 

Jouni Malinen wrote:
> On Mon, Jul 07, 2008 at 11:39:41AM +1000, Andrew Tarabaras wrote:
> 
>> They all connect ok but WinXP keeps disconnecting and re authenticating 
>> . Vista is OK so I sure the problem is in XP. Windows XP is no help in 
>> the debugging of this problem and tells me nothing. If I keep the 
>> interface busy with data it stays up. A few seconds of quiet on the 
>> interface it starts to disconnecting and re authenticating again.
> 
> Have you enabled EAPOL tracing in Windows XP to get debug information?
> This issue looks like something that requires client side debugging
> since everything looks fine from the AP side apart from the client
> deciding to re-associate (at least based on hostapd output).
> 

I have enabled tracing in XP but it gives almost no useful information. 
Its all gobbledygook to me but I will attach it for some better eyes to 
look over it.
  What I have done is try the linux WPA_Supplicant under XP and it 
behaves the same.
  Ive worked out its somewhere in the ndis drivers. I get this in 
wpa_supplicants output.

ndis: media disconnect event
msndis_status_media_disconnect

There is no other useful information in the logs. I get the same output 
from a different working AP but without the disconnect message.

Trying to get logs from the ndis driver I see the same.

General Status : NDIS_STATUS_MEDIA_DISCONNECT (0x4001000C)

What makes this happen ? What does the NDIS driver look for to see if 
the media link status is up or down ?

Could it be my ralink rt73 hardware on hostapd? Next step is to try a b43.

If I keep pinging the interface from the client all is good and the link 
stays up. As soon as the interface is quiet for a few secconds it starts 
doing its disconnect and reauth thing, over and over.
  Searching google seems some users have the same problem with the 
ralink chipset but nothing involving hostapd.

Below is the windows XP EAPOL trace and WZCTrace. I only took a portion 
of it as it was huge.

Ive marked it in the middle where the disconnect happens.
Let me know if I need more logs.


WINDOWS EAPOL TRACE

[1252] 22:51:28:671: EAPOL-Key for transmit key received within 5 
seconds in AUTHENTICATED state
[1252] 22:51:28:671: Resetting the auth fail counter to 0, Old Value was 0
[1252] 22:51:28:671: ElVerifyEAPOLKeyReceived: RpcCmdInterface[10] SUCCEEDed
[1252] 22:51:28:671: ElZeroConfigNotify: Handle=(175), failcount=(0), 
lastauthtype=(0)
[1252] 22:51:28:671: ElVerifyEAPOLKeyReceived: ElZeroConfigNotify 
SUCCEEDed -- type=(5)
[1252] 22:51:28:671: ElTimeoutCallbackRoutine completed
[5052] 22:51:29:703: EAPOLQueryGUIDNCSState: Broadcom 802.11b/g WLAN - 
Packet Scheduler Miniport is in PSK Mode Returning S_OK
[5052] 22:51:29:718: EAPOLQueryGUIDNCSState: Broadcom 802.11b/g WLAN - 
Packet Scheduler Miniport is in PSK Mode Returning S_OK
[5052] 22:51:29:718: EAPOLQueryGUIDNCSState: Broadcom 802.11b/g WLAN - 
Packet Scheduler Miniport is in PSK Mode Returning S_OK
[5052] 22:51:29:750: EAPOLQueryGUIDNCSState: Broadcom 802.11b/g WLAN - 
Packet Scheduler Miniport is in PSK Mode Returning S_OK
[3384] 22:51:30:265: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[3384] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<25>, 
Offset=<52/104>, dwAuthData=<0>
[3384] 22:51:30:265: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[3384] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<25>, 
Offset=<52/104>, dwAuthData=<0>
[3384] 22:51:30:265: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[3384] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<25>, 
Offset=<52/104>, dwAuthData=<0>
[3384] 22:51:30:265: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[3384] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1840] 22:51:30:265: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<25>, 
Offset=<52/104>, dwAuthData=<0>

This is where it goes down.

[5052] 22:51:47:953: ElMediaEventsHandler entered -- EventType=<6>
[5052] 22:51:47:953: ElMediaEventsHandler: Calling ElMediaSenseEventFromWZC
[5052] 22:51:47:953: ElMediaSenseEventFromWZC: Entered
[5052] 22:51:47:953: ElMediaSenseEventFromWZCWorker: For interface GUID 
({96DAC25A-9093-4351-9806-BBB4527AD423})
[5052] 22:51:47:953: ElMediaSenseEventFromWZCWorker: Callback for sense 
disconnect
[5052] 22:51:47:953: Current Mode is NOT WPA2. PreAuth disabled
[5052] 22:51:47:953: FSMWPAPSKDisconnected entered for port Broadcom 
802.11b/g WLAN - Packet Scheduler Miniport
[5052] 22:51:47:953: ElMediaSenseEventFromWZCWorker: Port marked 
disconnected {96DAC25A-9093-4351-9806-BBB4527AD423}
[5052] 22:51:47:953: ElMediaSenseCallbackWorker: processed, RetCode = 0
[5052] 22:51:47:953: ElReadFromPort entered, pPCB = 000D4110
[5052] 22:51:47:953: ElReadFromPort: pPCB = 000D4110, RefCnt = 3
[3356] 22:51:51:765: EAPOLQueryGUIDNCSState: Broadcom 802.11b/g WLAN - 
Packet Scheduler Miniport is in PSK Mode Returning S_OK
[1252] 22:51:51:781: ElMediaEventsHandler entered -- EventType=<7>
[1252] 22:51:51:781: ElMediaEventsHandler: Calling ElZeroConfigEvent
[1252] 22:51:51:781: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[1252] 22:51:51:781: ElEnumAndOpenInterfaces: DeviceDesc = , GUID = 
{96DAC25A-9093-4351-9806-BBB4527AD423}
[1252] 22:51:51:781: ElNdisuioEnumerateInterfaces: Opening handle
[1252] 22:51:51:781: NdisuioEnumerateInterfaces: NDISUIO bound to: (0) 
\DEVICE\{96DAC25A-9093-4351-9806-BBB4527AD423}
      - Broadcom 802.11b/g WLAN - Packet Scheduler Miniport
[1252] 22:51:51:781: ElNdisuioEnumerateInterfaces: DeviceIoControl 
IOCTL_NDISUIO_QUERY_BINDING has no more entries
[1252] 22:51:51:781: Device: \DEVICE\{96DAC25A-9093-4351-9806-BBB4527AD423}
[1252] 22:51:51:781: Description: Broadcom 802.11b/g WLAN - Packet 
Scheduler Miniport
[1252] 22:51:51:781: ElEnumAndOpenInterfaces: Found interface after 
enumeration \DEVICE\{96DAC25A-9093-4351-9806-BBB4527AD423}
[1252] 22:51:51:781: ElEnumAndOpenInterfaces: Found PCB already existing 
for interface
[1252] 22:51:51:781: ElCreatePort: Entered for Handle=(057C4F90), 
GUID=({96DAC25A-9093-4351-9806-BBB4527AD423}), Name=(Broadcom 802.11b/g 
WLAN - Packet Scheduler Miniport), ZCId=(177), UserData=(058EE530) 
Notification=<4>
[1252] 22:51:51:781: ElCreatePort: PCB found for 
{96DAC25A-9093-4351-9806-BBB4527AD423}
[1252] 22:51:51:781: ElReStartPort: Entered: pPCB=<000D4110>, 
pZCConnectInfo=<026DFEC0>, Refcnt=<3>, EapFlags=<c0000000>, Notification=<4>
[1252] 22:51:51:781: ElRestartPortLocked: Entered: pPCB=<000D4110>, 
pZCConnectInfo=<026DFEC0>, Refcnt=<3>, EapFlags=<c0000000>, Notification=<4>
[1252] 22:51:51:781: ElRestartPortLocked: Not restarting authentication 
because of preauth quarantine. Resetting the counter (curent value=0)
[1252] 22:51:51:781: Current Mode is NOT WPA2. PreAuth disabled
[1252] 22:51:51:781: ElRestartPortLocked: ElNdisuioQueryOIDValue for 
OID_802_11_INFRASTRUCTURE_MODE successful, Mode = (1)
[1252] 22:51:51:781: ElRestartPortLocked: ElNdisuioQueryOIDValue for 
OID_802_11_BSSID successful
[1252] 22:51:51:781: 00 17 9A 77 1D CF 00 00 00 00 00 00 00 00 00 00 
|...w............|
[1252] 22:51:51:781: ElRestartPortLocked: Moved to the same network
[1252] 22:51:51:781: ElRestartPortLocked: prdUserData not valid
[1252] 22:51:51:781: ElRestartPortLocked: pPCB=<000D4110>, 
AuthenticationMode=<7>, EncyptionStatus=<6>, usKeyDescription=<2>
[1252] 22:51:51:781: ElRestartPortLocked: Port Network Identifier:
[1252] 22:51:51:781: 74 65 73 74 00 00 00 00 00 00 00 00 00 00 00 00 
|test............|
[1252] 22:51:51:781: ElRestartPortLocked: Resetting Credentials for 
Broadcom 802.11b/g WLAN - Packet Scheduler Miniport
[1252] 22:51:51:796: ElGetInterfaceParams:  SsidLength=<4>, Found 
EapTypeId=<13>, SSIDLen=<4>
[1252] 22:51:51:796: ElReadPerPortRegistryParams: Setting 
dwEapFlags=<c0000000>
[1252] 22:51:51:796: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1252] 22:51:51:796: ElGetCustomAuthData: SSIDLen=<4>, EapTypeId=<13>, 
Offset=<52/104>, dwAuthData=<40>
[1252] 22:51:51:796: ElReadPerPortRegistryParams: 
dwTotalMaxAuthFailCount = (3)
[1252] 22:51:51:796: FSMWPAPSK entered for port Broadcom 802.11b/g WLAN 
- Packet Scheduler Miniport




And same point in WZCTrace

[3384] 22:51:30:265: [WzcDuplicateConfigList: dwDataIn=<0>, Flags=<5>, 
deMaxEntries=<0>, pListIn=<03D8CA68>, pConfigListNew=<00000000>
[3384] 22:51:30:265: [MIDL_user_allocate(1432)=0x055B7168;0]
[3384] 22:51:30:265: 	WZCIsSameNetwork: Flags=<3/3> => 
<4:4>:<test/test>, Result=<3/3>==> MATCHed
[3384] 22:51:30:265: 	WZCIsSameNetwork: Flags=<203/3> => 
<4:4>:<home/test>, Result=<0/3>==> NOT MATCHed
[3384] 22:51:30:265: [MIDL_user_allocate(120)=0x0597EAD0;0]
[3384] 22:51:30:265: [WzcDuplicateConfigList: dwDataIn=<0>, Flags=<5>, 
deMaxEntries=<0>, pListIn=<05A47860>, pConfigListNew=<00000000>
[3384] 22:51:30:265: [MIDL_user_allocate(1432)=0x055176B8;0]
[3384] 22:51:30:265: 	WZCIsSameNetwork: Flags=<4010/3> => 
<4:4>:<test/test>, Result=<3/3>==> MATCHed
[3384] 22:51:30:265: 	WZCIsSameNetwork: Flags=<4010/3> => 
<4:4>:<home/test>, Result=<0/3>==> NOT MATCHed
[3384] 22:51:30:265: [LstRccsUnlockUnref(0x000B6EB0)
[3384] 22:51:30:265:  LstRccsUnlockUnref 0x000B6EB0.refCount=1
[3384] 22:51:30:265: LstRccsUnlockUnref]=0
[3384] 22:51:30:265: Sending OutFlags = 0x40cff0f
[3384] 22:51:30:265: LstQueryInterface]=0
[3384] 22:51:30:265: RpcQueryInterface]=0
[3384] 22:51:30:265: [MIDL_user_free(0x0597EAD0)]
[3384] 22:51:30:265: [MIDL_user_free(0x055176B8)]
[3384] 22:51:30:265: [MIDL_user_free(0x055B7168)]
[3384] 22:51:30:265: [MIDL_user_allocate(552)=0x05DFE008;0]
[3384] 22:51:30:265: [MIDL_user_free(0x05DFE008)]
[3384] 22:51:30:265: [MIDL_user_allocate(552)=0x05DFE008;0]
[3384] 22:51:30:265: [MIDL_user_free(0x05DFE008)]
[3384] 22:51:30:265: [MIDL_user_allocate(552)=0x05DFE008;0]
[3384] 22:51:30:265: [MIDL_user_free(0x05DFE008)]
[3384] 22:51:30:265: [MIDL_user_allocate(552)=0x05DFE008;0]
[3384] 22:51:30:265: [MIDL_user_free(0x05DFE008)]

Dissconnect here

[5052] 22:51:47:937: WzcIoCompletion called, 98 bytes xferred
[5052] 22:51:47:937: WZCSvcNdisuioEventNotify: called 
pIoContext=(0x05C44700)
[5052] 22:51:47:937: [MemAlloc(150)=0x03C71468;0]
[5052] 22:51:47:937: [WZCWrkDeviceNotifHandler(wzcnotif 6)
[5052] 22:51:47:937: [MemAlloc(78)=0x05CAE8D0;0]
[5052] 22:51:47:937: [HshQueryObjectRef(0x05CAE8D0)
[5052] 22:51:47:937: HshQueryObjectRef]=0
[5052] 22:51:47:937: WZCNotif 6 for Device Key 
"{96DAC25A-9093-4351-9806-BBB4527AD423}". Context=0x000B6EB0
[5052] 22:51:47:937: [LstNotificationHandler(0x000B6EB0, 6, 
{96DAC25A-9093-4351-9806-BBB4527AD423})
[5052] 22:51:47:937: [LstRccsReference(0x000B6EB0)
[5052] 22:51:47:937:  LstRccsReference 0x000B6EB0.refCount=1
[5052] 22:51:47:937: LstRccsReference]=0
[5052] 22:51:47:937: [LstRccsLock(0x000B6EB0)
[5052] 22:51:47:937: LstRccsLock]=0
[5052] 22:51:47:937: [StateDispatchEvent(3,0x000B6EB0,0x00000000)
[5052] 22:51:47:937: [MemFree(0x00000000)]
[5052] 22:51:47:937: [StateDispatchEvent:313] --> RESET_TIMER 
pIntf=<000B6EB0>, Err=<0>
[5052] 22:51:47:937: [StateHardResetFn(0x000B6EB0)
[5052] 22:51:47:937: [MemFree(0x00000000)]
[5052] 22:51:47:937: [WzcNetmanNotify(0x000B6EB0)
[5052] 22:51:47:937: WzcNetmanNotify]=0
[5052] 22:51:47:937: [DevioRefreshIntfOIDs(0x000B6EB0)
[5052] 22:51:47:937: [DevioCloseIntfHandle(0x000B6EB0)
[5052] 22:51:47:937: 
[CloseIntfHandle(\DEVICE\{96DAC25A-9093-4351-9806-BBB4527AD423})
[5052] 22:51:47:937: [HshQueryObjectRef(0x01FAF8A4)
[5052] 22:51:47:937: HshQueryObjectRef]=0
[5052] 22:51:47:937: CloseIntfHandle -> 0x12c4 (deref)
[5052] 22:51:47:937: [DereferenceInterfaceHandleContext 0x57c4f90, ref 
count=2]
[5052] 22:51:47:937: CloseIntfHandle]=0
[5052] 22:51:47:937: DevioCloseIntfHandle]=0
[5052] 22:51:47:937: 
[DevioOpenIntfHandle({96DAC25A-9093-4351-9806-BBB4527AD423})
[5052] 22:51:47:937: 
[OpenIntfHandle(\DEVICE\{96DAC25A-9093-4351-9806-BBB4527AD423})
[5052] 22:51:47:937: [HshQueryObjectRef(0x01FAF8A0)
[5052] 22:51:47:937: HshQueryObjectRef]=0
[5052] 22:51:47:937: OpenIntfHandle: Context 0x57c4f90, handle: 0x12c4 
(cached)
[5052] 22:51:47:937: OpenIntfHandle]=0
[5052] 22:51:47:937: WzcReadFromIntlHandle entered
[5052] 22:51:47:937: [ReferenceInterfaceHandleContext 0x57c4f90, ref 
count=4]
[5052] 22:51:47:937: InternalWzcReadFromIntlHandle entered
[5052] 22:51:47:937: WzcReadFromIntlHandle Error=0
[5052] 22:51:47:937: DevioOpenIntfHandle]=0
[5052] 22:51:47:937: [DevioQueryBinaryOID(0x57c4f90, 0xd010102)
[5052] 22:51:47:937: [MemFree(0x00000000)]
[5052] 22:51:47:937: [MemAlloc(40)=0x05AD0268;0]
[4524] 22:51:47:937: [WZCSvcWMIHandler(0x01018740)
[4524] 22:51:47:937: [MemAlloc(214)=0x0545B570;0]
[4524] 22:51:47:937: WMI Notification GUID is not recognized
[4524] 22:51:47:937: [MemFree(0x0545B570)]
[4524] 22:51:47:937: WZCSvcWMIHandler=0]
[5052] 22:51:47:937: DevioQueryBinaryOID]=0
[5052] 22:51:47:937: DevioRefreshIntfOIDs[OID_802_11_SSID]:  ===> 
<__________> <0 bytes>




Thankyou
Andrew.

More information about the HostAP mailing list