28 January, 2017

Parse user name from events - OS

Have you ever needed to parse fields or text from Windows Event Log? Even if the answers is no, read on. You never know when someone stops you on the road and holds a gun to your head and shouts until you parse all the fields from those 100 000 events.

My example was just about parsing user names from events in the Application log in a very friendly situation - no guns and shouting involved...
There were 300 000+ of these events in the last 24 hours and I had to find out from them the list of users with connection to the app and a connection count for each user in the same time frame.

This is how the events I'm parsing look like:

Event with User name to parse and count

First attempt

I used Get-WinEvent and filtered in its hash based switch as much as possible to speed up the query for events. Something like:
Get-WinEvent -ea SilentlyContinue -FilterHashtable @{LogName="Application"; StartTime=$timelimit; id=998}

The events will tell me the SID (Security IDentifier) of the user who generated the event, to look up the user name I used the SecurityIdentifier and then the NTAccount classes of System.Security.Principal:
Select @{e={(New-Object System.Security.Principal.SecurityIdentifier($_.userID)).Translate([System.Security.Principal.NTAccount])}; l="User";}

The trick to make this a one-liner was to generate the user name on the fly when creating a custom object with 'Select' in the command

Full command and the measure of run time:
measure-command {$timelimit=(Get-Date).addhours(-24); $tmp=Get-WinEvent -ea SilentlyContinue -FilterHashtable @{LogName="Application"; StartTime=$timelimit; id=998} | Select @{e={(New-Object System.Security.Principal.SecurityIdentifier($_.userID)).Translate([System.Security.Principal.NTAccount])}; l="User";} | group user}

Days              : 0
Hours             : 0
Minutes           : 41
Seconds           : 0
Milliseconds      : 11

Second attempt - with regex parsing

Well, 41 minutes doesn't look like a lot of time when you are spending with your loved ones, but it's way above the limit of the patience of an average IT guy... Remember the first part of this article? I was lucky enough with this application that it logged the user name into the message of the event (with some other random text as well).

So let's try something different:
measure-command {$timelimit=(Get-Date).addhours(-24); $tmp=Get-WinEvent -ea SilentlyContinue -FilterHashtable @{LogName="Application"; StartTime=$timelimit; id=998} | Select @{e={$matches=$null;$a=($_.message -match "UserName: (?<users>[^`n]+)"); $matches.user}; l="User";} | group user}

Days              : 0
Hours             : 0
Minutes           : 8
Seconds           : 13
Milliseconds      : 54

Very nice, 80% reduction on run time. What's different on this run?
The reason why this is quicker because the command does not read into Active Directory to look up a SID and translate it to user name, instead, it just parses the user name from the message field of the event with a regex pattern:
$matches=$null;$a=($_.message -match "UserName: (?<users>[^`n]+)"); $matches.user

Hope this helps saving a bit of time for some of you and can spend this away from the computer thinking about the next powershell trick!


No comments:

Post a Comment