Detecting logins like a boss- the Seq Client for Windows Logins
Table of Contents
The Journey Begins ...
This was a journey that began with an existing, and really useful, Seq application.
I've had some mileage in the past from the Seq.Client.EventLog service. I've used it to monitor the Windows Application event log for new logs from a specific source, send them to Seq, and alert using Event Timeout if the expected event doesn't happen at a configured time.
It worked well for the purpose, so when a new requirement came up to monitor for successful interactive Windows logins and other efforts were falling short, I started looking at sending logs to Seq with Seq.Client.EventLog.
An account was successfully logged on
To pick up new logins from Windows, you'll typically monitor the Security event log for Success Audit events with the event id 4624. Easy enough to do with Seq.Client.EventLog, right? It has enough configuration elements to accomplish that, except - I did mention that we want interactive logons. That means we need to dig deeper into the event log event, to examine the "Logon Type" property, which you can see in the details below:
Sourced from Audit logon events (Windows 10) - Windows security, here are the possible logon types:
| Logon type | Logon title | Description |
|---|---|---|
| 2 | Interactive | A user logged on to this computer. |
| 3 | Network | A user or computer logged on to this computer from the network. |
| 4 | Batch | Batch logon type is used by batch servers, where processes may be executing on behalf of a user without their direct intervention. |
| 5 | Service | A service was started by the Service Control Manager. |
| 7 | Unlock | This workstation was unlocked. |
| 8 | NetworkCleartext | A user logged on to this computer from the network. The user's password was passed to the authentication package in its unhashed form. The built-in authentication packages all hash credentials before sending them across the network. The credentials do not traverse the network in plaintext (also called cleartext). |
| 9 | NewCredentials | A caller cloned its current token and specified new credentials for outbound connections. The new logon session has the same local identity, but uses different credentials for other network connections. |
| 10 | RemoteInteractive | A user logged on to this computer remotely using Terminal Services or Remote Desktop. |
| 11 | CachedInteractive | A user logged on to this computer with network credentials that were stored locally on the computer. The domain controller was not contacted to verify the credentials. |
Speaking broadly - at least for an always-online server - the logon types of interest are 2 (Interactive) and 10 (Remote Interactive).
In order to pick these up, we need to get up close and personal with the event log to extract the event log properties.
Digging out the properties
Doing this quickly turned the need to examine the logon type from a "problem" into an opportunity. To look at the properties for a standard event log (like an event id 4624), you can use an EventLogPropertySelector to all properties of interest ... and we're sending to Seq, a structured logging server that loves properties. Do you see where this is leading? Of course you do!
try{var query = new EventLogQuery(logName, PathType.LogName,"*[System[(EventRecordID=" + entry.Index + ")]]");var reader = new EventLogReader(query);for (var logEntry = reader.ReadEvent(); logEntry != null; logEntry = reader.ReadEvent()){//Get all the properties of interest for passing to Seqvar loginEventPropertySelector = new EventLogPropertySelector(new[]{"Event/EventData/Data[@Name='SubjectUserSid']","Event/EventData/Data[@Name='SubjectUserName']","Event/EventData/Data[@Name='SubjectDomainName']","Event/EventData/Data[@Name='SubjectLogonId']","Event/EventData/Data[@Name='TargetUserSid']","Event/EventData/Data[@Name='TargetUserName']","Event/EventData/Data[@Name='TargetDomainName']","Event/EventData/Data[@Name='TargetLogonId']","Event/EventData/Data[@Name='LogonType']","Event/EventData/Data[@Name='LogonProcessName']","Event/EventData/Data[@Name='AuthenticationPackageName']","Event/EventData/Data[@Name='WorkstationName']","Event/EventData/Data[@Name='LogonGuid']","Event/EventData/Data[@Name='TransmittedServices']","Event/EventData/Data[@Name='LmPackageName']","Event/EventData/Data[@Name='KeyLength']","Event/EventData/Data[@Name='ProcessId']","Event/EventData/Data[@Name='ProcessName']","Event/EventData/Data[@Name='IpAddress']","Event/EventData/Data[@Name='IpPort']","Event/EventData/Data[@Name='ImpersonationLevel']"});var eventProperties = ((EventLogRecord) logEntry).GetPropertyValues(loginEventPropertySelector);}}catch (Exception){}
If we can pull all those properties, we can make them properties within Seq structured logs, which means each property can be used for queries, signal, dashboards, alerts ... it's not hard to see the benefits! 😀
Enter Seq.Client.WindowsLogins
Around this point, I was still working with the Seq.Client.EventLog base, and looking at extending the SeqApi and RawEvent class to add the properties, but I started to find myself stripping back the code to essentials and then building new features and tackling challenges that seemingly only arise for this kind of targeted implementation.
- The Windows event log can iterate through all log entries and send them to the EntryWritten event handler ... repeatedly.
- Examining each event log's properties adds overhead that can slow down this iteration substantially for a large volume of log entries.
- In some cases it appeared that this could cause events not to be logged, but more usually it would result in multiple duplicate events being logged for the same source event log entry.
To be fair, I think it's a result of a very large security log that overwrites events as needed, and has a high level of log activity. On a system with a relatively small security log and low log activity, this behaviour wasn't observed.
Other challenges and opportunities:
- The service itself had separate logging to file, using Serilog, for service level events. That breaks our model for application logging - the service itself should be able to send logs to Seq. Easily done with Serilog, but then why do we need the separate implementation for sending Event Log entries to Seq?
- We already have an approach to using a common logging library that ensures some standard properties are always present.
- We need a way to detect if the service has been stopped, causing new logins not be be detected
To reduce the overhead and time to log new logins, we need to filter and de-duplicate event log entries, so that only recent logs are examined, duplicates are ignored, and we only use the EventLogPropertySelector for the specific events we're watching.
To achieve this, I implemented logic to filter new EntryWritten events to ensure they're no more than 10 minutes old and haven't already been seen. I also filter the event id (instance id) and event type - if it's not an event id 4624 of type SuccessAudit, it's of no interest.
To keep track of events, I added a class, TimedEventBag, to which new event entry ids can be added with a 10 minute expiry time. It handles the expiry with an internal MemoryCache, so we can simply add new events with an EventList.Add(entry.Index), and check if the list already contains that event with EventList.Contains(index).
With this in place, we now reliably log events to Seq in a short time after the login occurs, and we only log a given event log entry once.
Double trouble, or the joys of Kerberos
One added snag though - Windows can actually log two event id 4624 events; one has a Logon Guid (eg. {4fabda43-ce7b-9d1b-8a03-da0f930a775c}) and one doesn't (Logon Guid shows as {00000000-0000-0000-0000-000000000000}).
The reason for this is that the populated Logon Guid is a correlation id with Kerberos events, while the empty Logon Guid is for "everything else". In a non-Kerberos environment, you'll only see the empty Logon Guid event. Both are essentially valid logon event entries, with the same properties except for this.
Since we're using this in a Kerberos environment and we only want to receive one log event for a login, so that we can reliably alert on a user login, I select only the event with a populated Logon Guid.
Getting the right logon type
The EventLogPropertySelector gives us all the event properties associated with an event id 4624, so it's quite trivial to look at the logon type for types 2 and 10.
Logon type 10 is easy - we only get these if someone logs in via a remote connection, such as an RDP (Remote Desktop) connection.
Logon type 2 can be challenging though, because some non-interactive processes (eg. services) can log event id 4624 with logon type 2 for a process that they're launching. Examples that I've seen include SQL Server Reporting Services and SQL Service Integration Services. On examinination, I found that these "non-interactive interactive processes" will log certain properties with a "-", which doesn't occur with "real" interactive processes.
For example, the "IPAddress" property will contain "127.0.0.1" for an interactive user, but "-" for these "non-user" events. That means all we need to do is examine one of these properties, and "IPAddress" will fit the bill nicely.
So with this and the Kerberos Logon Guid filter in mind, our extracted EventLogPropertySelector list for an event can now be pared down to only the events that we want to log to Seq;
public static bool IsNotValid(IList<object> eventProperties){//Only interactive users are of interest - logonType 2 and 10. Some non-interactive services can launch processes with logontype 2 but can be filtered.return (uint) eventProperties[8] != 2 && (uint) eventProperties[8] != 10 ||(string) eventProperties[18] == "-" ||eventProperties[12].ToString() == "00000000-0000-0000-0000-000000000000";}
Put a little Lurgle in your heart
So now the final piece - I mentioned a common logging library, and of course I'm referring to Lurgle.Logging. Using this provides us with automatically populated common properties like AppName and MachineName (among others), and allows consolidating the service and event log logging to a single implementation that means we can see everything happening in our Seq.Client.WindowsLogins instance.
This means that our event log properties can readily be sent to Seq with a single Lurgle that will result in a Seq message that's nicely formatted for readability, with a bunch of extra properties to devour!
Log.Level(Extensions.MapLogLevel(entry.EntryType)).AddProperty("EventId", entry.EventID).AddProperty("InstanceId", entry.InstanceId).AddProperty("EventTime", entry.TimeGenerated).AddProperty("Source", entry.Source).AddProperty("Category", entry.CategoryNumber).AddProperty("EventLogName", logName).AddProperty("EventRecordID", entry.Index).AddProperty("Details", entry.Message).AddProperty("SubjectUserSid", eventProperties[0]).AddProperty("SubjectUserName", eventProperties[1]).AddProperty("SubjectDomainName", eventProperties[2]).AddProperty("SubjectLogonId", eventProperties[3]).AddProperty("TargetUserSid", eventProperties[4]).AddProperty("TargetUserName", eventProperties[5]).AddProperty("TargetDomainName", eventProperties[6]).AddProperty("TargetLogonId", eventProperties[7]).AddProperty("LogonType", eventProperties[8]).AddProperty("LogonProcessName", eventProperties[9]).AddProperty("AuthenticationPackageName", eventProperties[10]).AddProperty("WorkstationName", eventProperties[11]).AddProperty("LogonGuid", eventProperties[12]).AddProperty("TransmittedServices", eventProperties[13]).AddProperty("LmPackageName", eventProperties[14]).AddProperty("KeyLength", eventProperties[15]).AddProperty("ProcessId", eventProperties[16]).AddProperty("ProcessName", eventProperties[17]).AddProperty("IpAddress", eventProperties[18]).AddProperty("IpPort", eventProperties[19]).AddProperty("ImpersonationLevel", eventProperties[20]).Add("[{AppName:l}] New login detected on {MachineName:l} - {TargetDomainName:l}\\{TargetUserName:l} at {EventTime:F}");
And, of course, we can send a simple heartbeat event every 10 minutes for handling with Event Timeout for Seq (and especially the latest release)!
private static void ServiceHeartbeat(object sender, EventArgs e){Log.Level(LurgLevel.Debug).AddProperty("ItemCount", EventList.Count).AddProperty("NextTime", DateTime.Now.AddMilliseconds(Config.HeartbeatInterval)).Add("{AppName:l} Heartbeat [{MachineName:l}] - Cache of timed event ids is at {ItemCount} items, Next Heartbeat at {NextTime:H:mm:ss tt}");}
The end result!
I've blanked out some properties from our production Seq, but here's a sample of the logging, including the heartbeats.
And here's some of the properties that are sent - we even include the original Windows event log text as a property, and you can see part of that at the top of the screenshot. Even with properties blanked out, I'm sure you get the idea.. this brings a lot of potential for monitoring and alerting!
Get the Seq Client for Windows Logins
Seq.Client.WindowsLogins is available for download from Github, with install instructions in the readme!
Comments