{"id":72761,"date":"2015-10-14T00:01:00","date_gmt":"2015-10-14T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2015\/10\/14\/packet-sniffing-with-powershell-looking-at-messages\/"},"modified":"2019-02-18T09:34:54","modified_gmt":"2019-02-18T16:34:54","slug":"packet-sniffing-with-powershell-looking-at-messages","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/packet-sniffing-with-powershell-looking-at-messages\/","title":{"rendered":"Packet Sniffing with PowerShell: Looking at Messages"},"content":{"rendered":"

Summary<\/b>: Microsoft Scripting Guy Ed Wilson talks about looking at the message field in a packet log with Windows PowerShell.<\/span><\/p>\n

Microsoft Scripting Guy, Ed Wilson, is here. Yesterday I begin analyzing a packet trace log.<\/p>\n

Note<\/strong>  For more information about setting up and making a packet trace, see Packet Sniffing with PowerShell: Getting Started<\/a>. For more information about doing basic analytics, see Use PowerShell to Parse Network Log<\/a>.<\/p>\n

You may be surprised if you have rebooted your computer, logged off and back on, and opened and closed Windows PowerShell. If you go to create a new net event session, and you call it session1 (like I did yesterday), you will get an error message today.<\/p>\n

How can that be? Well, obviously Windows PowerShell remembers what you did yesterday when you created the session in the first place. A big red error message appears stating that an object already exists. Well, duh. Obviously an object already exists or it would not be an object.<\/p>\n

That is a somewhat ambiguous error to say the least. True, but ambiguous. To clear up the matter, I need to use the Remove-NetEventSession<\/b> cmdlet. The error message and the solution are shown in the following image:<\/p>\n

\"Image<\/a><\/p>\n

Now I have removed my error, so I can create the session anew, add NetEventProvider<\/b>, and start the net event session:<\/p>\n

$session = New-NetEventSession -Name "Session1"<\/p>\n

Add-NetEventProvider -Name "Microsoft-Windows-TCPIP" -SessionName "Session1<\/p>\n

Start-NetEventSession -Name "Session1"<\/p>\n

Now, I reproduce my problem, and then I stop my net event session:<\/p>\n

Stop-NetEventSession -Name session1<\/p>\n

I read the contents of the network trace log. I have to specify the –Oldest<\/b> switch to avoid errors due to the way the log contents are read. This command is shown here:<\/p>\n

$log = Get-WinEvent -Path $session.LocalFilePath –Oldest<\/p>\n

The following image shows these commands and any associated output.<\/p>\n

\"Image<\/a><\/p>\n

Now I want to see what timespan is documented by this trace, so I use New-Timespan<\/b>:<\/p>\n

New-TimeSpan -end ($log | select -Last 1).timecreated -start ($log | select -first 1).Timecreated<\/p>\n

I can see that it covers 2 minutes and 15 seconds. This might be enough to document my problem. I also want to see how many entries I have. It turns out that I have over 11,000 entries:<\/p>\n

PS C:\\> $log.Count<\/p>\n

11328<\/p>\n

Sure is a good thing that Windows PowerShell is great at parsing log files!<\/p>\n

Look at the Message field<\/h2>\n

In the trace log, the basic fields of the log are TimeCreated<\/b>, ID<\/b>, LevelDisplayName<\/b>, and Message<\/b>. The ID can be a great way to correlate events. But the Message<\/b> field shows what is going on. To parse this message field, one can use Select-String<\/b>.<\/p>\n

Note <\/b> Luckily beginning with Windows PowerShell 3.0, PowerShell has what I call an automatic foreach<\/b>—that is, it will automatically expand a collection of objects and allow me to examine a single property. This is a huge time saving feature, and one of my favorites. I wrote about it in PowerShell Looping: The Automatic Foreach<\/a>.<\/p>\n

All I need to do is access the message property from my collection of 11,000 events stored in the $log<\/b> variable. I pipe the output to the Select-String<\/b> cmdlet and do a simple match on the word fail<\/b>. The command is shown here:<\/p>\n

$log.message | Select-String -SimpleMatch 'fail'<\/p>\n

The output includes a lot of records. They tend to look like the following:<\/p>\n

TCP: connection 0xffffe000577e2430 (local=192.168.0.7:54083<\/p>\n

remote=127.0.0.1:443) connect attempt failed with status = {Device Timeout}<\/p>\n

The specified I\/O operation on %hs was not completed before the time-out period expired.<\/span><\/p>\n

It appears that there are different connection attempts that are failing with a timeout. Hmmm…how often is this happening? Well, I pipe the output to Measure-Object<\/b> (measure<\/b> is an alias):<\/p>\n

PS C:\\> $log.message | Select-String -SimpleMatch 'fail' | measure<\/p>\n

Count    : 81<\/p>\n

Average  :<\/p>\n

Sum      :<\/p>\n

Maximum  :<\/p>\n

Minimum  :<\/p>\n

Property :<\/p>\n

81 times in a 2 minute time frame. That sounds like it could be bad, and it would certainly explain the slowness of my computer. But what is it really? Well, I need to dive into the message field and see what is really connecting to what, and how many times the connections are failing.<\/p>\n

Before Windows PowerShell 5.0, this could have caused me some concern. I would have been falling back to write complicated REGEX patterns, and that would have taken some experimenting to get right. But with Windows PowerShell 5.0, I can parse this in no time at all because I have the ConvertFrom-String<\/b> cmdlet. Here is the command I use:<\/p>\n

$log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String<\/p>\n

The output that comes back is a collection of 27 fields. The default name is p1 – p27<\/b>, but the doesn't matter because I see that I want P4 (my local IP address and port) and P5 (the remote IP address and port).<\/p>\n

As shown here, I also already know the connections are failing with a timeout because that is what I found earlier:<\/p>\n

PS C:\\> $log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String<\/p>\n

P1  : TCP:<\/p>\n

P2  : connection<\/p>\n

P3  : -35182904204240<\/p>\n

P4  : (local=192.168.0.7:54083<\/p>\n

P5  : remote=127.0.0.1:443)<\/p>\n

P6  : connect<\/p>\n

P7  : attempt<\/p>\n

P8  : failed<\/p>\n

P9  : with<\/p>\n

P10 : status<\/p>\n

P11 : =<\/p>\n

P12 : {Device<\/p>\n

P13 : Timeout}<\/p>\n

P14 : The<\/p>\n

P15 : specified<\/p>\n

P16 : I\/O<\/p>\n

P17 : operation<\/p>\n

P18 : on<\/p>\n

P19 : %hs<\/p>\n

P20 : was<\/p>\n

P21 : not<\/p>\n

P22 : completed<\/p>\n

P23 : before<\/p>\n

P24 : the<\/p>\n

P25 : time-out<\/p>\n

P26 : period<\/p>\n

P27 : expired..<\/p>\n

<output truncated><\/p>\n

All I need to is select P4 and P5. This command is shown here:<\/p>\n

$log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String | select p4, p5<\/p>\n

Here is the output now:<\/p>\n

PS C:\\> $log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String | selec<\/p>\n

t p4, p5<\/p>\n

P4                       P5<\/p>\n

—                       —<\/p>\n

(local=192.168.0.7:54083 remote=127.0.0.1:443)<\/p>\n

(local=192.168.0.7:54085 remote=127.0.0.2:443)<\/p>\n

<output truncated><\/p>\n

I want to dive in and see where I am really having my problem. To do this, I want to group the output. This will show me the actual number of times each connection to each server is failing. The command I use is:<\/p>\n

$log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String | select p4, p5 | group p5 | sort count –Descending<\/p>\n

Here is the output:<\/p>\n

PS C:\\> $log.message | Select-String -SimpleMatch 'fail' | ConvertFrom-String | selec<\/p>\n

t p4, p5 | group p5 | sort count -Descending<\/p>\n

Count Name                      Group<\/p>\n

—– —-                      —–<\/p>\n

    7 remote=127.0.0.1:80)  {@{P4=(local=192.168.0.7:54228; P5=remote=127.0….<\/p>\n

    7 remote=127.0.0.2:… {@{P4=(local=192.168.0.7:54199; P5=remote=127.0….<\/p>\n

    6 remote=127.0.0.3:80)  {@{P4=(local=192.168.0.7:54204; P5=remote=127.0….<\/p>\n

<output truncated><\/p>\n

That is all there is to using Windows PowerShell to parse a network trace log.  Join me tomorrow when I will talk about more way cool stuff.<\/p>\n

I 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.<\/p>\n

Ed Wilson, Microsoft Scripting Guy<\/b> <\/span><\/p>\n","protected":false},"excerpt":{"rendered":"

Summary: Microsoft Scripting Guy Ed Wilson talks about looking at the message field in a packet log with Windows PowerShell. Microsoft Scripting Guy, Ed Wilson, is here. Yesterday I begin analyzing a packet trace log. Note  For more information about setting up and making a packet trace, see Packet Sniffing with PowerShell: Getting Started. For […]<\/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":[37,609,3,45],"class_list":["post-72761","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-networking","tag-powershell-5","tag-scripting-guy","tag-windows-powershell"],"acf":[],"blog_post_summary":"

Summary: Microsoft Scripting Guy Ed Wilson talks about looking at the message field in a packet log with Windows PowerShell. Microsoft Scripting Guy, Ed Wilson, is here. Yesterday I begin analyzing a packet trace log. Note  For more information about setting up and making a packet trace, see Packet Sniffing with PowerShell: Getting Started. For […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/72761","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=72761"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/72761\/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=72761"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=72761"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=72761"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}