Get-WinEvent, EventLogs, ETL, Providers on Win7 Part II

Working with Windows Tracing (ETL) logs
This is part of ongoing research project to understand how improved tracing providers in Windows 7 can help detect the presence of malware.  Microsoft has been improving event tracing for a number of years. The latest versions allows netsh to invoke multiple providers. After you have chosen your providers, you start the trace either by referencing the provider name or GUID. 'Netsh trace start' allows for keyword or capture filters, which can be useful if you know what specific events for which you need to trace. For this example, we will not create an NDIS capture ('capture=yes') nor will we select keywords or levels for the filters. After a few busy hours, this leads to quite a bit tracing.



[Cmd.exe]
netsh trace show providers | findstr "Network Security IP"
{6E7A2FC0-9244-4EE4-804F-E812924ABF26}  Windows NetworkMap Trace
{D9131565-E1DD-4C9E-A728-951999C2ADB5}  Network Profile Manager
{6B510852-3583-4E2D-AFFE-A67F9F223438}  Security: Kerberos Authentication
{CC85922F-DB41-11D2-9244-006008269001}  Local Security Authority (LSA)
{6D04BF88-60A5-4D02-BC5C-94A20BA490EC}  IPBusEnum Service Trace
{94335EB3-79EA-44D5-8EA9-306F49B3A040}  Downlevel IPsec Service
{94335EB3-79EA-44D5-8EA9-306F49B3A041}  Downlevel IPsec API
{EB004A05-9B1A-11D4-9123-0050047759BC}  TCPIP Service Trace
{A7EB57F6-145E-4F18-BD75-DBBF6F7E23A7}  WMP Network Sharing Service
{6165F3E2-AE38-45D4-9B23-6B4818758BD9}  Security: TSPkg
{37D2C3CD-C5D4-4587-8531-4696C44244C8}  Security: SChannel
{FB6A424F-B5D6-4329-B9D5-A975B3A93EAD}  Security: WDigest
{E4FF10D8-8A88-4FC6-82C8-8C23E9462FE5}  Downlevel IPsec NetShell Plugin
{5BBB6C18-AA45-49B1-A15F-085F7ED0AA90}  Security: NTLM Authentication


netsh trace show providers | findstr "NTLM Security Protocol"
{C92CF544-91B3-4DC0-8E11-C580339A0BF8}  NTLM Security Protocol


netsh trace start provider=Microsoft-Windows-Kernel-Network provider=Microsoft-Windows-Kernel-Process provider=Microsoft-Windows-Security-Auditing provider=Microsoft-Windows-Security-Netlogon provider=Microsoft-Windows-TCPIP provider="{C92CF544-91B3-4DC0-8E11-C580339A0BF8}"


In Powershell V2, 'Get-Winevent' is your ticket to parsing the trace (ETL) file. As a note, you can easily export the ETL format to (the new log format) ETVX and view either file format in Event Viewer. You can also export the file with 'netsh trace convert'. The size of the file increases greatly with the ETVX format. I don't recommend this unless you have a need.  Even a 50 MB ETL takes a while to process in Powershell (see below).  However, you can view the file and filter per eventID, provider, or otherwise inside the Event Viewer interface and then save the filtered events to a separate log.  Below, I show the respective file sizes of an ETL vs. and ETVX format. I then load the 54 MB ETL into a Powershell variable and export it into an ASCII format. This takes eleven minutes on an i5 core laptop.


[Powershell]
(ls NetTrace.etl | % {$_.length})/1MB
54.875


measure-command {netsh trace convert input=NetTrace.etl output=knpasntlm.evtx dump=EVTX}
Days              : 0
Hours             : 0
Minutes           : 8
Seconds           : 15
....


(ls .\knpasntlm.evtx  | % {$_.length})/1MB
883.06640625


measure-command {$KNPASNTLM=get-winevent -path 'NetTrace.etl' -oldest}
Days              : 0
Hours             : 0
Minutes           : 11
....


Analyzing the Trace


'Get-Winevent' has both XPath and Filterhashtable query options for working with event logs. But for working with raw tracing logs, we also have other some other options. Logparser 2.2, a six year old 'sql' parser works with ETL logs.  Once the file is loaded into a Powershell variable, we can query based on properties below. However, rather than create those queries right now, let us look at the properties of our variable and export variable contents to an ASCII file. Once again, this takes some time on a five core laptop.


$KNPASNTLM | gm | Select Name


Name
----
....
Message
ActivityId
Bookmark
ContainerLog
Id
Keywords
KeywordsDisplayNames
Level
LevelDisplayName
LogName
MachineName
MatchedQueryIds
Opcode
OpcodeDisplayName
ProcessId
Properties
ProviderId
ProviderName
Qualifiers
RecordId
RelatedActivityId
Task
TaskDisplayName
ThreadId
TimeCreated
UserId
Version


measure-command {$KNPASNTLM | Select TimeCreated,ID,RecordID, Message | ft -autosize | out-file -encoding ASCII knpasntlm.ASCII.txt}
Days              : 0
Hours             : 0
Minutes           : 6
...


