A Support Guide for Wireless Diagnostics and Troubleshooting
On This Page
Introduction
Information Gathering
Symptom Diagnosis
Part 1: 802.11 Connectivity
Part 2: 802.1X Authentication
Appendix A: Quick Reference Guide
Appendix B: Wireless Group Policy
References
Introduction
This article is designed to be a support aid to help diagnose wireless connection and authentication issues. It is meant to provide an advanced level of wireless diagnostics procedures by analyzing tracing logs generated by wireless components in Microsoft® Windows® XP and Windows Server™ 2003 to spot common problems and verify basic operation. This article includes a quick reference, providing quick answers to common connection problems.
This article assumes knowledge of IEEE 802.11-based wireless LAN networking including related technologies such as IEEE 802.1X and Wi-Fi Protected Access (WPA™). This article is not meant to be a detailed explanation of the inner workings of the Windows Wireless Zero Configuration service. For basic knowledge of wireless networking, see the Windows Server 2003 Wireless Networking Web site.
Information Gathering
The first step to take for a wireless issue is to gather information that might be needed to perform a preliminary diagnosis, including the following:
Windows operating system version, including the latest service pack installed and build number if applicable.
Wireless connection details of the Windows wireless client including the type of authentication and encryption that is being used.
Wireless network adapter details, including vendor, model, and driver version.
Wireless access point (AP) information, including vendor, model, firmware version, and configuration details similar to Step 2.
Wireless logs. Logging can be enabled through the netsh ras set tracing * en command. After enabling logging, you can either restart the computer or restart the Wireless Zero Configuration (for Windows XP) or Wireless Configuration (for Windows Server 2003) service with the net stop wzcsvc and net start wzcsvc commands. The wireless logs are located in the systemroot\tracing folder. The log files most useful for troubleshooting wireless issues are the following:
Wzctrace.log Used mostly for 802.11 association. This file is present only on computers running Windows XP Service Pack 2 (SP2) or Windows Server 2003 Service Pack 1.
Eapol.log Used mostly for IEEE 802.1X authentication.
Wzcdlg.log Used for user interface changes, such as changes made through the View Available Networks or Choose a wireless network dialog boxes.
Netman.log Used for user interface changes.
Netshell.log Used for user interface changes.
Along with any .old versions of these files
Note the times when the issues occurred so you can locate the relevant sections of the log files.
There are times when it is not necessary to have all this information, but when in doubt, it is better to have too much information than too little.
Symptom Diagnosis
For the times that an immediate or trivial solution is not apparent, symptomatic analysis is best used to determine where you should look next.
Symptoms and Solutions
Table 1 lists common issues, causes, and likely solutions.
Table 1 Wireless connection issues and solutions
Symptom |
Possible Causes |
Things to Do |
|---|---|---|
Inability to connect |
|
|
Intermittent connectivity |
|
|
Incorrect, missing, or stale visible networks |
|
|
Wireless client has associated but no there is no valid IP address configuration or no network connectivity |
|
|
Wireless connection problems when performing a suspend and resume with a laptop computer |
|
|
Wireless Networks tab is not present for the properties of the wireless network adapter in the Network Connections folder or there are no visible wireless networks |
|
|
Part 1: 802.11 Connectivity
The steps of diagnosing a wireless connection problem correspond to the two major phases of a wireless connection—an 802.11 association then an 802.1X authentication. If the issue is 802.11 association, then the focus of your investigation is on the contents of the Wzctrace.log file. If the issue is 802.1X authentication, then most likely you will need to analyze the Eapol.log file. There might be times you will need to refer to both.
Reading the Wzctrace.log File
The method for reading the Wzctrace.log file described in this section focuses on making quick checks for information at key points of the association process that are most likely to reveal the cause of the problem. With the Wzctrace.log file, you should be able to successfully diagnose the majority of common problems association problems, or at least rule out association as the being the root cause of the problem.
The general steps that should be taken when viewing the Wzctrace.log file are:
Identify the time periods of interest to examine (for example, if you got disconnected at 11:33 AM). If you have followed the basic information gathering process, you should know approximately what time the problems occurred. You should not start reading a log from beginning to end.
Focus initial attention around these time periods of interest. Depending on the issue, decide on what key areas need to be examined.
Note: Do not try to read every line in the wireless log files sequentially as you will quickly get bogged down in many details that you will not understand. Most issues that you will encounter can be spotted, diagnosed, and addressed by just skimming through a log file looking for key sections and events in the connection process. The best approach is to make a quick read of the appropriate section of the log file, taking note of anything obvious. If nothing appears obvious, read through the log file again, taking note of finer details.
An Example Wzctrace.log File
This section contains an example Wzctrace.log file for a successful wireless connection. This example log file shows the Wireless Zero Configuration service starting, the wireless network adapter being enabled, and a wireless connection being established when 802.1X authentication is not being used. The actual log file has much more information that is not included in the example.
The following example contains selected portions of a Wzctrace.log file. To guide you through its contents, the lines that begin with "//" and consist of capitalized text are comments explaining the meaning of the portion of the log above the comment lines. The bolded texts are the strings you would search for in order to collect information for troubleshooting.
[4024] 15:56:04:910: **** [WZCSvcMain - Service Start Pending
//THE WIRELESS ZERO CONFIGURATION SERVICE IS JUST BEGINNING TO INITIALIZE
...
[4024] 15:56:04:910: [StoLoadWZCConfig("ActiveSettings, Ver=7")
//THE WIRELESS ZERO CONFIGURATION SERVICE IS ABOUT TO LOAD SAVED CONFIGURATIONS FROM THE REGISTRY, THE LAYOUT VERSION SHOULD BE 7 FOR WINDOWS XP SP2 AND 5 FOR WINDOWS XP SERVICE PACK 1
...
[4024] 15:56:04:910: Uploading 0 static configurations
//THE WIRELESS ZERO CONFIGURATION SERVICE HAS UPLOADED NO SAVED CONFIGURATIONS FOR THIS INTERFACE
...
[4024] 15:56:04:910: Intf [0] {358A365F-54C4-4558-8CD5-5044BD595924} - Bluetooth Device (Personal Area Network)
//THE WIRELESS ZERO CONFIGURATION SERVICE HAS BEEN DOING THIS FOR THIS PARTICULAR DEVICE
...
[4024] 15:56:04:920: Local Mac address : [6]:{08 00 46 cc a4 5e }
...
[4024] 15:56:04:930: **** WZCSvcMain - Service Running
...
[2120] 15:56:17:468: [WZCWrkDeviceNotifHandler(wzcnotif 3)
[2120] 15:56:17:468: [MemAlloc(78)=0x001236D0;0]
[2120] 15:56:17:468: [HshQueryObjectRef(0x001236D0)
[2120] 15:56:17:468: HshQueryObjectRef]=2
[2120] 15:56:17:468: [LstNotificationHandler(0x00000000, 3, {AB6A1A0A-F3E9-48F1-B28E-6749F7064F58})
[2120] 15:56:17:468: [DevioGetInterfaceBindingByGuid({AB6A1A0A-F3E9-48F1-B28E-6749F7064F58}..)
//NOTIFICATION OF THE DEVICE WITH GUID AB6A1A0A-F3E9-48F1-B28E-6749F7064F58 BINDING
...
[2120] 15:56:17:468: Intf [1] {AB6A1A0A-F3E9-48F1-B28E-6749F7064F58} - Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE DEVICE IS AN INTEL 2200BG WIRELESS NETWORK ADAPTER
...
[2120] 15:56:17:468: [StoLoadWZCConfig("ActiveSettings, Ver=7")
//THE WIRELESS ZERO CONFIGURATION SERVICE IS ABOUT TO LOAD SAVED CONFIGURATIONS FROM THE REGISTRY, THE LAYOUT VERSION FOR WINDOWS XP SP2 SHOULD BE 7 (5 FOR WINDOWS XP SERVICE PACK 1)
...
[2120] 15:56:17:468: Uploading 1 static configurations
//THE WIRELESS ZERO CONFIGURATION SERVICE HAS UPLOADED 1 SAVED CONFIGURATION FOR THIS INTERFACE
...
[2120] 15:56:17:468: [WZCCopySelectedConfigs(02FE48D0->1/1, 0)
[2120] 15:56:17:468: WZCCopySelectedConfigs[0]: SSID=<8:DellTest> From List
[2120] 15:56:17:468: WZCCopySelectedConfigs]=0, NumCopied=<1>, Index=<1/1>
//IT IS A NETWORK CONFIGURATION WITH AN SSID OF “DellTest”
...
[2120] 15:56:17:468: Local Mac address : [6]:{00 0e 35 10 c5 81 }
//THE DEVICE’S MAC ADDRESS
...
[2120] 15:56:17:478: [DevioGetCapabilities(0x000A9588)
[2120] 15:56:17:478: [DevioGetCapSSN(0x000A9588)
[2120] 15:56:17:478: [DevioSetEnumOID(0x2290, 0xd010118, 3)
[2120] 15:56:17:478: DevioSetEnumOID]=0
[2120] 15:56:17:478: [DevioQueryEnumOID(0x2290, 0xd010118)
...
[2120] 15:56:17:488: DevioQueryEnumOID]=0
[2120] 15:56:17:488: DevioGetCapSSN=0x00000100]=0
[2120] 15:56:17:488: [DevioGetCapMaxCipher(0x000A9588)
[2120] 15:56:17:488: [DevioSetEnumOID(0x2290, 0xd01011b, 6)
...
[2120] 15:56:17:498: DevioSetEnumOID]=0
[2120] 15:56:17:498: [DevioQueryEnumOID(0x2290, 0xd01011b)
[2120] 15:56:17:498: DevioQueryEnumOID]=0
[2120] 15:56:17:498: [DevioSetEnumOID(0x2290, 0xd01011b, 4)
[2120] 15:56:17:498: DevioSetEnumOID]=0
[2120] 15:56:17:498: [DevioQueryEnumOID(0x2290, 0xd01011b)
[2120] 15:56:17:498: DevioQueryEnumOID]=0
[2120] 15:56:17:498: DevioGetCapMaxCipher=0x00000104]=0
[2120] 15:56:17:498: [DevioSetBinaryOID(0x2290,0xd01011d, 64 bytes,...)
[2120] 15:56:17:498: [MemAlloc(68)=0x000C1C38;0]
[2120] 15:56:17:498: Err: IOCTL_NDISUIO_SET_OID_VALUE->87
[2120] 15:56:17:498: [MemFree(0x000C1C38)]
[2120] 15:56:17:498: DevioSetBinaryOID]=87
[2120] 15:56:17:498: Checked OID_.._ADD_KEY; err=0; cap=0x00000104
[2120] 15:56:17:498: [DevioQueryBinaryOID(0x2290, 0xd01011f)
[2120] 15:56:17:498: [MemFree(0x00000000)]
[2120] 15:56:17:498: [MemAlloc(44)=0x02FB2F08;0]
[2120] 15:56:17:498: [MemFree(0x02FB2F08)]
[2120] 15:56:17:498: DevioQueryBinaryOID]=0
[2120] 15:56:17:498: [MemFree(0x00000000)]
[2120] 15:56:17:498: Checked OID_.._ASSOC.._INFO..; err=0; cap=0x00000104
[2120] 15:56:17:498: DevioGetCapabilities=0x00000104]=0
//THE WIRELESS ZERO CONFIGURATION SERVICE PERFORMS A CAPABILITIES CHECK OF THE WIRELESS NETWORK ADAPTER. THIS INVOLVES OID SETS AND QUERIES TO DETERMINE WHAT KINDS OF AUTH/ENCRYPTION MODES IT IS CAPABLE OF (E.G. WPA/TKIP). YOU MAY OBSERVE ERRORS HERE, BUT THEY ARE NOT AN INDICATION OF A DRIVER PROBLEM, UNLESS YOU SEE AN ASSERT.
...
[2120] 15:56:17:508: [StateSoftResetFn:584] --> SET_TIMER <3000>MSecs, Err=<0>
//THE WIRELESS ZERO CONFIGURATION SERVICE ISSUES A SCAN REQUEST TO THE DRIVER AND WAITS 3 SECONDS
...
[152] 15:56:20:522: [WZCTimeoutCallback(0x000A9588)
//THE WIRELESS ZERO CONFIGURATION SERVICE IS DONE WAITING
...
[152] 15:56:20:522: Media State (0) is Not Connected
//NOTE OUR CONNECTION STATE
...
[152] 15:56:20:522: [WzcNdisToWzc=0086FE84->06CB65A0
[152] 15:56:20:522: [AddNdisEntriesToCache, NumCached=<0>
[152] 15:56:20:522: AddNdisEntriesToCache: Flushing cache -- NumEntries= <0 + 0>
[152] 15:56:20:522: AddNdisEntriesToCache]=0, (Dup=0) + Cached/ThisScan+Untouched= 0/8+0, CacheSize=<8>
[152] 15:56:20:532: ResolveUncachedSsids[FAILed]: <DellTest> ==> Num=<0>, Error=<31>
[152] 15:56:20:532: ResolveUncachedSsids[FAILed]: <alokm10603-11i.Performance.5.1> ==> Num=<0>, Error=<31>
[152] 15:56:20:532: ResolveUncachedSsids[FAILed]: <WISP-MSFT> ==> Num=<0>, Error=<31>
[152] 15:56:20:532: ResolveUncachedSsids[FAILed]: <ZiM2-AP3> ==> Num=<0>, Error=<31>
[152] 15:56:20:542: ResolveUncachedSsids[FAILed]: <NDISTest_Cisco_AP2> ==> Num=<0>, Error=<31>
[152] 15:56:20:542: ResolveUncachedSsids[FAILed]: <reauthtest> ==> Num=<0>, Error=<31>
[152] 15:56:20:542: ResolveUncachedSsids[FAILed]: <Taroon802.11i> ==> Num=<0>, Error=<31>
[152] 15:56:20:542: ResolveUncachedSsids[FAILed]: <atheros11i> ==> Num=<0>, Error=<31>
[152] 15:56:20:542: [WZCCreateConfigList, NumEntries=<8>, Unique=<8>
//THE DRIVER RETURNS A LIST OF VISIBLE NETWORKS TO THE WIRELESS ZERO CONFIGURATION SERVICE. WE HAVE A TOTAL OF 8 DIFFERENT VISIBLE NETWORKS, 8 OF WHICH ARE UNIQUE. IGNORE THE “ERROR 31” MESSAGES.
...
[152] 15:56:20:542: [LstDeprecateBlockedList(0x000A9588)
[152] 15:56:20:542: LstDeprecateBlockedList]=0
//NOTHING HAS BEEN ADDED TO THE BLOCKED LIST
[152] 15:56:20:542: [LstBuildSelectList(0x000A9588)
[152] 15:56:20:542: LstBuildSelectList[0:1]: Flags=<3>, SSID==<8:DellTest> => (VP)
//HERE YOU CAN SEE ENTRIES FROM THE PREFERRED LIST. WE SEE THAT THERE IS 1 ENTRY, IT IS THE MOST PREFERRED, THERE IS ONLY 1 INSTANCE OF IT, AND IT IS VISIBLE AND PREFERRED.
...
[152] 15:56:20:542: [LstSetSelectResult {nsp=0,vsp=0,np=0,vp=1,sv=7}]
//A SUMMARY OF OUR SELECT LIST. IN THIS CASE, 1 VISIBLE PREFERRED NETWORK, AND 7 SKIPPED VISIBLE NETWORKS.
[152] 15:56:20:542: [WZCCopySelectedConfigs(000E5878->1/1, 0)
[152] 15:56:20:542: WZCCopySelectedConfigs[0]: SSID=<8:DellTest> From List
[152] 15:56:20:542: WZCCopySelectedConfigs]=0, NumCopied=<1>, Index=<1/1>
//OUR SELECT LIST ALONG WITH THE ORDER OF THE NETWORKS THAT THE WIRELESS ZERO CONFIGURATION SERVICE WILL ATTEMPT TO CONNECT TO. IN THIS CASE THERE IS ONLY 1 NETWORK CALLED “DellTest ”, AND IT HAS THE HIGHEST PRIORITY ORDER (0).
[152] 15:56:20:542: [LstChangedSelectList(0x000A9588)
[152] 15:56:20:542: SelList changed? YES; NumberOfItems = <0>==><1>
[152] 15:56:20:542: LstChangedSelectList]=TRUE
//THE WIRELESS ZERO CONFIGURATION SERVICE HAS DETERMINED THAT THE SELECT LIST IT JUST BUILT HAS CHANGED FROM THE PREVIOUS ONE. SO IT NOW PLUMBS A NEW CONFIGURATION TO THE DRIVER
...
[152] 15:56:20:542: Plumbing config 0
//THE WIRELESS ZERO CONFIGURATION SERVICE IS PLUMBING CONFIGURATION 0 (IN THIS CASE THIS CORRESPONDS TO “DELLTEST”)
...
[152] 15:56:20:542: WZCIsSameNetwork: Flags=<3/3> => <8:8>:<DellTest/DellTest>, Result=<3/1>==> MATCHed
[152] 15:56:20:542: Plumbing down the current SSID => skip the DHCP lease releasing
[152] 15:56:20:542: [LstSetSelectedConfig(0x000A9588..)
[152] 15:56:20:542: Plumbing down the User WEP txKey [idx:0,len:5]
//THE CONFIGURATION HAS A 5-CHARACTER (OR 40 BIT) WEP KEY
[152] 15:56:20:542: [DevioSetIntfOIDs(0x000A9588, 0x0086FDCC)
[152] 15:56:20:542: [DevioSetEnumOID(0x2290, 0xd010108, 1)
//THE WIRELESS ZERO CONFIGURATION SERVICE TELLS THE DRIVER IT IS AN INFRASTRUCTURE NETWORK
[152] 15:56:20:542: DevioSetEnumOID]=0
[152] 15:56:20:542: [DevioSetEnumOID(0x2290, 0xd010118, 0)
//AND THAT IT USES OPEN SYSTEM AUTHENTICATION
[152] 15:56:20:542: DevioSetEnumOID]=0
[152] 15:56:20:542: [DevioSetBinaryOID(0x2290,0xd01011d, 37 bytes,...)
[152] 15:56:20:542: [MemAlloc(41)=0x03D04EE8;0]
[152] 15:56:20:542: [MemFree(0x03D04EE8)]
[152] 15:56:20:542: DevioSetBinaryOID]=0
[152] 15:56:20:542: [DevioSetEnumOID(0x2290, 0xd01011b, 0)
[152] 15:56:20:542: DevioSetEnumOID]=0
[152] 15:56:20:542: [DevioSetBinaryOID(0x2290,0xd010102, 36 bytes,...)
[152] 15:56:20:542: [MemAlloc(40)=0x03C9BA38;0]
[152] 15:56:20:542: [MemFree(0x03C9BA38)]
[152] 15:56:20:542: DevioSetBinaryOID]=0
[152] 15:56:20:542: DevioSetBinaryOID[OID_802_11_SSID]: ===> < DellTest> <8 bytes>
//AND THE NETWORK’S SSID IS “DellTest”
...
[152] 15:56:20:542: [StateIterateFn:1020] --> SET_TIMER <2000>MSecs, Err=<0>
//THE WIRELESS ZERO CONFIGURATION SERVICE WILL WAIT 2 SECONDS FOR THE ASSOCIATION TO OCCUR.
...
[3364] 15:56:20:552: [WZCSvcWMIHandler(0x00DC2EE8)
//10 MILLISECONDS LATER THE WIRELESS ZERO CONFIGURATION SERVICE RECEIVES NOTIFICATION FROM WMI.
...
[152] 15:56:20:552: WZCNotif 5 for Device Key "{AB6A1A0A-F3E9-48F1-B28E-6749F7064F58}". Context=0x000A9588
//THE WIRELESS ZERO CONFIGURATION SERVICE HAS RECEIVED A MEDIA CONNECT FOR THE INTERFACE WITH GUID B6A1A0A-F3E9-48F1-B28E-6749F7064F58.
...
[152] 15:56:20:552: Requesting the refresh of the DHCP lease
//THE WIRELESS ZERO CONFIGURATION SERVICE MAKES A CALL TO DHCP FOR AN IP ADDRESS.
...
The following sections describe some of the more critical portions of the log that you typically analyze when trying to troubleshoot an association issue.
The Visible Networks Listing
The Wireless Zero Configuration service issues a scan request to the wireless network adapter driver whenever it is about to plumb a configuration, when the service first starts, and periodically every 60 seconds. If you are viewing the Wzctrace.log file with the Notepad accessory, find the string “AddNdis” and you will see something similar to the following:
[3880] 16:16:39:773: [WzcNdisToWzc=065EFE84->05D5E6D0
[3880] 16:16:39:773: [AddNdisEntriesToCache, NumCached=<0>
[3880] 16:16:39:773: AddNdisEntriesToCache: Flushing cache -- NumEntries= <0 + 0>
[3880] 16:16:39:773: AddNdisEntriesToCache]=0, (Dup=0) + Cached/ThisScan+Untouched= 0/11+0, CacheSize=<11>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: < PWLAN> ==> Num=<0>, Error=<31>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: <klinghagen.wifiG> ==> Num=<0>, Error=<31>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: < WLAN> ==> Num=<0>, Error=<31>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: <batabyal> ==> Num=<0>, Error=<31>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: <DANWEB> ==> Num=<0>, Error=<31>
[3880] 16:16:39:783: ResolveUncachedSsids[FAILed]: <indralog> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: ResolveUncachedSsids[FAILed]: <GOFAST> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: ResolveUncachedSsids[FAILed]: <Daniel_HN> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: ResolveUncachedSsids[FAILed]: <WA4GNI> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: ResolveUncachedSsids[FAILed]: < 4075> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: ResolveUncachedSsids[FAILed]: < w-net> ==> Num=<0>, Error=<31>
[3880] 16:16:39:793: [WZCCreateConfigList, NumEntries=<11>, Unique=<11>
[3880] 16:16:39:793: [MemAlloc(7620)=0x05A31008;0]
[3880] 16:16:39:793: IEPParseSSNIE[22 bytes]: Auth = 4; Priv = 4; OneX = 16.
[3880] 16:16:39:793: WZCCreateConfigList]=05A31008, Num=<11>
[3880] 16:16:39:793: WzcNdisToWzc]=05A31008, NumEntries=<11
The bolded line indicates that a total of 11 Service Set Identifier (SSID) beacons were reported by the wireless network adapter driver, and 11 of those are unique. The total number (“NumEntries”) means each of those have a unique Basic SSID (BSSID) (the MAC address of the wireless AP's wireless network adapter) but may not have unique SSIDs. The “Unique” number refers to the number of distinct SSIDs. It is important to make the distinction that this is only what the driver is reporting to the Wireless Zero Configuration service, and not necessarily what might be within range.
For example, if the “Unique” number is less than the “NumEntries”, it means that are multiple BSSIDs (MAC addresses) that share the same SSID. In other words, there are multiple wireless APs for the same wireless network that are within range of the wireless client. An example of this might be if you saw “NumEntries” = 2 and “Unique” = 1, indicating there are two BSSIDs sharing the same SSID (that is, there two wireless APs advertising the same SSID).
Note: It is safe to ignore the “FAILed” and “Error=<31>" messages in this section of the Wzctrace.log file.
Seeing What’s in the Preferred List
Search for the string "SelectList" in the Wzctrace.log file and you will see something similar to the following:
[3804] 23:30:53:154: [LstBuildSelectList(0x000A8358)
[3804] 23:30:53:154: LstBuildSelectList[0:0]: Flags=<0>, SSID==<4:test> => (P)
[3804] 23:30:53:154: LstBuildSelectList[1:0]: Flags=<0>, SSID==<12:youCantSee> => (P)
[3804] 23:30:53:154: LstBuildSelectList[2:1]: Flags=<0>, SSID==<8:EXAMPLELAN> => (VP)
This section of the Wzctrace.log file displays the preferred wireless networks list for this interface. Notice the bracketed numbers of for each entry (for example [2:1]). The first number denotes the preference order for that wireless network, 0 being the highest (most preferred). The second number denotes the number of instances of this wireless network. Typically, if the wireless network is visible, this is only 1, but may be greater for Wireless Provisioning Services (WPS) deployments.
The letters “P” (preferred) and “VP” (visible preferred) following each SSID denotes whether the 802.11 Beacon frame was visible in the last scan. In this example, there are three entries in the preferred list. In order of most preferred to least preferred, they are: “test”, “youCantSee”, and “EXAMPLELAN”. The only visible network is EXAMPLELAN. Note that SSIDs names are truncated in the log to 10 characters (except for the visible networks listing).
Variations You May See in the Preferred List
In the case of hidden SSIDs, you may see the notation of “(V..P)”, instead of “VP”. This denotes that the SSID is hidden, but because it is the currently connected SSID, the Wireless Zero Configuration service treats it as visible. The following log excerpt shows an example:
[3468] 07:53:41:368: [LstBuildSelectList(0x000B86D0)
[3468] 07:53:41:368: LstBuildSelectList[0:0]: Flags=<0>, SSID==<7:linksys> => (P)
[3468] 07:53:41:368: LstBuildSelectList[1:1]: Last Visible SSID==<4:west> ==> (V..P)
[3468] 07:53:41:368: LstBuildSelectList[2:0]: Flags=<0>, SSID==<10:wireless-a> => (P)
[3468] 07:53:41:368: LstBuildSelectList[3:0]: Flags=<0>, SSID==<7:ldshome> => (P)
Building a Select List
The Wireless Zero Configuration service uses the Select List to determine the order of networks to which it will attempt to connect, in the specified order. To view the Select List in the log, search for the "WZCCopy" string. The following log excerpt shows an example:
[3320] 23:31:56:184: [LstBuildSelectList(0x000A8358)
[3320] 23:31:56:184: LstBuildSelectList[0:0]: Flags=<0>, SSID==<4:test> => (P)
[3320] 23:31:56:184: LstBuildSelectList[1:0]: Flags=<0>, SSID==<12:youCantSee> => (P)
[3320] 23:31:56:184: LstBuildSelectList[2:1]: Flags=<0>, SSID==<8:EXAMPLELAN> => (VP)
[3320] 23:31:56:184: [MemAlloc(2144)=0x0427FD90;0]
[3320] 23:31:56:184: [LstSetSelectResult {nsp=0,vsp=0,np=2,vp=1,sv=22}]
[3320] 23:31:56:184: [WZCCopySelectedConfigs(03BEB3E8->3/3, 0)
[3320] 23:31:56:184: WZCCopySelectedConfigs[1]: SSID=<4:test> From List
[3320] 23:31:56:184: WZCCopySelectedConfigs[2]: SSID=<12:youCantSee> From List
[3320] 23:31:56:184: WZCCopySelectedConfigs[0]: SSID=<8:EXAMPLELAN> From List
The bolded numbers for "WZCCopySelectedConfigs" indicate the order of the networks (0 being of highest priority) that the Wireless Zero Configuration service will attempt to connect to. In this example, the order is: “EXAMPLELAN”, “test”, and then “youCantSee”.
The bolded line “{nsp=0,vsp=0,np=2,vp=1,sv=22}” is a summary count of the Select List, determined by the entries in the Preferred List and the Visible Networks List. In this case, there are two non-visible (“np”) networks, one visible preferred (“vp”) network, and 22 skipped visible ("sv") networks. The following are definitions for each notation:
NSP = "Non-visible Skipped Preferred". For example, skipped networks could be those set to Manual or On-demand, or have been filtered out due to the user having chosen to only connect to either ad hoc or infrastructure wireless networks and there are ad hoc or infrastructure configurations in the Preferred List (but are not visible).
VSP = "Visible Skipped Preferred". For example, the user has chosen to only connect to ad hoc or infrastructure networks, but ad hoc or infrastructure networks are both visible and in the Preferred List.
NP = "Non-visible Preferred". For example, network configurations that are in the Preferred List but are not visible.
VP = "Visible Preferred". For example, network configurations that are both in the Preferred List and are visible.
SV = "Skipped Visible". For example, visible networks that are not in the Preferred List. If the Connect to non-preferred networks checkbox were selected, this would be equal to 0.
Plumbing a Configuration
After building the Select List, the Wireless Zero Configuration service will start plumbing the configurations in the order mandated in the Select List. This is one of the more useful sections of the log to look at because this is the moment that the Wireless Zero Configuration service instructs the wireless network adapter driver what settings to configure (such as SSID, authentication type, encryption method, etc.)
From this section of the log, you can determine connection settings and behaviors such as the settings that a wireless network configuration has (such as authentication type), the last wireless network the wireless client was connected to, whether the associated was successful, whether the Wireless Zero Configuration service called DHCP to obtain an IP address configuration, etc.
To view the plumbing of a configuration in the log, search for the "plumb" string. The following log excerpt shows an example:
[2940] 00:28:48:391: Plumbing config 0
[2940] 00:28:48:391: [MemFree(0x00000000)]
[2940] 00:28:48:391: [WzcNetmanNotify(0x000A8358)
[2940] 00:28:48:391: WzcNetmanNotify]=0
[2940] 00:28:48:391: WZCIsSameNetwork: Flags=<0/c0> => <8:0>:<EXAMPLELAN/__________>, Result=<0/1>==> NOT MATCHed
//THIS IS A CHECK TO SEE IF THE LAST NETWORK WE WERE CONNECTED TO IS THE SAME AS THE ONE WE ARE CONSIDERING TO PLUMB DOWN NOW. THE SSID ON THE LEFT IS THE ONE TO BE PLUMBED, THE ONE ON THE RIGHT IS WHAT WE WERE/ARE CONNECTED TO (HOWEVER, THIS LEFT/RIGHT ORDER IS ONLY TRUE FOR THE “WZCIsSameNetwork” FUNCTION IN THE CONTEXT OF PLUMBING A CONFIGURATION)
...
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd010108, 1)
//0xd010108 is OID_802_11_INFRASTRUCTURE_MODE, 1 MEANS INFRASTRUCTURE MODE
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd010118, 0)
//0xd010118 is OID_802_11_AUTHENTICATION_MODE, 0 MEANS OPEN AUTHENTICATION
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd01011b, 0)
//0xd01011b is OID_802_11_WEP_STATUS, 0 MEANS WEP
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetBinaryOID(0x125c,0xd010102, 36 bytes,...)
[2940] 00:28:48:391: [MemAlloc(40)=0x036CE0D0;0]
[2940] 00:28:48:391: [MemFree(0x036CE0D0)]
[2940] 00:28:48:391: DevioSetBinaryOID]=0
[2940] 00:28:48:391: DevioSetBinaryOID[OID_802_11_SSID]: ===> < EXAMPLELAN> <8 bytes>
//THE SSID BEING PLUMBED DOWN, “EXAMPLELAN” IN THIS CASE
[2940] 00:28:48:391: DevioSetIntfOIDs]=0
[2940] 00:28:48:391: LstSetSelectedConfig]=0
[2940] 00:28:48:391: [StateIterateFn:1026] --> SET_TIMER <2000>MSecs, Err=<0>
//THE WIRELESS ZERO CONFIGURATION SERVICE GIVES 2 SECONDS FOR AN ASSOCIATION TO OCCUR
...
[628] 00:28:48:431: WZCNotif 5 for Device Key "{5F5126F1-A29C-440B-B5B4-90DE677409ED}" Context=0x000A8358
//A MEDIA CONNECT EVENT
...
[628] 00:28:48:441: Sending WZCNOTIF_WZC_CONNECT notification (SessHdl 12)
//A WZC_CONNECT NOTIFICATION IS SENT TO THE UPPER LAYER (802.1X IN THIS CASE)
[628] 00:28:48:441: Requesting the refresh of the DHCP lease
//THE WIRELESS ZERO CONFIGURATION SERVICE CALLS DHCP
The following sections describe some of the key things to look for first.
Which SSID is Being Plumbed
"Plumbing config x", in which x is the number of the entry in the Select List. Does the configuration being plumbed match with the expected Select List iteration behavior?
The GUID
Used to ensure that you are looking at the correct wireless network adapter if there are multiple wireless network adapters. You can usually match up the GUID with a more human-readable description of the interface at the beginning of the log. If the log has been overwritten due to lengthy activity, try looking in the .old version or perform a search for "GUID" in the Eapol.log file.
OIDs Being Set
The act of plumbing a configuration is done by the Wireless Zero Configuration service instructing the wireless network adapter driver to set certain values via Network Device Interface Specification (NDIS) object identifier (OID) function calls. It is important to verify that the OID values being set by the Wireless Zero Configuration service match with what is being expected. Definitions of the hexadecimal values for the OIDs and their parameters are listed in Table 2.
Table 2 OIDs and their parameters
OID |
Possible values |
|---|---|
(0xd010108) -> OID_802_11_INFRASTRUCTURE_MODE |
0: Non-infrastructure 1: Infrastructure |
(0xd010118) -> OID_802_11_AUTHENTICATION_MODE |
0: Open authentication 1: Shared authentication 3: WPA 4: WPA-PSK 5: WPA-NONE 6: WPA2 7: WPA2-PSK |
(0xd01011b) -> OID_802_11_WEP_STATUS |
0: DEFAULT (WEP) 1: NO ENCRYPTION 3: WEP NOT SUPPORTED 4: TKIP 6: AES |
(0xd010102) -> OID_802_11_SSID |
|
(0xd01011d) -> OID_802_11_ADD_KEY |
|
(0xd010113) -> OID_802_11_ADD_WEP |
|
Association Attempt Time Out
A successful association must occur within two seconds. The following log excerpt shows an example:
[1368] 16:15:47:549: [StateIterateFn:1020] --> SET_TIMER <2000>MSecs, Err=<0>
[1368] 16:15:47:549: StateIterateFn]=0
[1368] 16:15:47:549: StateDispatchEvent]=0
[1368] 16:15:47:549: [LstRccsUnlockUnref(0x043C9BC8)
[1368] 16:15:47:549: LstRccsUnlockUnref 0x043C9BC8.refCount=1
[1368] 16:15:47:549: LstRccsUnlockUnref]=0
[1368] 16:15:47:549: WZCSvcTimeoutHandler=0]
[1368] 16:15:49:562: [WZCTimeoutCallback(0x043C9BC8)
[1368] 16:15:49:562: [LstRccsReference(0x043C9BC8)
[1368] 16:15:49:562: LstRccsReference 0x043C9BC8.refCount=1
[1368] 16:15:49:562: LstRccsReference]=0
[1368] 16:15:49:562: WZCTimeoutCallback=0]
An association time out can indicate that the wireless AP is not responding. Common reasons for this are the following:
The wireless AP is not within range.
The wireless AP is ignoring the association frames from the wireless client (for example, MAC filtering).
The wrong OIDs were set (for example, user misconfiguration).
The wireless AP or wireless client network adapter radio is malfunctioning.
The wireless network adapter driver is malfunctioning. For example, the wireless AP has responded, but the driver is not reporting the media connect event to the Wireless Zero Configuration service. Short of using a wireless sniffer to capture the actual wireless frames sent by both the wireless client and the wireless AP, there might be no definite way of determining if this is the issue.
Media Connect
Possible values for media events are listed in Table 3.
Table 3 Values for Media Events
Media Connect value |
Meaning |
|---|---|
0 |
Unknown |
1 |
Device arrival |
2 |
Device removal |
3 |
Adapter bind |
4 |
Adapter unbind |
5 |
Media connect |
6 |
Media disconnect |
7 |
WZC connect (a WZC_connect event is generated when we have connected to a network for the first time after “plumbing” a configuration) |
8 |
Media specific |
A media event type 5 corresponds to a media connect, indicating a successful association.
You can view the media events in the Wzctrace.log file by searching for the "wzcnot" string. The typical order of events from when the Wireless Zero Configuration service first initializes from a system restart or service start to connecting are: Device Arrival, Adapter Bind, Media Connect. The reverse order when shutting down is Media Disconnect, Adapter Unbind, and Device Removal.
It can be useful to search for all the media events with the "wzcnot" search string to learn the association behavior of the wireless client. This technique can be especially useful for detecting a wireless network adapter driver that is logging spurious media connects or is unexpectedly roaming between multiple wireless APs within range. This technique is also useful for quickly finding the location in the log at which a suspend and resume has occurred. In this case, you would see a quick succession of media events 4 and 2 when suspending, then 1 and 3 when resuming.
DHCP
After a media connect, the Wireless Zero Configuration service makes a call to the DHCP client to obtain an IP address configuration. At this point, the Wireless Zero Configuration service has completed the 802.11 association. If you determine that the 802.11 association completes successfully, then you can begin to troubleshoot the 802.1X authentication as needed.
Tracking User Interaction
There are times when you need to find out when the user has changed wireless configuration through the Wireless Networks tab or displayed the View Available Networks or Choose a wireless network dialog boxes.
To determine whether a user has displayed the View Available Networks or Choose a wireless network dialog boxes, search for the “RpcQueryInterface” string in the Wzctrace.log file. To determine whether a user has changed wireless configuration through the Wireless Networks tab or connected to a wireless network through the View Available Networks or Choose a wireless network dialog boxes, search for the “RpcSetInterface” string.
Common Problems with 802.11 Association
The following are common problems with 802.11 association:
Driver problems
Inability to connect
Getting on the blocked list
Driver Problems
Sometimes problems with a wireless network adapter driver are easily found in the logs, and usually this occurs when an OID is set (but can also happen on an OID query). Search the Wzctrace.log file for the “DevioSet” of "DevioQuery" strings. If you see the function returning with anything other than a 0, such as a 21 (not ready) or 31 (general failure) or an assert message, then this indicates a driver problem. The following log excerpt shows and example of when a wireless network adapter has problems:
[2648] 14:27:28:481: [DevioQueryBinaryOID(0x2378, 0x1010102)
[2648] 14:27:28:481: [MemFree(0x00000000)]
[2648] 14:27:28:481: [MemAlloc(36)=0x03C3B390;0]
[2648] 14:27:28:481: [MemFree(0x03C3B390)]
[2648] 14:27:28:481: DevioQueryBinaryOID]=21
[2648] 14:27:28:481: DevioGetIntfMac]=21
[2648] 14:27:28:481: ##Assert state.c:380## DevioGetIntfMac failed for Intf context 0x03C6DA58
Notice that the function call returns 21 (not ready) as well as the assert message. You can look up return codes in the winerror.h file or you can use the Errlook.exe tool if you have installed Visual Studio 2003.
An exception to this rule in the Wzctrace.log file is during the capabilities check of the wireless network adapter. The capabilities check is performed after a device becomes available and is used to determine the authentication and encryption capabilities of the wireless adapter. The capabilities check sets certain OIDs to check for incompatibles. During the check, you may see different error codes that usually map to an "unsupported" error message. These errors aren't indicative of a driver problem, unless there is an assert messages. Search for the “capabilities” string. The following is a log excerpt showing the capabilities check:
[3880] 16:16:35:887: [DevioGetCapabilities(0x000FD4D0)
[3880] 16:16:35:887: [DevioGetCapSSN(0x000FD4D0)
[3880] 16:16:35:887: [DevioSetEnumOID(0x1c74, 0xd010118, 3)
[3880] 16:16:35:897: DevioSetEnumOID]=0
[3880] 16:16:35:897: [DevioQueryEnumOID(0x1c74, 0xd010118)
[3880] 16:16:35:897: DevioQueryEnumOID]=0
[3880] 16:16:35:897: DevioGetCapSSN=0x00000100]=0
[3880] 16:16:35:897: [DevioGetCapMaxCipher(0x000FD4D0)
[3880] 16:16:35:897: [DevioSetEnumOID(0x1c74, 0xd01011b, 6)
[3880] 16:16:35:897: Err: IOCTL_NDISUIO_SET_OID_VALUE->50
[3880] 16:16:35:897: DevioSetEnumOID]=50
[3880] 16:16:35:897: [DevioSetEnumOID(0x1c74, 0xd01011b, 4)
[3880] 16:16:35:907: DevioSetEnumOID]=0
[3880] 16:16:35:907: [DevioQueryEnumOID(0x1c74, 0xd01011b)
[3880] 16:16:35:907: DevioQueryEnumOID]=0
[3880] 16:16:35:907: DevioGetCapMaxCipher=0x00000104]=0
[3880] 16:16:35:907: [DevioSetBinaryOID(0x1c74,0xd01011d,...)
[3880] 16:16:35:907: [MemAlloc(68)=0x0015B658;0]
[3880] 16:16:35:907: Err: IOCTL_NDISUIO_SET_OID_VALUE->87
[3880] 16:16:35:907: [MemFree(0x0015B658)]
[3880] 16:16:35:907: DevioSetBinaryOID]=87
[3880] 16:16:35:907: Checked OID_.._ADD_KEY; err=0; cap=0x00000104
[3880] 16:16:35:907: [DevioQueryBinaryOID(0x1c74, 0xd01011f)
[3880] 16:16:35:907: [MemFree(0x00000000)]
[3880] 16:16:35:907: [MemAlloc(44)=0x028C2558;0]
[3880] 16:16:35:907: DevioQueryBinaryOID]=0
[3880] 16:16:35:907: [MemFree(0x028C2558)]
[3880] 16:16:35:907: Checked OID_.._ASSOC.._INFO..; err=0; cap=0x00000104
[3880] 16:16:35:907: DevioGetCapabilities=0x00000104]=0
[3880] 16:16:35:907: StateHardResetFn]=1246
Notice the bolded errors. The return error codes 50 and 87 map to “not supported” and “invalid parameter” respectively.
Note: For Windows XP SP2, faulty wireless network adapter drivers are typically the root cause of many wireless issues. The reason is the new WPA capabilities check performed by the Wireless Zero Configuration service, which was introduced in the Wireless update rollup package for Windows XP. Users with Windows XP SP1 that do not have the Wireless update rollup package installed that upgrade to Windows XP SP2 can experience problems. The most immediate solution is to obtain and install the latest version of the wireless network adapter driver.
Inability to Connect
An inability to connect for an 802.11 association, which is different than completing an association and then being disconnected for failing the 802.1X authentication, is most likely due to a configuration mismatch between the wireless client and the wireless AP. The mismatch might be in the form of different authentication settings, incompatible equipment, or other configuration issues. To troubleshoot this issue, go through the Wzctrace.log file to determine if what is being plumbed by the Wireless Zero Configuration service is what you expect.
A good place to start looking for mismatched configuration in the Wzctrace.log file is when the Wireless Zero Configuration service plumbs the configuration. The following log excerpt shows an example:
[2940] 00:28:48:391: Plumbing config 0
[2940] 00:28:48:391: [MemFree(0x00000000)]
[2940] 00:28:48:391: [WzcNetmanNotify(0x000A8358)
[2940] 00:28:48:391: WzcNetmanNotify]=0
[2940] 00:28:48:391: WZCIsSameNetwork: Flags=<0/c0> => <8:0>:<EXAMPLELAN/__________>, Result=<0/1>==> NOT MATCHed
...
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd010108, 1)
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd010118, 0)
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetEnumOID(0x125c, 0xd01011b, 0)
[2940] 00:28:48:391: DevioSetEnumOID]=0
[2940] 00:28:48:391: [DevioSetBinaryOID(0x125c,0xd010102, 36 bytes,...)
[2940] 00:28:48:391: [MemAlloc(40)=0x036CE0D0;0]
[2940] 00:28:48:391: [MemFree(0x036CE0D0)]
[2940] 00:28:48:391: DevioSetBinaryOID]=0
[2940] 00:28:48:391: DevioSetBinaryOID[OID_802_11_SSID]: ===> < EXAMPLELAN> <8 bytes>
Verify that the OIDs are being set with the correct or expected configuration settings. For example, if you have configured WEP on your wireless AP, but the log contents show that the Wireless Zero Configuration service is plumbing down a WPA/TKIP configuration, you know there is a configuration mismatch. You can also verify the SSID that is being plumbed.
For example, if you have two wireless networks in your preferred list the wireless client is within range of wireless APs for both networks, but one of the wireless APs is using a hidden SSID and the other is not, then the Wireless Zero Configuration service will always attempt to connect to the visible network first, regardless of whether the hidden wireless network is higher in the preference order. In such cases, it might also be necessary to examine the Wzctrace.log file and check the Visible Networks List, the Preferred List, and the Select List.
If you see that the configuration that is being plumbed is correct, then most likely you will also see that after plumbing the configuration the Wireless Zero Configuration service times out while waiting for a response from the wireless AP. This situation and possible causes is described in the “Plumbing a Configuration” section of this article.
Note: The following is an issue in Windows XP SP2: if you try to connect to a new wireless network (that is, is not in your Preferred List) from the Choose a wireless network dialog box and the wireless AP is configured for shared key authentication, you will receive the following error message:
.gif "sgwdat01.gif")
Unfortunately, the reason cited for the inability to connect and the workaround is incorrect because according to the IEEE 802.11 specification, SSID beacons do not advertise whether the wireless AP is capable of doing open system or shared key authentication. The default configuration of a new wireless network when connecting from the Choose a wireless network dialog box is for open system authentication when the Beacon frame does not contain any other authentication capabilities. Because the wireless AP requires shared key authentication, the association fails. To correct this problem, manually configure the wireless network to perform shared key authentication.
Intermittent Connectivity
There are several reasons why you may be experiencing intermittent connectivity. The most common scenario is an automatic disconnect about every 3 minutes. In this case, the most likely reason is that 802.1X authentication is enabled for wireless network that does not support 802.1X authentication. You can disable 802.1X authentication, which is enabled by default, from the Authentication tab for the properties of a wireless network. Clear the Enable IEEE 802.1X authentication for this network check box. Figure 1 shows the Authentication tab.
.gif "Figure 1. 802.1X authentication enabled")
Figure 1. 802.1X authentication enabled
If you are unable to check the Authentication tab, you can inspect the Wzctrace.log and Eapol.log files. The following are excerpts of the Wzctrace.log and Eapol.log files showing a wireless network has been configured with a valid WEP key but 802.1X authentication is also enabled. However, the wireless AP does not support 802.1X authentication.
The following is an excerpt from the Wzctrace.log:
[1368] 14:22:09:389: Plumbing config 0
...
[1368] 14:22:09:389: Plumbing down the User WEP txKey [idx:0,len:5]
...
[1368] 14:22:09:389: [DevioSetEnumOID(0x1f30, 0xd010108, 1)
...
[1368] 14:22:09:389: [DevioSetEnumOID(0x1f30, 0xd010118, 0)
...
[1368] 14:22:09:389: [DevioSetBinaryOID(0x1f30,0xd01011d, 37 bytes,...)
...
[1368] 14:22:09:389: [DevioSetEnumOID(0x1f30, 0xd01011b, 0)
...
[1368] 14:22:09:389: [DevioSetBinaryOID(0x1f30,0xd010102, 36 bytes,...)
...
[1368] 14:22:09:389: DevioSetBinaryOID]=0
[1368] 14:22:09:389: DevioSetBinaryOID[OID_802_11_SSID]: ===> < DellTest> <8 bytes>
...
[1368] 14:22:09:409: WZCNotif 5 for Device Key "{AB6A1A0A-F3E9-48F1-B28E-6749F7064F58}". Context=0x03423578
...
[1368] 14:22:09:419: Sending WZCNOTIF_WZC_CONNECT notification (SessHdl 126)
The association is successful. Next, we need to look in the Eapol.log file at the time 14:22:09:419, which is when the WZC Connect event was passed from the Wireless Zero Configuration service to the 802.1X components. If we suspect that 802.1X is enabled, then we need to look for the 802.1X state machine running through states.
The expected behavior for this scenario would be for 802.1X to stay in the Connecting state for 1 minute waiting for a Request ID message from the authenticator (the wireless AP). The 802.1X component does this three times, and then it moves to the Authenticated state. The 802.1X component marks the attempt as failed since no reply from an authenticator was received, disconnects, and then does it all over again until 3 consecutive failures have occurred. The Wireless Zero Configuration service blocks the wireless network and no further connection attempts are made.
The following is an excerpt from the Eapol.log:
[1576] 14:22:09:419: ElMediaEventsHandler entered -- EventType=<7>
//THE 802.1X COMPONENT RECEIVES THE WZC CONNECT EVENT FROM THE WIRELESS ZERO CONFIGURATION SERVICE
...
[1576] 14:22:09:439: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT SETS STATE CONNECTING
...
[2908] 14:23:09:505: ElTimeoutCallbackRoutine entered
//1 MINUTE HAS PASSED WITHOUT RECEIVING A REQUEST ID PACKET
...
[2908] 14:23:09:505: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT SETS STATE CONNECTING
...
[1848] 14:24:09:682: ElTimeoutCallbackRoutine entered
//1 MINUTE HAS PASSED WITHOUT RECEIVING A REQUEST ID PACKET
...
[1848] 14:24:09:682: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT SETS STATE CONNECTING
...
[1368] 14:25:09:738: ElTimeoutCallbackRoutine entered
//1 MINUTE HAS PASSED WITHOUT RECEIVING A REQUEST ID PACKET
...
[1368] 14:25:09:738: FSMConnecting: Sent out maxStart with no response, Setting AUTHENTICATED state
...
[1368] 14:25:09:738: Setting state AUTHENTICATED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT SETS STATE AUTHENTICATED AS 3 EAPOL START PACKETS WERE SENT WITH NO REPONSE
[1368] 14:25:09:738: FSMAuthenticated: fIsRemoteEndEAPOLAware=<0>, dwWaitForKeys=<1>
[1368] 14:25:09:738: EAPOL-Key for transmit key *NOT* received within 5 seconds in AUTHENTICATED state
[1368] 14:25:09:738: EAPOL Failure: Fail Count = 1
//THE 802.1X COMPONENT COUNTS 1 FAILURE
...
[1368] 14:25:09:818: ElMediaEventsHandler entered -- EventType=<6>
...
[1368] 14:25:09:818: Setting state DISCONNECTED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT DISCONNECTS
If the intermittent connectivity is occurring at irregular intervals, then the issue is most likely not related to having 802.1X enabled for a wireless AP that does not use 802.1X authentication. For intermittent connectivity, look through the Wzctrace.log for unexpected media disconnects. Unexpected media events are those that occur outside of any context in which it is expected that the Wireless Zero Configuration service or the 802.1X would issue a disconnect. Examples of expected disconnects are when the Wireless Zero Configuration service is already connected and plumbs a different configuration, when the Wireless Zero Configuration service is transitioning to a more preferred network, and when 802.1X fails authentication.
Getting on the Blocked List
Sometimes a wireless network is inadvertently put on the Wireless Zero Configuration service Blocked List, most commonly because of 802.1X authentication (either user or computer authentication) failing for some reason. After three failures, the 802.1X component instructs the Wireless Zero Configuration service to put the wireless network on an internal Blocked List and no more automatic connection attempts will be made to that wireless network. The Blocked List prevents a computer with bad credentials from continually attempting authentication over a long period of time, and impacting the performance of a RADIUS server.
The ways in which a wireless network can get on to the Blocked List are the following:
Three consecutive 802.1X authentication failures (user or computer authentication)
A WPA-PSK password mismatch
The 802.1X authentication has passed, but encryption keys are not received within 5 seconds in the authenticated state
The wireless network adapter driver returns an error while plumbing the configuration
The ways to clear the Blocked List are the following:
Disable and then enable the wireless network adapter (in Windows XP SP2, you can use the Repair feature)
Stop and then start the Wireless Zero Configuration or Wireless Configuration service
For PC Card or USB-based wireless network adapters, eject or disconnect and then insert of connect the wireless network adapter
Logoff of Windows and then log on
If a wireless network is not connecting, it might be because the network has somehow been put on the Blocked List. When the Wireless Zero Configuration service places a network on the blocked list, it looks similar to the following excerpt in the Wzctrace.log file:
[240] 11:40:35:441: The upper layer directs this config to be deleted => obey
[240] 11:40:35:441: StateCfgRemoveFn[1]: Flags=<c>, SSID==<EXAMPLELAN> => BLOCKed
Part 2: 802.1X Authentication
The troubleshooting approach for 802.1X-authenticated wireless connections follows state-to-state transitions of the 802.1X Supplicant Machine, along with key pieces of information for particular states to determine the cause of an authentication problem. This method can be used to troubleshoot many types of 802.1X authentication issues.
When to Examine the Eapol.log File
IEEE 802.1X authentication is widely used and is the recommended authentication method for wireless enterprise scenarios. Typically, you should only begin examining the Eapol.log file after you have determined that the 802.11 association has succeeded and that the issue is related to 802.1X authentication. In most cases, you know that successful 802.11 association has occurred after the following:
The Wireless Zero Configuration service has plumbed the correct configuration.
The wireless network adapter driver passes a media connect event.
The Wireless Zero Configuration service sends a WZC_CONNECT event to 802.1X.
The typical steps for a successful 802.1X negotiation as seen in the Eapol.log file are the following:
Receive the WZC_CONNECT event (media event type 7) from the Wireless Zero Configuration service.
Transition to connecting state
Transition to acquired state
Several authenticating iterations
Transition to authenticated state
Receive unicast and group keys
Plumb the keys to the wireless miniport driver
Make a call to DHCP client for an IP address configuration
For information about the set of messages exchanged for a successful 802.1X negotiation, see IEEE 802.11 Wireless LAN Security with Microsoft Windows XP.
The 802.1X Supplicant State Machine
Figure 2 shows a slightly simplified version the 802.1X Supplicant State Machine. You might need to refer to this figure when performing 802.1X troubleshooting. Descriptions of each of the states and their transitional behaviors are provided in the following sections. For more information, see the “IEEE Standard for Local and metropolitan area networks – Port-Based Network Access Control” publication available from the IEEE.
.gif "Figure 2. The 802.1X Supplicant State Machine")
Figure 2. The 802.1X Supplicant State Machine
The 802.1X Supplicant State Machine can be described in terms of the following:
States
Variables
Constants
Procedures
The states section contains most of the useful information and you can refer to the other sections as needed.
Throughout the following sections, the supplicant is the wireless client and the authenticator is the wireless AP.
States
The following are the states of the 802.1X Supplicant State Machine:
LOGOFF
Entered if the user executes a logoff event. The supplicant sends an EAPOL-Logoff message to the authenticator.
DISCONNECTED
Entered when the system is first initialized or reinitialized, or from any state when the MAC service for the port in question is inoperable. Also entered from the LOGOFF state after the user executes a logoff. Once initialized and the port becomes enabled, it transitions to the CONNECTING state.
CONNECTING
Entered when the port has been enabled and the supplicant is trying to acquire an authenticator. The supplicant sends an EAPOL-Start message, increments a counter, and starts a timer. The timer (startWhen) is used for retransmission of the EAPOL-Start message for a maximum number of times defined by the variable maxStart. If the maximum number of retransmissions have been sent and an authenticator has not responded, the supplicant moves to the AUTHENTICATED state assuming that the authenticator is not EAPOL-aware. If a requested packet is received, the supplicant moves to the ACQUIRED state.
**ACQUIRED **
Entered whenever a requested message is received. The supplicant then sends an EAP-Response/Identity message, sets a timer (authWhile), and waits a certain amount of time (authPeriod) for an EAP-Request message. If the timer expires, the supplicant returns to the CONNECTING state in an effort to acquire the authenticator.
If an EAP-Request message other than an EAP-Request/Identity is received, the supplicant transitions to the AUTHENTICATING state. If an EAP-Request/Identity is again received while in this state, another EAP-Response/Identity is sent to the authenticator and the authWhile timer is reset.
**AUTHENTICATING **
In this state, the supplicant sends an EAP-Response message, sets a timer (authWhile) to a specific time-out period (authPeriod), and waits for either an EAP-Request, EAP-Success, or EAP-Failure message. This cycle is repeated whenever an EAP-Request message is received. The exception being when an EAP-Request/Identity is received, in which case the supplicant transitions to the ACQUIRED state. If the supplicant receives an EAP-Failure message, it moves to the HELD state. If the supplicant receives and EAP-Success message, the supplicant moves to the AUTHENTICATED state.
**HELD **
Entered whenever an EAP-Failure message is received from the authenticator. A timer (heldWhile) is then started for a specific amount of time (heldPeriod). When this timer expires, the supplicant moves to the CONNECTING state. If an EAP-Request/Identity is received in this state, the supplicant moves to the AQUIRED state.
AUTHENTICATED
The supplicant has received an EAP-Success message from the authenticator or has timed out from the CONNECTING state and assumed that the authenticator is not EAPOL-aware. If an EAP-Request/Identity packet is received, the supplicant moves to the AQUIRED state.
Variables
The following are the variables that control the behavior of the 802.1X Supplicant State Machine:
userLogoff
This variable has a value of either TRUE or FALSE, indicating whether the user is logged on or logged off, respectively.
logoffSent
This variable has a value of either TRUE or FALSE, indicating whether an EAPOL-Logoff message has been sent while in the LOGOFF state or not, respectively. This variable is used to prevent multiple transmissions of logoff messages.
requestID
This variable’s value is TRUE if the supplicant received an EAP-Request/Identity packet from the authenticator.
requestAuth
This variable’s value is TRUE if the supplicant received an EAP-Request packet (other than a Request/Identity) from the authenticator.
eapSuccess
This variable’s value is TRUE if the supplicant received an EAP-Success packet from the authenticator.
eapFail
This variable’s value is TRUE if the supplicant received an EAP-Failure packet from the authenticator.
eapolStartCount
This variable is a counter used to count the number of times an EAPOL-Start has been sent by the supplicant without receiving a response from the authenticator.
**Initialize **
This variable is externally controlled. If it is set to TRUE, all states in the supplicant state machine are initialized to their initial values and held there until this variable is set to FALSE.
**portEnabled **
This variable is externally controlled. Its value is TRUE if there exists a MAC service in an operable state for the port. Otherwise, its value is FALSE.
Constants
The following are the constants that control the behavior of the 802.1X Supplicant State Machine:
authPeriod The initial value for the authWhile timer. Default value is 30 seconds.
heldPeriod The initial value for the heldWhile timer. Default value is 60 seconds.
startPeriod The initial value for the startWhen timer. Default value is 30 seconds.
maxStart Represents the amount of times an EAPOL-Start message will be transmitted before the supplicant times out. Default value is 3.
Procedures
The following are the procedures that control the behavior of the 802.1X Supplicant State Machine:
transmitEapolStart(). Sends an EAPOL-Start message to the authenticator.
transmitLogoff(). Sends an EAPOL-Logoff message to the authenticator.
transmitRespondID(). Sends and EAP-Respond/Identity message to the authenticator.
transmitRespondAuth(). Sends an EAP-Respond packet (other than an EAP-Respond/Identity) to the authenticator.
Making Use of the State Machine
A good approach for 802.1X authentication troubleshooting is to analyze the contents of the Eapol.log file and follow the states in the log. Whenever you do not know why a particular state transition occurred, refer back to the state machine and its descriptions to determine why. This is preferable to trying to memorize the state machine and all the meanings of the states and transition conditions.
Reading Eapol.log
The steps that should be taken when first analyzing an Eapol.log file are:
Identify the time period of interest to examine (e.g. 9:30 AM to 10:30 AM). If you have followed the basic information gathering process, you should know approximately what time the problems occurred. Do not start reading a log from beginning to end if you can avoid it.
Quickly step through each states for the desired time period. Depending on the circumstances (for example, initial authentication, reauthentication, roaming, etc.), note whether the state transition order is what is expected. Note and analyze further any deviations from what is expected.
If needed, go back to the beginning of the time period and take note of key pieces of information at each state.
State Transitions
The following table lists common authentication scenarios and their corresponding set of state transitions. To determine if the problem is with 802.1X authentication, compare the state transitions in the Eapol.log file to the set of state transitions listed in Table 4.
Table 4 Common authentication scenarios and 802.1X state transitions
Scenario |
State Transitions |
Notes |
|---|---|---|
Authentication |
[wzc_connect] > CONNECTING > ACQUIRED > AUTHENTICATING (several) > AUTHENTICATED |
|
Re-authentication |
[any state] > ACQUIRED |
The Authenticator has sent a EAPOL Request-ID packet. |
Roaming |
[already AUTHENTICATED] > [media connect] > CONNECTING > ACQUIRED > AQUIRED ->AUTHENTICATING (several) > AUTHENTICATED or [already AUTHENTICATED] > ACQUIRED > [media connect] > CONNECTING > ACQUIRED > AUTHENTICATING (several) > AUTHENTICATED |
There is an extra ACQUIRED state because there are times when the new wireless AP has already sensed that the wireless client has roamed to it and decides to send out a EAPOL Request-ID packet without waiting for the wireless client to send an EAPOL-Start packet. This can occur either before or after the media connect event is received. In either case, an EAPOL-Start packet is still sent, which results in the wireless AP sending another EAPOL Request-ID packet. |
No authenticator on the other end |
CONNECTING > CONNECTING > CONNECTING > AUTHENTICATED (failure no keys received) |
|
You should refer to the 802.1X Supplicant State Machine for more information about state transition behavior.
An Example 802.1X Authentication
In this section, we will step through an 802.1X authentication process. We begin with a brief excerpt from the Wzctrace.log to ensure that the Wireless Zero Configuration service has set up the 802.11 association successfully. The following is a summarized excerpt of an example Wzctrace.log:
[3688] 16:34:40:206: Plumbing config 0
...
[3688] 16:34:40:206: Driver loaded its default WEP key successfully.
[3688] 16:34:40:206: [DevioSetIntfOIDs(0x000E1930, 0x0680FDCC)
[3688] 16:34:40:206: [DevioSetEnumOID(0x15ac, 0xd010108, 1)
[3688] 16:34:40:206: DevioSetEnumOID]=0
[3688] 16:34:40:206: [DevioSetEnumOID(0x15ac, 0xd010118, 0)
[3688] 16:34:40:206: DevioSetEnumOID]=0
[3688] 16:34:40:206: [DevioSetEnumOID(0x15ac, 0xd01011b, 0)
[3688] 16:34:40:206: DevioSetEnumOID]=0
[3688] 16:34:40:206: [DevioSetBinaryOID(0x15ac,0xd010102, 36 bytes,...)
...
[3688] 16:34:40:206: DevioSetBinaryOID[OID_802_11_SSID]: ===> < EXAMPLELAN> <8 bytes>
...
[3688] 16:34:40:276: WZCNotif 5 for Device Key "{FB630E90-59FC-47CA-815E-DC0B297B511C}".
...
[3688] 16:34:40:306: Sending WZCNOTIF_WZC_CONNECT notification (SessHdl 2)
...
[3688] 16:34:40:316: Sending WZC_CONFIG_NOTIF to upper level apps
In this excerpt, you can see that the Wireless Zero Configuration service plumbs a configuration set for infrastructure mode, open system authentication, default WEP encryption, and the SSID is “EXAMPLELAN”. This is correct for an association with a wireless network that uses 802.1X authentication. Notice that the Wireless Zero Configuration service has received media event 5 (media connect) indicating that 802.11 association has passed. Next, the Wireless Zero Configuration service informs the 802.1X component of the successful association with media event 7 (WZC_CONNECT) at the time 16:34:40:316.
Stepping Through the 802.1X States
You can quickly get an overview of what is happening for the 802.1X authentication by searching for the “Setting state" string in the Eapol.log file. By noting the set of transitions, you can see how the 802.1X Supplicant State Machine is being traversed.
The following excerpt is the corresponding 802.1X authentication process from the Eapol.log that is matched with the Wzctrace.log file previously described for a normal and successful EAP-TLS authentication (this excerpt has been shortened considerably to emphasize the 802.1X state changes):
[3688] 16:34:40:316: ElMediaEventsHandler entered -- EventType=<7>
[3688] 16:34:40:316: ElMediaEventsHandler: Calling ElZeroConfigEvent
//WE BEGIN AT TIME 16:34:40:316, THE POINT AT WHICH THE 802.1X COMPONENT RECEIVED A WZC_CONNECT
[3688] 16:34:40:316: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3688] 16:34:40:316: FSMConnecting completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT SENDS OUT AN EAPOL-START IN THIS STATE
...
[1272] 16:34:40:637: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1272] 16:34:40:637: FSMAcquired completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT RECEIVES A REQUEST-ID PACKET (OR ELSE THE 802.1X COMPONENT WOULD NOT HAVE MOVED TO THE ACQUIRED STATE)
...
[1272] 16:34:40:637: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1272] 16:34:40:637: FSMAcquired completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//THE 802.1X COMPONENT RECEIVES A REQUEST-ID PACKET (OR ELSE THE 802.1X COMPONENT WOULD NOT HAVE MOVED TO THE ACQUIRED STATE)
...
[1272] 16:34:46:405: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:455: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:485: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:555: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:575: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:615: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:916: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:46:986: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:48:068: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:48:098: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:48:288: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
...
[3688] 16:34:48:328: Setting state AUTHENTICATING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//SEVERAL AUTHENTICATION EXCHANGES
...
[3688] 16:34:48:328: Setting state AUTHENTICATED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport\
...
[1272] 16:34:48:328: ProcessReceivedPacket: != EAP_Packet
[1272] 16:34:48:328: ProcessReceivedPacket: == EAPOL_Key
//A KEY HAS BEEN RECEIVED
...
[1272] 16:34:48:328: KeyLength = 13, KeyIndex = 0
//IT IS THE UNICAST KEY
...
[1272] 16:34:48:338: ProcessReceivedPacket: != EAP_Packet
[1272] 16:34:48:338: ProcessReceivedPacket: == EAPOL_Key
//A KEY HAS BEEN RECEIVED
...
[1272] 16:34:48:338: KeyLength = 13, KeyIndex = 131
//IT IS THE GROUP KEY
...
[1272] 16:34:48:338: FSMKeyReceive: Port Opened by current key
//KEYS PLUMBED
...
[1272] 16:34:48:338: ElIPPnPWorker: DhcpNotifyMediaReconnected successful
//THE 802.1X COMPONENT CALLS DHCP FOR AN IP ADDRESS
...
This log excerpt shows a typical 802.1X authentication. Typically, if you see a deviation from this order of state transitions, you might have an issue. Examples of deviations might include going to the State Held state, transitioning from State Connecting to State Authenticated states directly, and cycling between states without progressing.
Example Logs for Unsuccessful 802.1X Authentications
This section contains example logs for unsuccessful 802.1X authentications for the following reasons:
An invalid user certificate
No certificate present
An Invalid User Certificate
The following excerpt from the Eapol.log file shows the log file contents for an EAP-TLS-based 802.1X authentication in which the user certificate is invalid:
[3152] 14:26:01:001: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3152] 14:26:01:001: FSMAcquired completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3152] 14:26:01:001: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3152] 14:26:01:001: ElReadFromPort entered
[3152] 14:26:01:001: ElReadFromPort: pPCB = 031C0F88, RefCnt = 3
[3152] 14:26:01:001: ProcessReceivedPacket: pPCB= 031C0F88, RefCnt = 3
[3152] 14:26:01:001: ProcessReceivedPacket exit
[808] 14:26:01:001: ElGetEapUserInfo: (pbEapBlob == NULL) && (dwEapBlob == 0)
[808] 14:26:01:001: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[808] 14:26:01:001: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2008] 14:26:01:051: ElGetEapUserInfo: (pbEapBlob == NULL) && (dwEapBlob == 0)
[2008] 14:26:01:051: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2008] 14:26:01:051: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2008] 14:26:01:933: ElGetEapUserInfo: (pbEapBlob == NULL) && (dwEapBlob == 0)
[2008] 14:26:01:933: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2008] 14:26:01:933: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2008] 14:26:02:714: RpcEapolUIResponse: Response function found, msg (1)
[2008] 14:26:02:714: TIMER: Restart PCB Time: 30
[2008] 14:26:02:714: ElProcessUserIdentityResponse: Got username = Administrator@example.microsoft.com
[2008] 14:26:02:714: ElCreateAndSendIdResp: EapolPkt created at 0319CED8
[2008] 14:26:02:714: ElCreateAndSendIdResp: Identity sent out = Administrator@example.microsoft.com
//THE USER IDENTITY IS BEING SENT OUT FOR AUTHENTICATION
[2008] 14:26:02:714: ElWriteToPort entered: Pkt Length = 34
[2008] 14:26:02:714: ElWriteToPort: pPCB = 031C0F88, RefCnt = 4
[2008] 14:26:02:714: ElWriteToInterface entered
[2008] 14:26:02:714: ElWriteToInterface completed, RetCode = 0
[2252] 14:26:02:734: ElIoCompletionRoutine called, 46 bytes xferred
[2252] 14:26:02:734: ElWriteCompletionRoutine sent out 46 bytes with error 0
[2252] 14:26:02:734: ElWriteCompletionRoutine: pPCB= 031C0F88, RefCnt = 3
[3152] 14:26:05:578: ElIoCompletionRoutine called, 22 bytes xferred
[3152] 14:26:05:578: ElReadCompletionRoutine entered, 22 bytes recvd
[3152] 14:26:05:578: ProcessReceivedPacket entered, length = 22
[3152] 14:26:05:578: ProcessReceivedPacket: EAP_Packet
[3152] 14:26:05:578: ProcessReceivedPacket: EAPOLSTATE_ACQUIRED
[3152] 14:26:05:578: TIMER: Restart PCB Time: 2097148
[3152] 14:26:05:578: ElProcessEapFail: Got EAPCODE_Failure
//THE 802.1X COMPONENT HAS RECEIVED AN EAP FAILURE
[3152] 14:26:05:578: ElEapEnd entered
[3152] 14:26:05:578: ElEapDllEnd called for EAP Index -1
[3152] 14:26:05:578: ElGetUserIdentity[UI]: dwEAPOLUIMsgType=<32>, dwEapId=<2>, dwEapTypeId=<d>, dwEapFlags=<0>
[3152] 14:26:05:578: WZCNetmanShowBalloon: Entered
[3152] 14:26:05:578: WZCNetmanShowBalloon: CoCreateInstance succeeded
[3152] 14:26:05:578: WZCNetmanShowBalloon completed
[3152] 14:26:05:578: WZCNetmanConnectionStatusChanged: Entered
[3152] 14:26:05:578: QueueEvent: CoCreateInstance succeeded
[3152] 14:26:05:578: ConnectionStatusChanged completed
[3152] 14:26:05:578: ElZeroConfigNotify: Handle=(2), failcount=(1), lastauthtype=(1)
//THE 802.1X COMPONENT INCREMENTS THE FAILURE COUNTER AND NOTIFIES THE WIRELESS ZERO CONFIGURATION SERVICE
[3152] 14:26:05:628: ElProcessEapFail: Called ElZeroConfigNotify with failcount = 1, prevauthtype = 1, type=(2)
[3152] 14:26:05:628: FSMHeld entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3152] 14:26:05:628: FSMHeld: EAP authentication failed with error 0x0
[3152] 14:26:05:628: Restarting Held timer with time value = 60
[3152] 14:26:05:628: FSMHeld: Setting state HELD for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3152] 14:26:05:628: FSMHeld[SSID]: Deleting user creds info on failure ...
[3152] 14:26:05:628: FSMHeld: Port {FB630E90-59FC-47CA-815E-DC0B297B511C} set to HELD state
[3152] 14:26:05:628: TIMER: Restart PCB Time: 60
[3152] 14:26:05:628: FSMHeld completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3152] 14:26:05:628: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3152] 14:26:05:628: ElReadFromPort entered
[3152] 14:26:05:628: ElReadFromPort: pPCB = 031C0F88, RefCnt = 3
[3152] 14:26:05:628: ProcessReceivedPacket: pPCB= 031C0F88, RefCnt = 3
[3152] 14:26:05:628: ProcessReceivedPacket exit
No Certificate Present
The following excerpt from the Eapol.log file shows the log file contents for an EAP-TLS-based 802.1X authentication in which there is no certificate present on the wireless client:
//BEGINNING AT THE POINT WHERE THE 802.1X COMPONENT RECEIVES A WZC_CONNECT EVENT
[2356] 16:02:59:912: ElMediaEventsHandler entered -- EventType=<7>
[2356] 16:02:59:912: ElMediaEventsHandler: Calling ElZeroConfigEvent
...
//HERE IS SOME USEFUL INFORMATION, THE WIRELESS AP’S MAC BSSID AND SSID
[2356] 16:02:59:912: ElCreatePort: ElNdisuioQueryOIDValue for OID_802_11_BSSID successful
[2356] 16:02:59:912: 00 40 96 31 12 1F 00 00 00 00 00 00 00 00 00 00 |.@.1............|
[2356] 16:02:59:912: ElCreatePort: prdUserData not valid
[2356] 16:02:59:912: ElCreatePort: Port Network Identifier:
[2356] 16:02:59:912: 4D 53 46 54 57 4C 41 4E 00 00 00 00 00 00 00 00 |EXAMPLELAN........|
...
//EAP TYPE 13 INDICATES EAP-TLS
[2356] 16:02:59:912: ElGetInterfaceParams: SsidLength=<8>, Found EapTypeId=<13>, SSIDLen=<8>
...
//BEGIN BY SEARCHING ON “SETTING STATE”. THE LOG IS NOT ABBREVIATED AND IS SHOW IN FULL. FOLLOW THE BOLDED STATES FIRST AND THEN JUMP TO THE BOLDED “SETTING STATE ACQUIRED”.
[2356] 16:02:59:912: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: FSMConnecting completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElCreatePort: Completed for GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C}, Name = Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: CreatePort successful
[2356] 16:02:59:912: ElCreateInterfaceEntry: Added to hash table GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C} : Desc= Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport at Index=0
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: Completed with retcode = 0
[2356] 16:02:59:912: ElIoCompletionRoutine called, 19 bytes xferred
[2356] 16:02:59:912: ElWriteCompletionRoutine sent out 19 bytes with error 0
[2356] 16:02:59:912: ElWriteCompletionRoutine: pPCB= 033767B8, RefCnt = 3
[2356] 16:02:59:912: ElIoCompletionRoutine called, 72 bytes xferred
[2356] 16:02:59:912: ElReadCompletionRoutine entered, 72 bytes recvd
[2356] 16:02:59:912: ProcessReceivedPacket entered, length = 72
[2356] 16:02:59:912: ProcessReceivedPacket: EAP_Packet
[2356] 16:02:59:912: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[2356] 16:02:59:912: TIMER: Restart PCB Time: 2097148
[2356] 16:02:59:912: FSMAcquired entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: TIMER: Restart PCB Time: 30
[2356] 16:02:59:912: ElEapEnd entered
[2356] 16:02:59:912: ElEapBegin entered
[2356] 16:02:59:912: ElEapBegin done
[2356] 16:02:59:912: ElEapWork: EapolPkt created at 064C2410
[2356] 16:02:59:912: ElEapMakeMessage entered
[2356] 16:02:59:912: ElParseIdentityString: DisplayString =
[2356] 16:02:59:912: ElParseIdentityString: LocalIdString = networkid=EXAMPLELAN,nasid=CUSRED040C3439,portid=0
[2356] 16:02:59:912: ElParseIdentityString: LocalIdString Length = 49
[2356] 16:02:59:912: ElParseIdentityString: NetworkID Size = 9
[2356] 16:02:59:912: Got NetworkId = EXAMPLELAN
[2356] 16:02:59:912: Got NASId = CUSRED040C3439
[2356] 16:02:59:912: ElParseIdentityString: For PortId, length = 1
[2356] 16:02:59:912: Got PortId = 0
[2356] 16:02:59:912: ElParseIdentityString: End of String reached
[2356] 16:02:59:912: ElParseIdentityString: Out of while loop
[2356] 16:02:59:912: ElParseIdentityString: Out of while loop: NO ERROR
[2356] 16:02:59:912: ElParseIdentityString: Calling NLARegister_802_1X with params {FB630E90-59FC-47CA-815E-DC0B297B511C} and networkid=EXAMPLELAN,nasid=CUSRED040C3439,portid=0
[2356] 16:02:59:912: NLARegister_802_1X: Entered
[2356] 16:02:59:912: NLAConnectLPC: Entered
[2356] 16:02:59:912: NLARegister_802_1X: g_hNLA_LPC_Port != NULL
[2356] 16:02:59:912: NLARegister_802_1X: Completed with status = 0
[2356] 16:02:59:912: ElParseIdentityString: Returned after calling NLARegister_802_1X
[2356] 16:02:59:912: ElGetIdentity: Userlogged, Prev !Machine auth
[2356] 16:02:59:912: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: !MD5
[2356] 16:02:59:912: ElGetUserIdentity entered
[2356] 16:02:59:912: ElGetEapUserInfo: (pbEapBlob == NULL) && (dwEapBlob == 0)
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:922: ElGetUserIdentityOptimized: Error in calling GetIdentity = 798
[2356] 16:02:59:922: ElGetUserIdentity[UI]: dwEAPOLUIMsgType=<1>, dwEapId=<30>, dwEapTypeId=<d>, dwEapFlags=<c0000000>
[2356] 16:02:59:922: WZCNetmanConnectionStatusChanged: Entered
[2356] 16:02:59:922: QueueEvent: CoCreateInstance succeeded
[2356] 16:02:59:922: ConnectionStatusChanged completed
[2356] 16:02:59:922: WZCNetmanShowBalloon: Entered
[2356] 16:02:59:922: WZCNetmanShowBalloon: CoCreateInstance succeeded
[2356] 16:02:59:922: WZCNetmanShowBalloon completed
[2356] 16:02:59:922: TIMER: Restart PCB Time: 2097148
[2356] 16:02:59:922: ElGetUserIdentity completed with error 997
[2356] 16:02:59:922: ElGetIdentity: Error in ElGetUserIdentity 997
[2356] 16:02:59:922: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: No Error: User Auth fine
[2356] 16:02:59:922: ElEapMakeMessage: Error in ElGetIdentity 997
[2356] 16:02:59:922: ElEapWork: ElEapMakeMessage returned error 997
[2356] 16:02:59:922: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
//WE HAVE MOVED FROM THE CONNECTING STATE TO THE ACQUIRED STATE, MEANING THAT THE WIRELESS CLIENT HAS RECEIVED AN EAPOL REQUEST-ID PACKET FROM THE WIRELESS AP.
//NOTE THE BOLDED ERROR 997, WHICH INDICATES “ERROR_IO_PENDING.” FOR AN EAP-TLS AUTHENTICATION, THIS ERROR INDICATES THAT NO CERTIFICATES ARE AVAILABLE OR A CERTIFICATE IS WAITING FOR USER INPUT (SUCH AS A PIN TO UNLOCK A SMARTCARD).
Important Information From the Eapol.log File
The Eapol.log file contains other pieces of information from the log that are useful for gathering information about the wireless connection. They are typically visible in the log file. The following sections show examples of determining information about the wireless connection while analyzing the Eapol.log file.
Access Point Information
There might be cases in which you need to identify the wireless AP to which the client station has associated. For example, you might want to know if you are roaming to a particular wireless AP, roaming in some expected manner, or you are trying to determine whether the wireless network adapter is cycling through a set of wireless APs.
There are three useful pieces of wireless AP information; the BSSID, the NASID, and the SSID (although the SSID is also recorded in the Wzctrace.log file). The BSSID and SSID are typically found somewhere between the initial media event (either WZC_CONNECT or MEDIA CONNECT) and before STATE CONNECTING has been set. The NASID is found somewhere after STATE CONNECTING and STATE ACQUIRED. These are bolded in the log excerpt found in the following section.
EAP Type
You might also need to determine the EAP type used for authentication. Search for the “EAPtype” string. Type 13 indicates EAP-TLS. Type 25 indicates PEAP. The EAP type is bolded in the following excerpt:
[2356] 16:02:59:912: ElMediaEventsHandler entered -- EventType=<7>
[2356] 16:02:59:912: ElMediaEventsHandler: Calling ElZeroConfigEvent
[2356] 16:02:59:912: ElGetInterfaceParams: SsidLength=<8>, Found EapTypeId=<13>, SSIDLen=<8>
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: DeviceDesc = , GUID = {FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: ElNdisuioEnumerateInterfaces: Opening handle
[2356] 16:02:59:912: NdisuioEnumerateInterfaces: NDISUIO bound to: (0) \DEVICE\{7BC47114-8B32-470B-A789-F69B9779A7CD}
- Intel(R) PRO/100 VE Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: NdisuioEnumerateInterfaces: NDISUIO bound to: (1) \DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}
- Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElNdisuioEnumerateInterfaces: DeviceIoControl IOCTL_NDISUIO_QUERY_BINDING has no more entries
[2356] 16:02:59:912: Device: \DEVICE\{7BC47114-8B32-470B-A789-F69B9779A7CD}
[2356] 16:02:59:912: Description: Intel(R) PRO/100 VE Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: Device: \DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: Description: Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: Found interface after enumeration \DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: Did NOT find PCB already existing for interface
[2356] 16:02:59:912: ElOpenInterfaceHandle: Opening handle for \DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: ElOpenInterfaceHandle: Trying to access NDIS Device: \DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: ElOpenInterfaceHandle: OpenIntfHandle(\DEVICE\{FB630E90-59FC-47CA-815E-DC0B297B511C}) = 9676
[2356] 16:02:59:912: ElOpenInterfaceHandle: Opened handle 000025CC with dwRetCode 0
[2356] 16:02:59:912: ElCreatePort: Entered for Handle=(000025CC), GUID=({FB630E90-59FC-47CA-815E-DC0B297B511C}), Name=(Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport), ZCId=(2), UserData=(0339AE3C) Notification=<4>
[2356] 16:02:59:912: ElCreatePort: No PCB found for {FB630E90-59FC-47CA-815E-DC0B297B511C}
[2356] 16:02:59:912: ElGetInterfaceNdisStatistics: pwszDeviceInterfaceName = (\Device\{FB630E90-59FC-47CA-815E-DC0B297B511C})
[2356] 16:02:59:912: ElCreatePort: ElNdisuioQueryOIDValue for OID_802_3_CURRENT_ADDRESS successful
[2356] 16:02:59:912: 00 0E 35 10 C5 81 00 00 00 00 00 00 00 00 00 00 |..5.............|
[2356] 16:02:59:912: ElCreatePort: ElNdisuioQueryOIDValue for OID_802_11_INFRASTRUCTURE_MODE successful, Mode = (1)
[2356] 16:02:59:912: ElCreatePort: ElNdisuioQueryOIDValue for OID_802_11_BSSID successful
[2356] 16:02:59:912: 00 40 96 31 12 1F 00 00 00 00 00 00 00 00 00 00 |.@.1............|
[2356] 16:02:59:912: ElCreatePort: prdUserData not valid
[2356] 16:02:59:912: ElCreatePort: Port Network Identifier:
[2356] 16:02:59:912: 4D 53 46 54 57 4C 41 4E 00 00 00 00 00 00 00 00 |EXAMPLELAN........|
[2356] 16:02:59:912: ElCreatePort: pPCB=<033767B8>, AuthenticationMode=<0>, EncyptionStatus=<0>, usKeyDescription=<1>
[2356] 16:02:59:912: TIMER: Create PCB Time: 2097148
[2356] 16:02:59:912: ElInitRegPortData: ElGetCustomAuthData returned error 603
[2356] 16:02:59:912: ElInitRegPortData: completed with error 0
[2356] 16:02:59:912: ElGetInterfaceParams: SsidLength=<8>, Found EapTypeId=<13>, SSIDLen=<8>
[2356] 16:02:59:912: ElReadPerPortRegistryParams: Setting dwEapFlags=<c0000000>
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:912: ElReadPerPortRegistryParams: dwTotalMaxAuthFailCount = (3)
[2356] 16:02:59:912: ElReadFromPort entered
[2356] 16:02:59:912: ElReadFromPort: pPCB = 033767B8, RefCnt = 3
[2356] 16:02:59:912: FSMConnecting entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: TIMER: Restart PCB Time: 60
[2356] 16:02:59:912: ElWriteToPort entered: Pkt Length = 7
[2356] 16:02:59:912: ElWriteToPort: pPCB = 033767B8, RefCnt = 4
[2356] 16:02:59:912: ElWriteToInterface entered
[2356] 16:02:59:912: ElWriteToInterface completed, RetCode = 0
[2356] 16:02:59:912: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: FSMConnecting completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElCreatePort: Completed for GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C}, Name = Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: CreatePort successful
[2356] 16:02:59:912: ElCreateInterfaceEntry: Added to hash table GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C} : Desc= Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport at Index=0
[2356] 16:02:59:912: ElEnumAndOpenInterfaces: Completed with retcode = 0
[2356] 16:02:59:912: ElIoCompletionRoutine called, 19 bytes xferred
[2356] 16:02:59:912: ElWriteCompletionRoutine sent out 19 bytes with error 0
[2356] 16:02:59:912: ElWriteCompletionRoutine: pPCB= 033767B8, RefCnt = 3
[2356] 16:02:59:912: ElIoCompletionRoutine called, 72 bytes xferred
[2356] 16:02:59:912: ElReadCompletionRoutine entered, 72 bytes recvd
[2356] 16:02:59:912: ProcessReceivedPacket entered, length = 72
[2356] 16:02:59:912: ProcessReceivedPacket: EAP_Packet
[2356] 16:02:59:912: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[2356] 16:02:59:912: TIMER: Restart PCB Time: 2097148
[2356] 16:02:59:912: FSMAcquired entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[2356] 16:02:59:912: TIMER: Restart PCB Time: 30
[2356] 16:02:59:912: ElEapEnd entered
[2356] 16:02:59:912: ElEapBegin entered
[2356] 16:02:59:912: ElEapBegin done
[2356] 16:02:59:912: ElEapWork: EapolPkt created at 064C2410
[2356] 16:02:59:912: ElEapMakeMessage entered
[2356] 16:02:59:912: ElParseIdentityString: DisplayString =
[2356] 16:02:59:912: ElParseIdentityString: LocalIdString = networkid=EXAMPLELAN,nasid=CUSRED040C3439,portid=0
[2356] 16:02:59:912: ElParseIdentityString: LocalIdString Length = 49
[2356] 16:02:59:912: ElParseIdentityString: NetworkID Size = 9
[2356] 16:02:59:912: Got NetworkId = EXAMPLELAN
[2356] 16:02:59:912: Got NASId = CUSRED040C3439
[2356] 16:02:59:912: ElParseIdentityString: For PortId, length = 1
[2356] 16:02:59:912: Got PortId = 0
[2356] 16:02:59:912: ElParseIdentityString: End of String reached
[2356] 16:02:59:912: ElParseIdentityString: Out of while loop
[2356] 16:02:59:912: ElParseIdentityString: Out of while loop: NO ERROR
[2356] 16:02:59:912: ElParseIdentityString: Calling NLARegister_802_1X with params {FB630E90-59FC-47CA-815E-DC0B297B511C} and networkid=EXAMPLELAN,nasid=CUSRED040C3439,portid=0
[2356] 16:02:59:912: NLARegister_802_1X: Entered
[2356] 16:02:59:912: NLAConnectLPC: Entered
[2356] 16:02:59:912: NLARegister_802_1X: g_hNLA_LPC_Port != NULL
[2356] 16:02:59:912: NLARegister_802_1X: Completed with status = 0
[2356] 16:02:59:912: ElParseIdentityString: Returned after calling NLARegister_802_1X
[2356] 16:02:59:912: ElGetIdentity: Userlogged, Prev !Machine auth
[2356] 16:02:59:912: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: !MD5
[2356] 16:02:59:912: ElGetUserIdentity entered
[2356] 16:02:59:912: ElGetEapUserInfo: (pbEapBlob == NULL) && (dwEapBlob == 0)
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:912: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[2356] 16:02:59:922: ElGetUserIdentityOptimized: Error in calling GetIdentity = 798
[2356] 16:02:59:922: ElGetUserIdentity[UI]: dwEAPOLUIMsgType=<1>, dwEapId=<30>, dwEapTypeId=<d>, dwEapFlags=<c0000000>
[2356] 16:02:59:922: WZCNetmanConnectionStatusChanged: Entered
[2356] 16:02:59:922: QueueEvent: CoCreateInstance succeeded
[2356] 16:02:59:922: ConnectionStatusChanged completed
[2356] 16:02:59:922: WZCNetmanShowBalloon: Entered
[2356] 16:02:59:922: WZCNetmanShowBalloon: CoCreateInstance succeeded
[2356] 16:02:59:922: WZCNetmanShowBalloon completed
[2356] 16:02:59:922: TIMER: Restart PCB Time: 2097148
[2356] 16:02:59:922: ElGetUserIdentity completed with error 997
[2356] 16:02:59:922: ElGetIdentity: Error in ElGetUserIdentity 997
[2356] 16:02:59:922: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: No Error: User Auth fine
[2356] 16:02:59:922: ElEapMakeMessage: Error in ElGetIdentity 997
[2356] 16:02:59:922: ElEapWork: ElEapMakeMessage returned error 997
[2356] 16:02:59:922: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
User or Computer Identity Information
You can easily distinguish between user and computer authentication by examining the identity string that the Supplicant sends to the Authenticator. A user name indicates user authentication and a computer name indicates computer authentication. Search for the “identity sent out” string. User names typically have the format username@DNSdomainName” (for example, user10@example.microsoft.com”) or DOMAIN\username (for example. EXAMPLE\user10). Computer names typically have the format host/Computername.DNSdomainName (for example, host/Laptop10.example.microsoft.com). The user or computer name is typically found just before the STATE ACQUIRING state transition. The following excerpt shows an example:
[3688] 16:34:40:316: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3688] 16:34:40:316: FSMConnecting completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3688] 16:34:40:316: ElCreatePort: Completed for GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C}, Name = Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3688] 16:34:40:316: ElEnumAndOpenInterfaces: CreatePort successful
[3688] 16:34:40:316: ElCreateInterfaceEntry: Added to hash table GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C} : Desc= Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport at Index=0
[3688] 16:34:40:316: ElEnumAndOpenInterfaces: Completed with retcode = 0
[1272] 16:34:40:316: ElIoCompletionRoutine called, 72 bytes xferred
[1272] 16:34:40:316: ElReadCompletionRoutine entered, 72 bytes recvd
[1272] 16:34:40:316: ElIoCompletionRoutine called, 19 bytes xferred
[1272] 16:34:40:316: ElWriteCompletionRoutine sent out 19 bytes with error 0
[1272] 16:34:40:316: ElWriteCompletionRoutine: pPCB= 00115E90, RefCnt = 3
[1272] 16:34:40:316: ProcessReceivedPacket entered, length = 72
[1272] 16:34:40:316: ProcessReceivedPacket: EAP_Packet
[1272] 16:34:40:316: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[1272] 16:34:40:316: TIMER: Restart PCB Time: 2097148
[1272] 16:34:40:316: FSMAcquired entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1272] 16:34:40:316: TIMER: Restart PCB Time: 30
[1272] 16:34:40:316: ElEapEnd entered
[1272] 16:34:40:316: ElEapBegin entered
[1272] 16:34:40:316: ElEapBegin done
[1272] 16:34:40:316: ElEapWork: EapolPkt created at 064AF008
[1272] 16:34:40:316: ElEapMakeMessage entered
[1272] 16:34:40:316: ElParseIdentityString: DisplayString =
[1272] 16:34:40:316: ElParseIdentityString: LocalIdString = networkid=EXAMPLELAN,nasid=CUSRED040C3430,portid=0
[1272] 16:34:40:316: ElParseIdentityString: LocalIdString Length = 49
[1272] 16:34:40:316: ElParseIdentityString: NetworkID Size = 9
[1272] 16:34:40:316: Got NetworkId = EXAMPLELAN
[1272] 16:34:40:316: Got NASId = CUSRED040C3430
[1272] 16:34:40:316: ElParseIdentityString: For PortId, length = 1
[1272] 16:34:40:316: Got PortId = 0
[1272] 16:34:40:316: ElParseIdentityString: End of String reached
[1272] 16:34:40:316: ElParseIdentityString: Out of while loop
[1272] 16:34:40:316: ElParseIdentityString: Out of while loop: NO ERROR
[1272] 16:34:40:316: ElParseIdentityString: Calling NLARegister_802_1X with params {FB630E90-59FC-47CA-815E-DC0B297B511C} and networkid=EXAMPLELAN,nasid=CUSRED040C3430,portid=0
[1272] 16:34:40:316: NLARegister_802_1X: Entered
[1272] 16:34:40:316: NLARegister_802_1X: g_hNLA_LPC_Port != NULL
[1272] 16:34:40:316: NLARegister_802_1X: Completed with status = 0
[1272] 16:34:40:316: ElParseIdentityString: Returned after calling NLARegister_802_1X
[1272] 16:34:40:316: ElGetIdentity: Userlogged, Prev !Machine auth
[1272] 16:34:40:316: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: !MD5
[1272] 16:34:40:316: ElGetUserIdentity entered
[1272] 16:34:40:316: ElGetEapUserInfo: Get value succeeded: EapTypeId=<13>, SSIDLen=<8>, AuthData=(62)
[1272] 16:34:40:316: ElGetEapUserInfo: Get value succeeded: EapTypeId=<13>, SSIDLen=<8>, AuthData=(62)
[1272] 16:34:40:316: ElGetUserIdentityOptimized: ElGetEapUserInfo: Got user blob, size = (62)
[1272] 16:34:40:316: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[1272] 16:34:40:316: ElGetCustomAuthData: SSIDLen=<8>, EapTypeId=<13>, Offset=<52/104>, dwAuthData=<40>
[1272] 16:34:40:637: ElGetUserIdentityOptimized: Got identity = peterbui@ntdev.microsoft.com
[1272] 16:34:40:637: ElGetUserIdentity: ElGetUserIdentityOptimized got identity without user module intervention
[1272] 16:34:40:637: ElGetUserIdentity completed with error 0
[1272] 16:34:40:637: ElGetIdentity: Userlogged, <Maxauth, Prev !Machine auth: No Error: User Auth fine
[1272] 16:34:40:637: Identity sent out = user10@example.microsoft.com
[1272] 16:34:40:637: ElWriteToPort entered: Pkt Length = 39
[1272] 16:34:40:637: ElWriteToPort: pPCB = 00115E90, RefCnt = 4
[1272] 16:34:40:637: ElWriteToInterface entered
[1272] 16:34:40:637: ElWriteToInterface completed, RetCode = 0
[1272] 16:34:40:637: Setting state ACQUIRED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
WPA
Wi-Fi Protected Access (WPA) is recommended over WEP to secure wireless traffic and can be used in an Enterprise mode, in which 802.1X and an EAP type is used, or Personal mode, in which a preshared key (PSK) is used. Enterprise mode (WPA) and Personal mode (WPA-PSK) mainly differ in the way that encryption keys are generated. For WPA authentication, the set of 802.1X state transitions in the Eapol.log file are the same as for 802.1X authentication with WEP. The following excerpt shows an example of WPA authentication:
[3708] 16:40:01:815: Setting state AUTHENTICATED for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3708] 16:40:01:815: FSMAuthenticated: fIsRemoteEndEAPOLAware=<1>, dwWaitForKeys=<1>
[3708] 16:40:01:815: TIMER: Restart PCB Time: 5
[3708] 16:40:01:815: FSMAuthenticated completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3708] 16:40:01:815: WZCNetmanConnectionStatusChanged: Entered
[3708] 16:40:01:815: QueueEvent: CoCreateInstance succeeded
[3708] 16:40:01:815: ConnectionStatusChanged completed
[3708] 16:40:01:815: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3708] 16:40:01:815: ElReadFromPort entered
[3708] 16:40:01:815: ElReadFromPort: pPCB = 0340C4A8, RefCnt = 3
[3708] 16:40:01:815: ProcessReceivedPacket: pPCB= 0340C4A8, RefCnt = 3
[3708] 16:40:01:815: ProcessReceivedPacket exit
[1600] 16:40:01:815: ElIoCompletionRoutine called, 113 bytes xferred
[1600] 16:40:01:815: ElReadCompletionRoutine entered, 113 bytes recvd
[1600] 16:40:01:815: ProcessReceivedPacket entered, length = 113
[1600] 16:40:01:815: ProcessReceivedPacket: != EAP_Packet
[1600] 16:40:01:815: ProcessReceivedPacket: == EAPOL_Key
[1600] 16:40:01:815: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:815: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:815: ElKeyReceiveSSN: usKeyInfo=<89>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[1600] 16:40:01:815: ElQueryMasterKeys: Using EAPOL Keys as Master Keys for Re-keying
[1600] 16:40:01:815: ElWriteToPort entered: Pkt Length = 125
[1600] 16:40:01:815: ElWriteToPort: pPCB = 0340C4A8, RefCnt = 3
[1600] 16:40:01:815: ElWriteToInterface entered
[1600] 16:40:01:815: ElWriteToInterface completed, RetCode = 0
[1600] 16:40:01:815: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:815: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:815: ProcessReceivedPacket: STATE_AUTHENTICATED
[1600] 16:40:01:815: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[1600] 16:40:01:815: ElReadFromPort entered
[1600] 16:40:01:815: ElReadFromPort: pPCB = 0340C4A8, RefCnt = 4
[1600] 16:40:01:815: ProcessReceivedPacket: pPCB= 0340C4A8, RefCnt = 4
[1600] 16:40:01:815: ProcessReceivedPacket exit
[1600] 16:40:01:815: ElIoCompletionRoutine called, 137 bytes xferred
[1600] 16:40:01:815: ElWriteCompletionRoutine sent out 137 bytes with error 0
[1600] 16:40:01:815: ElWriteCompletionRoutine: pPCB= 0340C4A8, RefCnt = 3
[1600] 16:40:01:835: ElIoCompletionRoutine called, 137 bytes xferred
[1600] 16:40:01:835: ElReadCompletionRoutine entered, 137 bytes recvd
[1600] 16:40:01:835: ProcessReceivedPacket entered, length = 137
[1600] 16:40:01:835: ProcessReceivedPacket: != EAP_Packet
[1600] 16:40:01:835: ProcessReceivedPacket: == EAPOL_Key
[1600] 16:40:01:835: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:835: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:835: ElKeyReceiveSSN: usKeyInfo=<1c9>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[1600] 16:40:01:835: ElKeyReceiveSSN: Received Per-STA Unicast key confirmation
[1600] 16:40:01:835: ElWriteToPort entered: Pkt Length = 101
[1600] 16:40:01:835: ElWriteToPort: pPCB = 0340C4A8, RefCnt = 3
[1600] 16:40:01:835: ElWriteToInterface entered
[1600] 16:40:01:835: ElWriteToInterface completed, RetCode = 0
[1600] 16:40:01:835: ElKeyReceiveSSN: Plumbing key -- TotalLength=<64>, KeyLength=<32>, Index=<e0000000>
[3232] 16:40:01:865: ElIoCompletionRoutine called, 113 bytes xferred
[3232] 16:40:01:865: ElWriteCompletionRoutine sent out 113 bytes with error 0
[3232] 16:40:01:865: ElWriteCompletionRoutine: pPCB= 0340C4A8, RefCnt = 3
[1600] 16:40:01:875: ElNdisuioSetOIDValue: DeviceIoControl succeeded
[1600] 16:40:01:875: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:875: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:01:875: ProcessReceivedPacket: STATE_AUTHENTICATED
[1600] 16:40:01:875: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[1600] 16:40:01:875: ElReadFromPort entered
[1600] 16:40:01:875: ElReadFromPort: pPCB = 0340C4A8, RefCnt = 3
[1600] 16:40:01:875: ProcessReceivedPacket: pPCB= 0340C4A8, RefCnt = 3
[1600] 16:40:01:875: ProcessReceivedPacket exit
[1600] 16:40:02:837: ElIoCompletionRoutine called, 145 bytes xferred
[1600] 16:40:02:837: ElReadCompletionRoutine entered, 145 bytes recvd
[1600] 16:40:02:837: ProcessReceivedPacket entered, length = 145
[1600] 16:40:02:837: ProcessReceivedPacket: != EAP_Packet
[1600] 16:40:02:837: ProcessReceivedPacket: == EAPOL_Key
[1600] 16:40:02:837: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:02:837: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:02:837: ElKeyReceiveSSN: usKeyInfo=<391>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[1600] 16:40:02:837: ElKeyReceiveSSN: Received Per-STA BROADCAST key material
[1600] 16:40:02:837: ElKeyReceiveSSN: Plumbing key -- TotalLength=<64>, KeyLength=<32>, Index=<20000001>
[1600] 16:40:02:837: ElNdisuioSetOIDValue: DeviceIoControl succeeded
[1600] 16:40:02:837: ElWriteToPort entered: Pkt Length = 101
[1600] 16:40:02:837: ElWriteToPort: pPCB = 0340C4A8, RefCnt = 3
[1600] 16:40:02:837: ElWriteToInterface entered
[1600] 16:40:02:837: ElWriteToInterface completed, RetCode = 0
[1600] 16:40:02:837: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:02:837: FSMKeyReceive: Port Opened by current key
[1600] 16:40:02:837: FSMKeyReceive: Queued ElIPPnPWorker
[1600] 16:40:02:837: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[1600] 16:40:02:837: ProcessReceivedPacket: STATE_AUTHENTICATED
[1600] 16:40:02:837: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[1600] 16:40:02:837: ElReadFromPort entered
[1600] 16:40:02:837: ElReadFromPort: pPCB = 0340C4A8, RefCnt = 4
[1600] 16:40:02:837: ProcessReceivedPacket: pPCB= 0340C4A8, RefCnt = 4
[1600] 16:40:02:837: ProcessReceivedPacket exit
[1600] 16:40:02:837: ElIPPnPWorker: Calling DhcpNotifyMediaReconnected on ({FB630E90-59FC-47CA-815E-DC0B297B511C}) ...
[1600] 16:40:02:837: ElIPPnPWorker: DhcpNotifyMediaReconnected successful
WPA-PSK
For authentication with WPA-PSK, the 802.1X state machine does not run and you will not see the usual Connecting, Acquired, Authenticating, Authenticated state sequence. However, a unicast key is generated from the authentication process and the value of the PSK. Each WPA-PSK authentication creates a new unicast key. The following excerpt shows a typical WPA-PSK authentication:
[3020] 16:21:49:693: Setting state CONNECTING for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: FSMConnecting completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: ElCreatePort: Completed for GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C}, Name = Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: ElEnumAndOpenInterfaces: CreatePort successful
[3020] 16:21:49:693: ElCreateInterfaceEntry: Added to hash table GUID= {FB630E90-59FC-47CA-815E-DC0B297B511C} : Desc= Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport at Index=0
[3020] 16:21:49:693: ElEnumAndOpenInterfaces: Completed with retcode = 0
[3020] 16:21:49:693: ElIoCompletionRoutine called, 113 bytes xferred
[3020] 16:21:49:693: ElReadCompletionRoutine entered, 113 bytes recvd
[3020] 16:21:49:693: ProcessReceivedPacket entered, length = 113
[3020] 16:21:49:693: ProcessReceivedPacket: != EAP_Packet
[3020] 16:21:49:693: ProcessReceivedPacket: == EAPOL_Key
[3020] 16:21:49:693: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: ElKeyReceiveSSN: usKeyInfo=<89>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[3020] 16:21:49:693: ElSecureDecodePw: CryptUnprotectData failed: 87
[3020] 16:21:49:693: ElQueryEAPOLMasterKeys: ElSecureDecodePw failed for MasterSecretSend with error 87
[3020] 16:21:49:693: ElQueryMasterKeys: ElQueryEAPOLMasterKeys failed with error 87
[3020] 16:21:49:693: ElQueryMasterKeys: Using WZC Keys as Master Keys for Re-keying
[1600] 16:21:49:693: ElIoCompletionRoutine called, 19 bytes xferred
[1600] 16:21:49:693: ElWriteCompletionRoutine sent out 19 bytes with error 0
[1600] 16:21:49:693: ElWriteCompletionRoutine: pPCB= 000920A0, RefCnt = 3
[3020] 16:21:49:693: ElWriteToPort entered: Pkt Length = 125
[3020] 16:21:49:693: ElWriteToPort: pPCB = 000920A0, RefCnt = 3
[3020] 16:21:49:693: ElWriteToInterface entered
[3020] 16:21:49:693: ElWriteToInterface completed, RetCode = 0
[3020] 16:21:49:693: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:693: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[3020] 16:21:49:693: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3020] 16:21:49:693: ElReadFromPort entered
[3020] 16:21:49:693: ElReadFromPort: pPCB = 000920A0, RefCnt = 4
[3020] 16:21:49:693: ProcessReceivedPacket: pPCB= 000920A0, RefCnt = 4
[3020] 16:21:49:693: ProcessReceivedPacket exit
[2756] 16:21:49:693: EAPOLQueryGUIDNCSState: WPA-PSK Mode Returning S_OK
[3020] 16:21:49:703: ElIoCompletionRoutine called, 137 bytes xferred
[3020] 16:21:49:703: ElWriteCompletionRoutine sent out 137 bytes with error 0
[3020] 16:21:49:703: ElWriteCompletionRoutine: pPCB= 000920A0, RefCnt = 3
[3020] 16:21:49:703: ElIoCompletionRoutine called, 137 bytes xferred
[3020] 16:21:49:703: ElReadCompletionRoutine entered, 137 bytes recvd
[3020] 16:21:49:703: ProcessReceivedPacket entered, length = 137
[3020] 16:21:49:703: ProcessReceivedPacket: != EAP_Packet
[3020] 16:21:49:703: ProcessReceivedPacket: == EAPOL_Key
[3020] 16:21:49:703: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:703: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:703: ElKeyReceiveSSN: usKeyInfo=<1c9>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[3020] 16:21:49:703: ElKeyReceiveSSN: Received Per-STA Unicast key confirmation
[3020] 16:21:49:703: ElWriteToPort entered: Pkt Length = 101
[3020] 16:21:49:703: ElWriteToPort: pPCB = 000920A0, RefCnt = 3
[3020] 16:21:49:703: ElWriteToInterface entered
[3020] 16:21:49:703: ElWriteToInterface completed, RetCode = 0
[3020] 16:21:49:703: ElKeyReceiveSSN: Plumbing key -- TotalLength=<64>, KeyLength=<32>, Index=<e0000000>
[1600] 16:21:49:743: ElIoCompletionRoutine called, 113 bytes xferred
[1600] 16:21:49:743: ElWriteCompletionRoutine sent out 113 bytes with error 0
[1600] 16:21:49:743: ElWriteCompletionRoutine: pPCB= 000920A0, RefCnt = 3
[3020] 16:21:49:743: ElNdisuioSetOIDValue: DeviceIoControl succeeded
[3020] 16:21:49:743: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:743: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:49:743: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[3020] 16:21:49:743: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3020] 16:21:49:743: ElReadFromPort entered
[3020] 16:21:49:743: ElReadFromPort: pPCB = 000920A0, RefCnt = 3
[3020] 16:21:49:743: ProcessReceivedPacket: pPCB= 000920A0, RefCnt = 3
[3020] 16:21:49:743: ProcessReceivedPacket exit
[2756] 16:21:49:833: EAPOLQueryGUIDNCSState: WPA-PSK Mode Returning S_OK
[1048] 16:21:50:685: EAPOLQueryGUIDNCSState: WPA-PSK Mode Returning S_OK
[3020] 16:21:50:715: ElIoCompletionRoutine called, 145 bytes xferred
[3020] 16:21:50:715: ElReadCompletionRoutine entered, 145 bytes recvd
[3020] 16:21:50:715: ProcessReceivedPacket entered, length = 145
[3020] 16:21:50:715: ProcessReceivedPacket: != EAP_Packet
[3020] 16:21:50:715: ProcessReceivedPacket: == EAPOL_Key
[3020] 16:21:50:715: FSMKeyReceive entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:50:715: ElKeyReceiveSSN entered for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:50:715: ElKeyReceiveSSN: usKeyInfo=<391>, KEY_TYPE_BIT=<8>, KEY_TYPE_PAIRWISE=<8>
[3020] 16:21:50:715: ElKeyReceiveSSN: Received Per-STA BROADCAST key material
[3020] 16:21:50:715: ElKeyReceiveSSN: Plumbing key -- TotalLength=<64>, KeyLength=<32>, Index=<20000001>
[3020] 16:21:50:715: ElNdisuioSetOIDValue: DeviceIoControl succeeded
[3020] 16:21:50:715: ElWriteToPort entered: Pkt Length = 101
[3020] 16:21:50:715: ElWriteToPort: pPCB = 000920A0, RefCnt = 3
[3020] 16:21:50:715: ElWriteToInterface entered
[3020] 16:21:50:715: ElWriteToInterface completed, RetCode = 0
[3020] 16:21:50:715: ElKeyReceiveSSN completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:50:715: FSMKeyReceive: Port Opened by current key
[3020] 16:21:50:715: FSMKeyReceive: Queued ElIPPnPWorker
[3020] 16:21:50:715: FSMKeyReceive completed for port Intel(R) PRO/Wireless 2200BG Network Connection - Packet Scheduler Miniport
[3020] 16:21:50:715: ProcessReceivedPacket: EAPOLSTATE_CONNECTING
[3020] 16:21:50:715: ProcessReceivedPacket: Reposting buffer on port {FB630E90-59FC-47CA-815E-DC0B297B511C}
[3020] 16:21:50:715: ElReadFromPort entered
[3020] 16:21:50:715: ElReadFromPort: pPCB = 000920A0, RefCnt = 4
[3020] 16:21:50:715: ProcessReceivedPacket: pPCB= 000920A0, RefCnt = 4
[3020] 16:21:50:715: ProcessReceivedPacket exit
[3020] 16:21:50:715: ElIPPnPWorker: Calling DhcpNotifyMediaReconnected on ({FB630E90-59FC-47CA-815E-DC0B297B511C}) ...
[3020] 16:21:50:715: ElIPPnPWorker: DhcpNotifyMediaReconnected successful
The “...failed with error 87” in this case is expected and not a real error.
Appendix A: Quick Reference Guide
General steps for troubleshooting association or 802.1X authentication issues:
Gather information.
Evaluate and categorize symptom or issue.
If needed, analyze the contents of the Wzctrace.log file for 802.11 association problems.
If needed, analyze the contents of the Eapol.log file for 802.1X-based authentication problems.
Step 1: Gather information
Information to gather:
Version of Windows, service pack version, installed hotfix numbers
Wireless connection details
802.11 authentication type (open system, shared key, 802.1X, WPA, WPA-PSK)
802.11 encryption (none, 40-bit WEP, 104-bit WEP, TKIP, AES)
802.1X authentication method (EAP-TLS, PEAP-MS-CHAP v2 with or without logon credentials, PEAP-EAP-TLS)
Wireless network adapter details
Vendor
Model
Driver version
Wireless access point details
Vendor
Model
Firmware version
Authentication and encryption configuration
Logs
To enable logging. use the netsh ras set tracing * enable command.
Collect Wzctrace.log, Eapol.log, Wzcdlg.log, Netman.log, Netshell.log, and .old versions if they exist in the systemroot\tracing folder
To disable logging. use the netsh ras set tracing * disable command.
Times when problem was reproduced (down to the minute preferably to correlate to the appropriate sections in the log files)
Step 2: Evaluate and categorize symptom or issue
Use Table 1 in this article to categorize the wireless connection symptom or issue.
Step 3: Analyze the Wzctrace.log file for 802.11 association problems
The general steps for reading the Wzctrace.log file are the following:
If possible, determine the time range to examine in the log. Restrict inspection to this time range at first.
Compare what is recorded in the log with what you expect to happen. Look for anything outside of expected activity. Common things to check:
Is your wireless network visible in the visible networks listing?
For the configuration being plumbed, is it the correct one? Are the right OIDs being set? Are there errors or asserts when OIDs are set or queried?
Are media events (such as connects and disconnects) occurring at expected times?
If needed, widen the scope of the time range made in step 1 and repeat the process to understand what has been happening for other wireless connection attempts.
Table 5 lists the areas of interest in the Wzctrace.log file and the corresponding search string.
Table 5 Searching the Wzctrace.log file
Area of Interest |
Search String |
Notes of Interest |
|---|---|---|
Visible list |
NdisToWzc |
Note “NumEntries” and “Unique.” |
Preferred list |
SelectList |
Number denotes preference order. |
Select list |
WZCCopy |
Number denotes connect order. |
Blocked list |
Blocked |
|
Plumbing configuration |
Plumb |
Look at OID values. |
Media events |
WZCnot |
See media event values in Table 3. |
User configuration change from the View Available Network or Choose a wireless network dialog boxes |
RpcQueryInterface |
|
User configuration change from the Wireless Networks tab or a connect from the View Available Networks or Choose a wireless network dialog boxes |
RpcSet |
|
DHCP release or renew |
DHCP |
This only means we called DHCP to do its work, not that DHCP configuration is successful. |
Capabilities check |
capabilities |
Some errors here are expected |
For definitions of the hexadecimal values for the OIDs and their parameters, see Table 2 in this article.
Step 4: Analyze the Eapol.log file for 802.1X authentication problems
Steps for reading the Eapol.log file:
Identify the time period of interest to examine (e.g. 9:30am to 10:30am). If you have followed the basic information gathering process, you should know approximately what time the problems occurred.
Quickly step through the 802.1X Supplicant Machine States one by one for this time period. Depending on the circumstances (be it authentication, roaming, etc), note if the state transition order is what is expected, noting any deviations from what is expected.
If needed, go back to the beginning of the time period and take note of key pieces of information at each state. The key pieces of information commonly used are:
User or computer identity
Media events
Keys received
Table 6 lists the areas of interest in the Eapol.log file and the corresponding search string.
Table 6 Searching the Eapol.log file
Area of Interest |
Search String |
Notes of Interest |
|---|---|---|
State |
Setting state |
|
Key received |
EAPOL_Key |
Look at the key length to determine the type of key |
Failure counts |
failcount |
Three failures block a wireless network |
Service start |
ElMediaInit |
|
Service stop |
ElMediaDeInit |
|
Media events |
mediaEventsHandler |
Number types same as in the Wzctrace.log file |
SSID & BSSID of wireless AP |
SSID |
|
Wireless AP identity |
nasid |
|
Identity sent by wireless client |
identity sent |
To check for user or computer authentication |
DHCP call |
DHCP |
|
Key plumbed |
port opened |
|
Failure to receive key |
key *NOT* received |
|
WPA keys |
Per-STA Unicast key |
|
EAP types |
EAP Type 13 |
EAP-TLS, PEAP |
Logon/logoff |
logon, logoff |
|
WPA or WPA-PSK master keys |
Master |
Error 87 expected for WPA-PSK |
WPA unicast key |
Per-STA Unicast |
|
WPA broadcast key |
Per-STA Broadcast |
|
See Table 4 for a listing of common 802.1X state transitions.
Common Problems
The following are common problems with wireless connectivity:
Wireless network adapter driver problems
Inability to connect
Intermittent connectivity
Wireless network adapter driver problems
Look for errors or asserts when OIDs are being set or queried. These OIDs are commonly found near or during the following events:
Configuration being plumbed
Capabilities check
Before or after a suspend or resume
Also, perform a search for each instance of the “devioset” or “devioquery” string.
Inability to connect
Check for the following:
Is there a configuration mismatch between the wireless AP and the wireless client? Verify that the OIDs being set match with known wireless AP settings.
Is the desired network visible? Check the visible networks list.
Is the wireless AP not responding for some reason? After the configuration is plumbed, a two second timer is initiated. Search for the “timeoutcallback” string occurring two seconds after the configuration is plumbed and determine whether it times out.
Are you using the latest wireless network adapter driver?
Intermittent connectivity
Check for the following:
What are the symptoms? For example, are disconnects happening every 3 minutes? If so, then disable 802.1X authentication. States in the Eapol.log file would look like the following:
STATE CONNECTING
STATE CONNECTING
STATE CONNECTING
STATE AUTHENTICATED
DISCONNECT
The wireless client might be at the periphery of radio range.
There might be intermittent environmental radio interference.
Appendix B: Wireless Group Policy
To automate the configuration of wireless network settings for Windows XP with SP2, Windows XP with SP1, and Windows Server 2003 wireless client computers, Windows Server 2003 Active Directory® directory service domains support a new Wireless Network (IEEE 802.11) Policies Group Policy extension that allows you to configure wireless network settings that are part of Computer Configuration Group Policy for a domain-based Group Policy object. The user of the wireless client computer cannot change the settings applied by the wireless Group Policy settings. Only the network administrator can change the settings through Group Policy. However, a local administrator can add new preferred wireless networks.
For background information about wireless Group Policy settings, see Configuring Wireless Settings Using Windows Server 2003 Group Policy.
Determining Wireless Group Policy Status
To determine wireless Group Policy status using tracing logs, enable tracing with the netsh ras set tracing * enable command. The logs are written in the systemroot\tracing folder.
Eapol.log Entries
To determine if a wireless client is ready to accept wireless Group Policy settings, look for the following lines in the Eapol.log file:
[284] 15:32:33:284: ElPolicyChange: Entered
[284] 15:32:33:284: ElPolicyChange: Ready to accept policy
[524] 15:32:33:284: ElPolicyChangeWorker entered
[524] 15:32:33:284: Old Policy =
The last line shows what the current policy on the computer is before the new policy is applied. If this line is blank, there was no previous wireless Group Policy applied. For the actual settings of the applied wireless Group Policy, you need to look at the Wlpolicy.log file.
Another line in the Eapol.log file that describes wireless Group Policy is the following:
[524] 15:32:33:300: Policy setting requiring reauth
This line indicates that due to policy changes, a re-authentication was required. If you are having authentication issues, this could be a cause. The easiest way to force a wireless client to perform a re-authentication is to use the Repair feature of the wireless network adapter for Windows XP SP2 (right-click the wireless network adapter in the Network Connections folder and click Repair). The repair process will disable, and then enable the adapter, which will initiate the authentication process again.
Wlpolicy.log Entries
The Wlpolicy.log file contains a wealth of information about the wireless Group Policy settings that are applied to a wireless client, including the general settings for the policy and the individual SSIDs and their settings.
The following lines detail the general policy settings:
[284] 15:32:32: Policy Name: New Wireless Network Policy
[284] 15:32:32: Policy Description: this is a description of a wireless network policy for wireless Group Policy......
[284] 15:32:32: Disable Zero Conf: 0
[284] 15:32:32: Network To Access: 1
[284] 15:32:32: Polling Interval: 60
[284] 15:32:32: Connect To Non Preferred networks: 0
[284] 15:32:32: Num Preferred Settings: 11
[284] 15:32:32: Num AP Networks: 11
The lines for the general wireless policy settings contain the following:
Policy Name The name of the wireless Group Policy as configured by the network administrator.
**Policy Description **A description of the wireless Group Policy as configured by the network administrator. The policy name and description are administrative information and do not affect wireless connection behavior. However, you can use this information to determine exactly which wireless Group Policy is applied to a wireless client.
Disable Zero Conf Determines if the wireless client will use Wireless Auto Configuration (the feature enabled by the Wireless Zero Configuration service). If this is set to 1, then wireless Group Policy settings are not applied.
Network To Access Determines the types of wireless networks to which the wireless clients can connect. The types are: any available (1), infrastructure only (2), or ad hoc only (3).
Polling Interval Determines the amount of time in seconds that the wireless client waits to check for new wireless Group Policy settings.
Connect To Non Preferred networks Determines if the client will connect to networks that are not in the preferred list. This setting does not prevent a user from adding a network to the preferred list, it only determines whether the wireless client will automatically attempt to connect to wireless networks that are not in the preferred networks list.
Num Preferred Settings The number of SSIDs that wireless Group Policy is adding to the preferred networks list.
Num AP Networks The number of SSIDs that are being placed in the preferred list that are infrastructure mode wireless networks.
The following excerpt is for an SSID within the wireless Group Policy settings:
[284] 15:32:32: Printing PS 1
[284] 15:32:32: SSID: shared_disabled
[284] 15:32:32: SSIDLen: 15
[284] 15:32:32: WepEnabled: 0
[284] 15:32:32: Id: 1
[284] 15:32:32: Network Type: 2
[284] 15:32:32: NetworkAuthentication: 1
[284] 15:32:32: Automatic Key Provision: 1
[284] 15:32:32: Enable8021x: 0
[284] 15:32:32: Enable8021xMode: 2
[284] 15:32:32: Eap Type: 13
[284] 15:32:32: EAP Data Len: 0
[284] 15:32:32: Machine Authentication: 1
[284] 15:32:32: MachineAuthenticationType: 1
[284] 15:32:32: GuestAuthentication: 0
[284] 15:32:32: IEEE 8021x MaxStart: 3
[284] 15:32:32: IEEE 8021x Start Period: 60
[284] 15:32:32: IEEE 8021x Auth Period: 30
[284] 15:32:32: IEEE 8021x Held Period: 60
[284] 15:32:32: IEEE Preferrerd Setting Description:
[284] 15:32:32: Sample Description
[284] 15:32:32: Description Len: 18
[284] 15:32:32: TotalSize: 176
Multiple SSIDs within the wireless Group Policy are separated by the following line:
[284] 15:32:32: Printing PS...
A number after "PS" in this line indicates the number of the SSID within the Group Policy, starting at 0.
Most of the options for an SSID match the manually configured options listed correspond to settings on the Network Properties and IEEE 802.1x tabs for an SSID when configuring wireless Group Policy. For more information, see Configuring Wireless Settings Using Windows Server 2003 Group Policy.
The following line defines how computer authentication works for an SSID:
[284] 15:32:32: MachineAuthenticationType: 1
This setting is on the 802.1x tab of the wireless Group Policy but is not present in the user interface of the wireless client. The value of the MachineAuthenticationType setting defines the following:
0 – Use computer authentication. If a user logs on and computer authentication has not already been done, perform authentication with the user's credentials.
1 – Use computer authentication. If a user logs on, perform authentication with the user’s credentials.
2 – Use computer authentication. If a user logs on, do not perform authentication with the user’s credentials.
The HKEY_LOCAL_MACHINE\Software\Microsoft\EAPOL\Parameters\General\Global\AuthMode registry value also controls this behavior, however the registry value does not have any effect on SSIDs that have been configured on the wireless client through wireless Group Policy.
You can also use information in the Wlpolicy.log file to determine whether or not there has a change to the policy. The following excerpt shows the process of checking for policy:
[5772] 13:27:16: Updating with DS Policy
[5772] 13:27:16: DBASE: Wireless Policy – Checking for Current Policy on DC
[5772] 13:27:16: DBASE: Wireless Policy – Checking for Current Cached Policy
[5772] 13:27:16: Policy State :: Initial State
[5772] 13:27:16: Timeout period is 3600000
The "Policy State :: Initial State" indicates that the current wireless Group Policy on the wireless client computer matches that in Active Directory.
If a wireless client is not downloading and applying an updated set of wireless Group Policy settings, check the following:
Your wireless client is running Windows XP with SP1, Windows XP with SP2, or Windows Server 2003.
You have correctly configured the Wireless Network (IEEE 802.11) Policies Group Policy extension in the appropriate Active Directory system container. For example, if your wireless client computer is in an organizational unit (OU), verify that the wireless Group Policy settings are applied to that OU. You can also use the Result Set of Policy (RSoP) snap-in to determine which policy settings are being applied to which system container.
If these conditions are satisfied, run the gpupdate /force command on the wireless client. If the updated Group Policy is still not being applied, restart the wireless client. If restarting the wireless client computer does not work, remove the computer from the domain, restart the computer, join the domain, and restart the computer again, ensuring that the new computer account is in the correct OU.
References
For additional information, see the following resources: