Summary: Learn how to use date types to filter event trace logs in Windows PowerShell.
Hey, Scripting Guy! I am wondering, oh great scripting master: can I use Windows PowerShell to parse an ETW log file?
—JM
Hello JM,
Microsoft Scripting Guy Ed Wilson here. It is “oh dark thirty” in the Piedmont region of the United States. For some reason, I woke up early. It is Thursday as I write this article, and the Scripting Wife and I were up late last night listening to the PowerScripting Podcast. I thought Spencer Brown did a great job as the guest, and as usual, Hal Rottenberg was in top form as he played the suave and debonair talk show host. Jonathan Walz was grooving in the background—audiophile extraordinaire. The Scripting Wife loves the chat room conversation because it gives her a chance to hang out with her friends from all over the world. Anyway, because I was up late, and then again up early, I decided it would make for a great excuse to have a coffee day. My last coffee day occurred back in January when I was talking about scheduling Windows PowerShell scripts that require input values.
Anyway, JM, the “standard answer” is that Windows PowerShell can do anything. The other day on Twitter, someone asked if Windows PowerShell could be made to mow the grass. I believe it could be (here is a cool article about using Windows PowerShell to control robots). Now all you need is a robot lawn mower.
In Saturday’s Weekend Scripter article, I talked about working with Event Tracing for Windows (ETW) logs. I discussed how to enable and disable the logs, and how to use the Get-WinEvent cmdlet to find and to read the trace.
The first thing to do is to obtain the name of the log and to store it in a variable. I do this because it makes working interactively from the Windows PowerShell line easier to do. The actual log name I want to work with today is Microsoft-Windows-WMI-Activity/Trace. I can find the log name from one of the trace entries when I look in Event Viewer. Such an entry appears in the following figure.
After I have the log name stored in a variable, I can use the Get-WinEvent cmdlet to retrieve the message property (or other properties as appropriate). The following two commands store the Microsoft-Windows-WMI-Activity/Trace log name in a variable, and return the message property from each of the entries in the WMI Activity trace ETW log:
$wmiLog = (Get-WinEvent -ListLog *wmi*trace -force).logname
Get-WinEvent -LogName $wmilog -Oldest | select message
The two commands and associated output are shown in the following figure.
In the previous figure, the output of the message property appears truncated. At times, a truncated output provides enough information to allow for quick identification of a particular problem. In the case of the above output, there is not enough detailed information to allow for much exploration. The solution is to expand the message property. To expand the message property, use the expandproperty property from the Select-Object cmdlet. Here is the syntax of this command:
Get-WinEvent -LogName $wmilog -Oldest | select -ExpandProperty message
The command and associated output are shown in the following figure.
In attempting to work with individual event entries, it would be logical to use the date timestamp in a filter. I therefore take the time, cast it to a system.datetime object, and use it with a Where-Object filter. Unfortunately, no records are returned from the query. The two commands are shown here:
$date = [datetime]”7/6/2011 6:03:51 PM”
Get-WinEvent -LogName $wmilog -Oldest | where-object { $_.timecreated -eq $date }
If I change the operator from equals to greater than, the command produces output. The revised command and associated output are shown here (the ? character is an alias for Where-Object).
PS C:\> Get-WinEvent -LogName $wmilog -Oldest | ? { $_.timecreated -gt $date }
TimeCreated ProviderName Id Message
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 2 ProviderInfo for…
7/6/2011 6:04:01 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:04:42 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:04:42 PM Microsoft-Window… 3 Stop OperationId…
The reason the equality operator does not return any objects is because the timecreated property is an instance of a system.datetime object, and as such the property is more complex than a simple string. The following command explores the timecreated property. Both the command and associated output are shown here (the command is broken at the pipeline character for the sake of readability; in reality, it is normally typed on a single line):
PS C:\> Get-WinEvent -LogName $wmilog -Oldest -MaxEvents 1 |
Get-Member -Name timecreated
TypeName: System.Diagnostics.Eventing.Reader.EventLogRecord
Name MemberType Definition
TimeCreated Property System.Nullable`1[[System.DateTime, mscorlib, Version…
I can use the maxevents property to help retrieve a single record for exploration. In the following command, I store the eventlogrecord object in a variable named $record. I then display the timecreated property. The commands and output follow:
PS C:\> $record = Get-WinEvent -LogName $wmilog -Oldest -MaxEvents 1
PS C:\> $record.TimeCreated
Wednesday, July 06, 2011 6:03:51 PM
To get a better idea of what is involved in the datetime object, I send the results from the TimeCreated property across the pipeline to the Format-List cmdlet. I use the force parameter to ensure that any hidden properties display. The command and associated output are shown here.
PS C:\> $record.TimeCreated | Format-List -Force
Date : 7/6/2011 12:00:00 AM
Day : 6
DayOfWeek : Wednesday
DayOfYear : 187
Hour : 18
Kind : Local
Millisecond : 776
Minute : 3
Month : 7
Second : 51
Ticks : 634455722317760648
TimeOfDay : 18:03:51.7760648
Year : 2011
DateTime : Wednesday, July 06, 2011 6:03:51 PM
If I hone in on the timeofday property from the timecreated property, I see that another object is returned. The command and associated output are shown here.
PS C:\> $record.TimeCreated.TimeOfDay
Days : 0
Hours : 18
Minutes : 3
Seconds : 51
Milliseconds : 776
Ticks : 650317760648
TotalDays : 0.752682593342593
TotalHours : 18.0643822402222
TotalMinutes : 1083.86293441333
TotalSeconds : 65031.7760648
TotalMilliseconds : 65031776.0648
When I am only interested in the type of object contained in a property, I use the gettype method directly. The use of the gettype method and associated output are shown here:
PS C:\> ($record.TimeCreated.TimeOfDay).gettype()
IsPublic IsSerial Name BaseType
True True TimeSpan System.ValueType
It is possible to use the ticks to filter records. There are a couple of ticks available for this use. The first is a tick associated with the timespan object. This tick represents 100 nanoseconds since midnight. The tick is the smallest unit of time. In the code that follows, the ticks property from the timespan object contained in the timeofday property is displayed. Next, I store the tick in the $ticks variable, and use it to display event log entries that occur at the same time of day. The commands and associated output are shown here.
PS C:\> $record.TimeCreated.TimeOfDay.Ticks
650317760648
PS C:\> $ticks = $record.TimeCreated.TimeOfDay.Ticks
PS C:\> Get-WinEvent -LogName $wmilog -Oldest |
? { $_.timecreated.timeofday.ticks -eq $ticks }
TimeCreated ProviderName Id Message
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 1 GroupOperationId…
7/6/2011 6:03:51 PM Microsoft-Window… 3 Stop OperationId…
The other ticks property that is available is the one directly on the system.datetime object stored in the timecreated property. This ticks property represents the number of 100-nanosecond intervals that have elapsed since 12:00:00 midnight, January 1, 0001. The value of ticks from the datetime object is shown here:
PS C:\> $record.TimeCreated.Ticks
634455722317760648
JM, that is all there is to filtering ETW logs in the Get-WinEvent cmdlet using time stamps. Troubleshooting Windows Week will continue tomorrow when I will talk about searching the message results.
I invite you to follow me on Twitter and Facebook. If you have any questions, send email to me at scripter@microsoft.com, or post your questions on the Official Scripting Guys Forum. See you tomorrow. Until then, peace.
Ed Wilson, Microsoft Scripting Guy
0 comments