Hostapd WPA2 and XP Supplicant
Andrew Tarabaras
atp3
Sat Jul 12 17:17:14 PDT 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