{"id":13341,"date":"2011-07-12T00:01:00","date_gmt":"2011-07-12T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2011\/07\/12\/parse-windows-trace-logs-by-using-powershell\/"},"modified":"2011-07-12T00:01:00","modified_gmt":"2011-07-12T00:01:00","slug":"parse-windows-trace-logs-by-using-powershell","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/parse-windows-trace-logs-by-using-powershell\/","title":{"rendered":"Parse Windows Trace Logs by Using PowerShell"},"content":{"rendered":"

Summary<\/strong>: Learn how to use Windows PowerShell to parse Windows trace logs.\n \n\"Hey,Hey, Scripting Guy! Is it possible to filter the results from an ETW log?\n—DK\n \n\"Hey,Hello DK,\nMicrosoft Scripting Guy Ed Wilson here. Sure there is.\nIn Saturday’s Weekend Scripter article<\/a>, 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<\/b> cmdlet to find and to read the trace. Yesterday, I continued the ETW discussion<\/a> by examining the datetime<\/b> stamp that is generated for each event.\nIn 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<\/i> 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 <\/i>switched parameter. The commands that follow illustrate these techniques.<\/p>\n

Get-WinEvent -ListLog *wmi*trace* -force<\/p>\n

(Get-WinEvent -ListLog *wmi*trace* -force).logname<\/p>\n

$WmiLog = (Get-WinEvent -ListLog *wmi*trace* -force).logname<\/p>\n

Get-WinEvent -LogName $wmiLog -Oldest\n \nTo parse a trace log, you monkey around with the message<\/i> portion of the trace log entry. This means that any of the parse text<\/a> type of articles, or regular expression<\/a> <\/i>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.\nAfter I have the reference to the WMI trace log stored in the $wmiLog<\/b> variable, I use it in my query to the Get-WinEvent<\/b> cmdlet. The command returns all the entries (remember the Oldest<\/i> switched parameter is required in these types of queries). I pipe the resulting trace log contents to the Where-Object<\/b> cmdlet (?<\/b> Is an alias for the Where-Object<\/b> cmdlet), and I look for entries that contain the word execquery<\/i>, which is one of the commands used by WMI when performing a query. I use the Select-Object<\/b> cmdlet (select<\/b> is an alias for the Select-Object<\/b> cmdlet) to choose only the message<\/b> 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:<\/p>\n

PS C:> Get-WinEvent -LogName $wmiLog -Oldest |<\/p>\n

? { $_.message -match ‘execquery’ } | select -ExpandProperty message<\/p>\n

GroupOperationId = 486; OperationId = 487; Operation = Start IWbemServices::Exe<\/p>\n

cQuery – select * from win32_bios; ClientMachine = NEWMRED; User = IAMMREDAdmi<\/p>\n

nistrator; ClientProcessId = 4392; NamespaceName = \\.rootcimv2\n \nI 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.\nIf 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<\/b> <\/i>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):<\/p>\n

Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match ‘execquery’ } |<\/p>\n

