Blog Post: Parse Windows Trace Logs by Using PowerShell

Summary: Learn how to use Windows PowerShell to parse Windows trace logs.

 

Hey, Scripting Guy! Is it possible to filter the results from an ETW log?

—DK

 

Hello DK,

Microsoft Scripting Guy Ed Wilson here. Sure there is.

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. Yesterday, I continued the ETW discussion by examining the datetime stamp that is generated for each event.

In this article, I will continue exploring the WMI activity trace log. By way of a quick review, the first thing I need to remember is to use the force parameter when searching for trace logs—it will not be visible otherwise. I also should remember that I do not need to type the entire log name because I can use wildcard characters to assist. After I have found the proper log name, I can store the log name in a variable for quick access. When reading a trace log, I must remember to use the Oldest switched parameter. The commands that follow illustrate these techniques.

Get-WinEvent -ListLog *wmi*trace* -force

(Get-WinEvent -ListLog *wmi*trace* -force).logname

$WmiLog = (Get-WinEvent -ListLog *wmi*trace* -force).logname

Get-WinEvent -LogName $wmiLog -Oldest

 

To parse a trace log, you monkey around with the message portion of the trace log entry. This means that any of the parse text type of articles, or regular expression type of articles will be extremely useful when it comes to examining these logs. I am not going to repeat all that type of information here.

After I have the reference to the WMI trace log stored in the $wmiLog variable, I use it in my query to the Get-WinEvent cmdlet. The command returns all the entries (remember the Oldest switched parameter is required in these types of queries). I pipe the resulting trace log contents to the Where-Object cmdlet (? Is an alias for the Where-Object cmdlet), and I look for entries that contain the word execquery, which is one of the commands used by WMI when performing a query. I use the Select-Object cmdlet (select is an alias for the Select-Object cmdlet) to choose only the message property, and I expand the property so I can see all the information contained in the particular entry. The command (broken into two lines at the pipe character for clarity) and associated output are shown here:

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'execquery' } | select -ExpandProperty message

GroupOperationId = 486; OperationId = 487; Operation = Start IWbemServices::Exe

cQuery - select * from win32_bios; ClientMachine = NEWMRED; User = IAMMRED\Admi

nistrator; ClientProcessId = 4392; NamespaceName = \\.\root\cimv2

 

I like this view because it makes it rather easy to look at related entries. It is much faster than clicking entries in Event Viewer. In the entry above, the WMI query, namespace, computer name, and username all appear in the entry. This makes it easy to troubleshoot WMI failures.

If I have a trace log with a large number of entries (even a large number of entries that may match my query), I add a more command to the end of the command. The revised command appears here (I break the command at the pipe character for display on the blog; I do not break the command inside the Windows PowerShell console):

Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match 'execquery' } |

select -ExpandProperty message | more

 

Rather than using the Select-Object cmdlet, at times I like to use the Format-Table cmdlet (ft is an alias for the Format-Table cmdlet) with the wrap switched parameter. This is particularly true if I want to use two or more properties. (I will use Format-Table for 2–5 properties. If I have more than 5 properties, I generally use Format-List). In the following query, I query the WMI trace log and look for entries that have the word reference in the message property. The word reference appears in referencesof types of WMI queries. In general, these referencesof types of queries are used by WMI in preparation for performing the actual Select command (although, it is perfectly valid—if advanced—for a user to write a referencesof type of query directly). All of the matching entries from the logs are then displayed in a table with the ID in the first position, and the message wrapped for readability. The autosize switched parameter tightens up the display and makes for better output. The command and associated output are shown here.

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'reference' } | ft id, message -Wrap -AutoSize

 

Id Message

