WinLogon Operational Log Events

Question

_{Saturday, June 8, 2019 10:05 PM}

I am trying to find a whitepaper or explanation on how Event ID 1 and Event ID 2 are generated in the Application and Services>WinLogon>Operational log for Windows 10. We are seeing that the time between Authentication Attempt (Event ID 1) and Authentication complete (Event ID 2) is varying by 20-40 seconds. I am trying to find out how to track down what is causing the variance. Our monitoring tools say that DC discovery is consistent, and we don't any errors in the Kerberos logs, or any other log that we have looked through. Any help would be greatly appreciated as it affecting the time it takes for customers to logon.

A+ NET+ Security+ MCDST MCITP

All replies (3)

_{Sunday, June 9, 2019 11:06 AM}

Hello Psychomike70,

One thing that you could try is to use Event Tracing for Windows (ETW) to record what is happening between the two events. There are thousands of event trace providers, but for this case my initial choice would be as follows (in a format suitable for use with the -pf option of logman.exe):

Microsoft-Windows-Winlogon
Microsoft-Windows-NTLM
Microsoft-Windows-Security-Netlogon
Microsoft-Windows-Kernel-Process 0x10
Microsoft-Windows-Kernel-Network
Microsoft-Windows-LDAP-Client
{D451642C-63A6-11D7-9720-00B0D03E0347} 0xFFFFFFFFFFFFFFFF 255 # WinLogon
{C92CF544-91B3-4DC0-8E11-C580339A0BF8} 0xFFFFFFFFFFFFFFFF 255 # NTLM Security Protocol
{6B510852-3583-4E2D-AFFE-A67F9F223438} 0xFFFFFFFFFFFFFFFF 255 # Security: Kerberos Authentication
{5BBB6C18-AA45-49B1-A15F-085F7ED0AA90} 0xFFFFFFFFFFFFFFFF 255 # Security: NTLM Authentication
{CC85922F-DB41-11D2-9244-006008269001} 0xFFFFFFFFFFFFFFFF 255 # Local Security Authority (LSA)
{199FE037-2B82-40A9-82AC-E1D46C792B99} 0xFFFFFFFFFFFFFFFF 255 # LsaSrv
{BBA3ADD2-C229-4CDB-AE2B-57EB6966B0C4} 0xFFFFFFFFFFFFFFFF 255 # Active Directory: Kerberos Client

Tracing these providers across a logon on my standalone home PC produces this output:

8 milliseconds and several hundred events later:

The second and second last entries in the images above are the event IDs 1 and 2 that you mention. In your case, a trace like this should help us to narrow down the activities that are consuming time. If there are big gaps in the timeline of the trace, we may have to add additional trace providers.

I saved the list of event providers in a file (say winlogon.lst) and then issued a command like "logman start -ets slow -pf winlogon.lst -o slow.etl -nb 100"; I then logged out and back in and stopped the trace with "logman stop -ets slow".

The trace data can be analysed with Microsoft's Message Analyzer or any other tool that works with .etl files.

Gary

_{Sunday, June 9, 2019 11:28 AM}

Thank you for the advice. I was planning on using SysInternals ProcMon to try to capture the events, but I will see about setting up a logman trace as well. Perhaps between the two we can find what is causing the deltas. 

A+ NET+ Security+ MCDST MCITP

_{Thursday, June 13, 2019 1:41 PM}

Hi,

If any update, feel free to post here.

Best Regards,

Please remember to mark the replies as answers if they help.
If you have feedback for TechNet Subscriber Support, contact [email protected].