Now we have a file we can look at in Linux, BSD, or Cygwin with wc, less, head, tail, awk, grep, etc.:
[Cygwin]
$ wc -l knpasntlm.ASCII.txt
491392 knpasntlm.ASCII.txt


$ head knpasntlm.ASCII.txt
TimeCreated            Id RecordId Message
-----------            -- -------- -------
1/31/2011 1:31:02 PM 1300        0 TCP: connection 0xfffffa8008e79170 (local=192.168.0.11:1193 remote=74.125.224.23:443) exists. State = EstablishedState. PID = 5776.
1/31/2011 1:31:02 PM 1300        1 TCP: connection 0xfffffa8004489cf0 (local=192.168.0.11:1076 remote=74.125.224.54:443) exists. State = EstablishedState. PID = 5776.
1/31/2011 1:31:02 PM 1300        2 TCP: connection 0xfffffa8004531cf0 (local=192.168.0.11:1037 remote=74.125.127.100:80) exists. State = CloseWaitState. PID = 4376.
1/31/2011 1:31:02 PM 1202        3 IP: Interface rundown: Index = 1, Linkspeed = 0 bps, PhysicalMediumType = NdisPhysicalMediumUnspecified, IP Address = 127.0.0.1   .
1/31/2011 1:31:02 PM 1202        4 IP: Interface rundown: Index = 12, Linkspeed = 54000000 bps, PhysicalMediumType = NdisPhysicalMediumNative802_11, IP Address = 192.168.0.11   .
1/31/2011 1:31:02 PM 1202        5 IP: Interface rundown: Index = 1, Linkspeed = 0 bps, PhysicalMediumType = NdisPhysicalMediumUnspecified, IP Address = 0.0.0.0 (Ignore IPv4 address), IPv6 address...
1/31/2011 1:31:02 PM 1202        6 IP: Interface rundown: Index = 12, Linkspeed = 54000000 bps, PhysicalMediumType = NdisPhysicalMediumNative802_11, IP Address = 0.0.0.0 (Ignore IPv4 address), IPv...


$ tail knpasntlm.ASCII.txt
1/31/2011 7:53:22 PM    0   491379
1/31/2011 7:53:22 PM    0   491380
1/31/2011 7:53:22 PM    0   491381
1/31/2011 7:53:22 PM    0   491382
1/31/2011 7:53:22 PM    0   491383
1/31/2011 7:53:22 PM    0   491384
1/31/2011 7:53:22 PM    0   491385
1/31/2011 7:53:22 PM    0   491386


$ grep connection knpasntlm.ASCII.txt  | wc -l
150079


$ grep connection knpasntlm.ASCII.txt  | less
1/31/2011 1:31:02 PM 1300        0 TCP: connection 0xfffffa8008e79170 (local=192.168.0.11:1193 remote=74.125.224.23:443) exists. State = EstablishedState. PID = 5776.
1/31/2011 1:31:02 PM 1300        1 TCP: connection 0xfffffa8004489cf0 (local=192.168.0.11:1076 remote=74.125.224.54:443) exists. State = EstablishedState. PID = 5776.
1/31/2011 1:31:02 PM 1300        2 TCP: connection 0xfffffa8004531cf0 (local=192.168.0.11:1037 remote=74.125.127.100:80) exists. State = CloseWaitState. PID = 4376.
1/31/2011 1:31:19 PM 1158      682 TCP: connection 0xfffffa8004489cf0 delivery 0xfffffa8004489e50 satisfied 0x35 bytes 0x17a requested. IsFullySatisfied = 0. RcvNxt = 2280417497.
1/31/2011 1:31:19 PM 1074      685 TCP: connection 0xfffffa8004489cf0: Received data with number of bytes = 53. ThSeq = 2280417497.
1/31/2011 1:31:19 PM 1156      686 TCP: connection 0xfffffa8004489cf0, delivery 0xfffffa8004489e50, Request 0xfffffa80040fb1a0  posted for 0x145 bytes, flags = 0. RcvNxt = 2280417550.
1/31/2011 1:31:45 PM 1158     1097 TCP: connection 0xfffffa8004489cf0 delivery 0xfffffa8004489e50 satisfied 0x35 bytes 0x145 requested. IsFullySatisfied = 0. RcvNxt = 2280417550.
1/31/2011 1:31:45 PM 1074     1100 TCP: connection 0xfffffa8004489cf0: Received data with number of bytes = 53. ThSeq = 2280417550.
....


$  grep -f search knpasntlm.ASCII.txt  | grep received | awk -F":" {'print $5'} | awk {'print $3'} | sort -nr | uniq -c | sort -nr | less
   2416
   1696 192.168.0.15
   1403 192.168.0.11
    586 224.0.0.252
    527 67.192.97.131
    403 74.125.224.54
    333 74.125.127.83
    313 74.125.53.19
    227 192.168.0.255
    174 74.125.155.191
    132 184.73.205.16
    128 74.125.127.17
    120 239.255.255.250
    107 208.71.123.76
    103 96.17.109.9
....


To be continued...