1 GroupOperationId = 490; OperationId = 494; Operation = Start IWbemServices::

   ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

   ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

    = \\.\root\CIMV2

 1 GroupOperationId = 490; OperationId = 496; Operation = Start IWbemServices::

   ExecQuery - references of {__Win32Provider.Name="CIMWin32"}; ClientMachine =

    Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName = \

   \.\root\CIMV2

 1 GroupOperationId = 490; OperationId = 498; Operation = Start IWbemServices::

   ExecQuery - references of {__Win32Provider.Name="CIMWin32"}; ClientMachine =

    Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName = \

   \.\root\CIMV2

 1 GroupOperationId = 501; OperationId = 504; Operation = Start IWbemServices::

   ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

   ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

    = \\.\root\CIMV2

 1 GroupOperationId = 501; OperationId = 506; Operation = Start IWbemServices::

   ExecQuery - references of {__Win32Provider.Name="WmiPerfClass"}; ClientMachi

   ne = Local; User = IAMMRED\Administrator; ClientProcessId = 0; NamespaceName

    = \\.\root\CIMV2

 

When troubleshooting WMI, one of my favorite techniques is to search the trace log for the specific WMI class name. This allows me to trace the operations related to a particular search or WMI query. As shown in the query and results below, the WMI provider for a specific class must be located before executing the actual Select * win32_bios WMI query:

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest |

? { $_.message -match 'win32_bios' } | ft id, message -Wrap -AutoSize

 

Id Message

1 GroupOperationId = 490; OperationId = 491; Operation = Start IWbemServices::

   ExecQuery - select * from win32_bios; ClientMachine = NEWMRED; User = IAMMRE

   D\Administrator; ClientProcessId = 4392; NamespaceName = \\.\root\cimv2

 2 ProviderInfo for GroupOperationId = 490; Operation = Provider::CreateInstanc

   eEnum - Win32_BIOS; ProviderName = CIMWin32; ProviderGuid = {d63a5850-8f16-1

   1cf-9f47-00aa00bf345c}; Path = %systemroot%\system32\wbem\cimwin32.dll

 1 GroupOperationId = 490; OperationId = 499; Operation = Start IWbemServices::

   GetObject - win32_bios; ClientMachine = Local; User = IAMMRED\Administrator;

    ClientProcessId = 0; NamespaceName = \\.\root\CIMV2

 

The two-column output from the previous command is pretty decent from a readability perspective. As discussed in yesterday’s Hey Scripting Guy! Blog post, the ETW log provider is such a high performer that many entries have exactly the same time stamp (down to the tick); therefore, filtering (or even displaying) the time stamp does little to aid understanding. This is illustrated in the following output (where I add the time stamp to the previous output):

PS C:\> Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match 'win32_bio

s' } | ft TimeCreated, id, message -Wrap -AutoSize

 

TimeCreated                              Id Message

7/11/2011 3:23:47 PM                1 GroupOperationId = 490; OperationId = 491; Operation =

Start IWbemServices::ExecQuery - select * from win32_bi

os; ClientMachine = NEWMRED; User = IAMMRED\Administrat

or; ClientProcessId = 4392; NamespaceName = \\.\root\ci

mv2

7/11/2011 3:23:47 PM                2 ProviderInfo for GroupOperationId = 490; Operation = Pr

ovider::CreateInstanceEnum - Win32_BIOS; ProviderName =

CIMWin32; ProviderGuid = {d63a5850-8f16-11cf-9f47-00aa

00bf345c}; Path = %systemroot%\system32\wbem\cimwin32.d

ll

7/11/2011 3:23:47 PM                1 GroupOperationId = 490; OperationId = 499; Operation =

Start IWbemServices::GetObject - win32_bios; ClientMach

ine = Local; User = IAMMRED\Administrator; ClientProces

sId = 0; NamespaceName = \\.\root\CIMV2

 

As is shown in the previous output, all three entries happened at the same time, so the time stamp does not improve output (in fact, it reduces readability by causing additional wrapping of the message output).

DK, that is all there is to using the Get-WinEvent cmdlet to parse WMI activity/trace logs. I encourage you to take some time to review the last couple of articles as well as this one, and play around with querying the message property. After all, you know what you need to find. Troubleshooting Windows Week will continue tomorrow when I will show you a really cool technique for automating the enabling and disabling of trace logs. Stay tuned: same batch time, same batch channel.

 

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

 

 

Amber Arbucci Christina Aguilera Kate Hudson Adriana Lima Brittany Daniel