select -ExpandProperty message | more\n \nRather than using the Select-Object<\/b> cmdlet, at times I like to use the Format-Table<\/b> cmdlet (ft<\/b> is an alias for the Format-Table<\/b> cmdlet) with the wrap <\/i>switched parameter. This is particularly true if I want to use two or more properties. (I will use Format-Table<\/b> for 2–5 properties. If I have more than 5 properties, I generally use Format-List<\/b>). In the following query, I query the WMI trace log and look for entries that have the word reference<\/i> in the message<\/b> property. The word reference<\/i> appears in referencesof<\/b> types of WMI queries. In general, these referencesof<\/b> types of queries are used by WMI in preparation for performing the actual Select<\/b> command (although, it is perfectly valid—if advanced—for a user to write a referencesof<\/b> 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<\/i> switched parameter tightens up the display and makes for better output. The command and associated output are shown here.<\/p>\n

PS C:> Get-WinEvent -LogName $wmiLog -Oldest |<\/p>\n

? { $_.message -match ‘reference’ } | ft id, message -Wrap -AutoSize<\/p>\n

 <\/p>\n

Id Message<\/span><\/p>\n

1 GroupOperationId = 490; OperationId = 494; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – references of {__Win32Provider.Name=”WmiPerfClass”}; ClientMachi<\/p>\n

   ne = Local; User = IAMMREDAdministrator; ClientProcessId = 0; NamespaceName<\/p>\n

    = \\.rootCIMV2<\/p>\n

 1 GroupOperationId = 490; OperationId = 496; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – references of {__Win32Provider.Name=”CIMWin32″}; ClientMachine =<\/p>\n

    Local; User = IAMMREDAdministrator; ClientProcessId = 0; NamespaceName = <\/p>\n

   .rootCIMV2<\/p>\n

 1 GroupOperationId = 490; OperationId = 498; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – references of {__Win32Provider.Name=”CIMWin32″}; ClientMachine =<\/p>\n

    Local; User = IAMMREDAdministrator; ClientProcessId = 0; NamespaceName = <\/p>\n

   .rootCIMV2<\/p>\n

 1 GroupOperationId = 501; OperationId = 504; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – references of {__Win32Provider.Name=”WmiPerfClass”}; ClientMachi<\/p>\n

   ne = Local; User = IAMMREDAdministrator; ClientProcessId = 0; NamespaceName<\/p>\n

    = \\.rootCIMV2<\/p>\n

 1 GroupOperationId = 501; OperationId = 506; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – references of {__Win32Provider.Name=”WmiPerfClass”}; ClientMachi<\/p>\n

   ne = Local; User = IAMMREDAdministrator; ClientProcessId = 0; NamespaceName<\/p>\n

    = \\.rootCIMV2\n \nWhen 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<\/b> WMI query:<\/i><\/p>\n

PS C:> Get-WinEvent -LogName $wmiLog -Oldest |<\/p>\n

? { $_.message -match ‘win32_bios’ } | ft id, message -Wrap -AutoSize<\/p>\n

 <\/p>\n

Id Message<\/span><\/p>\n

1 GroupOperationId = 490; OperationId = 491; Operation = Start IWbemServices::<\/p>\n

   ExecQuery – select * from win32_bios; ClientMachine = NEWMRED; User = IAMMRE<\/p>\n

   DAdministrator; ClientProcessId = 4392; NamespaceName = \\.rootcimv2<\/p>\n

 2 ProviderInfo for GroupOperationId = 490; Operation = Provider::CreateInstanc<\/p>\n

   eEnum – Win32_BIOS; ProviderName = CIMWin32; ProviderGuid = {d63a5850-8f16-1<\/p>\n

   1cf-9f47-00aa00bf345c}; Path = %systemroot%system32wbemcimwin32.dll<\/p>\n

 1 GroupOperationId = 490; OperationId = 499; Operation = Start IWbemServices::<\/p>\n

   GetObject – win32_bios; ClientMachine = Local; User = IAMMREDAdministrator;<\/p>\n

    ClientProcessId = 0; NamespaceName = \\.rootCIMV2<\/p>\n

 \nThe 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):<\/p>\n

PS C:> Get-WinEvent -LogName $wmiLog -Oldest | ? { $_.message -match ‘win32_bio<\/p>\n

s’ } | ft TimeCreated, id, message -Wrap -AutoSize<\/p>\n

 <\/p>\n

TimeCreated<\/span>                              Id Message<\/span><\/p>\n

7\/11\/2011 3:23:47 PM                1 GroupOperationId = 490; OperationId = 491; Operation =<\/p>\n

Start IWbemServices::ExecQuery – select * from win32_bi<\/p>\n

os; ClientMachine = NEWMRED; User = IAMMREDAdministrat<\/p>\n

or; ClientProcessId = 4392; NamespaceName = \\.rootci<\/p>\n

mv2<\/p>\n

7\/11\/2011 3:23:47 PM                2 ProviderInfo for GroupOperationId = 490; Operation = Pr<\/p>\n

ovider::CreateInstanceEnum – Win32_BIOS; ProviderName =<\/p>\n

CIMWin32; ProviderGuid = {d63a5850-8f16-11cf-9f47-00aa<\/p>\n

00bf345c}; Path = %systemroot%system32wbemcimwin32.d<\/p>\n

ll<\/p>\n

7\/11\/2011 3:23:47 PM                1 GroupOperationId = 490; OperationId = 499; Operation =<\/p>\n

Start IWbemServices::GetObject – win32_bios; ClientMach<\/p>\n

ine = Local; User = IAMMREDAdministrator; ClientProces<\/p>\n

sId = 0; NamespaceName = \\.rootCIMV2<\/p>\n

 \nAs 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).\nDK, that is all there is to using the Get-WinEvent<\/b> 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<\/b> <\/i>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.\n \nI invite you to follow me on Twitter<\/a> and Facebook<\/a>. If you have any questions, send email to me at scripter@microsoft.com<\/a>, or post your questions on the Official Scripting Guys Forum<\/a>. See you tomorrow. Until then, peace.\nEd Wilson, Microsoft Scripting Guy<\/b>\n \n <\/p>\n","protected":false},"excerpt":{"rendered":"

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) […]<\/p>\n","protected":false},"author":596,"featured_media":87096,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[97,98,31,60,3,4,134,61,45,6],"class_list":["post-13341","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-event-logs","tag-logs-and-monitoring","tag-operating-system","tag-performance","tag-scripting-guy","tag-scripting-techniques","tag-troubleshooting","tag-weekend-scripter","tag-windows-powershell","tag-wmi"],"acf":[],"blog_post_summary":"

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) […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/13341","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/users\/596"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/comments?post=13341"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/13341\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media\/87096"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media?parent=13341"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=13341"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=13341"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}