Wednesday, October 24, 2012

Process Tracing with Log Parser

I've decided that I need to start blogging to improve my communication and teaching skills.  This is my first blog so feel free to provide constructive feedback and suggestions.

Security professionals involved in incident response often have to trace processes through security event logs. Even if the Windows audit settings are set correctly process tracing can still be a laborious task. To make things easier I've developed a query using Microsoft's Log Parser.

Let's begin with understanding what we're looking for.  In Windows 7, when the Audit Process Creation setting is set to Success within the Detailed Tracking section of the Advanced Audit Policy Configuration the system will create an entry in the Security Event Log with an Event ID of 4688. The entry looks like this in Event Viewer:

A new process has been created.

Subject:
Security ID: SYSTEM
Account Name: PC001$
Account Domain: DOMAIN
Logon ID: 0x3e7

Process Information:
New Process ID: 0x1bbc
New Process Name: C:\Windows\System32\dllhost.exe
Token Elevation Type: TokenElevationTypeDefault (1)
Creator Process ID: 0x2a8
<...snip>

Notice the New Process ID and Creator Process ID. This is the way that we'll trace processes back to the process that created them. Before we begin we need to know what fields to query against and to see how Log Parser sees the log data to make sure that our query works properly.

logparser -h -i:EVT

This command lists the fields available in the EVT input type of the local system and shows whether the data is a string (S), integer (I) or timestamp (T).

Fields:

EventLog (S)       RecordNumber (I)    TimeGenerated (T)
TimeWritten (T)    EventID (I)         EventType (I)
EventTypeName (S)  EventCategory (I)   EventCategoryName (S)
SourceName (S)     Strings (S)         ComputerName (S)
SID (S)            Message (S)         Data (S)

The fields we'll be using to trace processes are:

TimeGenerated
EventID
Message

Event Viewer formats the data so it's easier for humans to read. Since Log Parser doesn't do this specifically for Windows event logs we need to start by looking at how Log Parser displays data in the message field. So we start by running a simple query that dumps all event ID 4688 events to a CSV file

logparser 'SELECT message, eventID INTO c:\temp\processtracetest.csv FROM Security WHERE eventID = 4688' -i:EVT -o:CSV

When we open the CSV we see that the message column contains content that looks like this:

A new process has been created. Subject: Security ID: S-1-5-18 Account Name: PC001$ Account Domain: CORP Logon ID: 0x3e7 Process Information: New Process ID: 0x1bbc New Process Name: C:\Windows\System32\dllhost.exe Token Elevation Type: %%1936 Creator Process ID: 0x2a8 Token Elevation Type indicates the type of token that was assigned to the new process in accordance with User Account Control policy.
<...snip> 

Now to make things useful in process tracing we need to see columns of user IDs, process names, process IDs and parent process IDs. Unfortunately, there are no fields for those values so we're going to have to parse the data out of the message field.  Log Parser supports many functions available in SQL like EXTRACT_SUFFIX and EXTRACT_PREFIX. Let's start with extracting the process name.  To get the process name we want everything that occurs before "Token Elevation Type:" and after the last "\" in the file path.

Log Parser (as best as I can tell) reads data from the end of the line to the beginning of the line when executing an EXTRACT_SUFFIX command. The EXTRACT_SUFFIX function requires three parameters; the source field it's extracting from, the position parameter in case the string we're searching for occurs multiple times and the string that occurs right before the suffix we want to extract.

We can see that there are three '\' characters in our text and we want the data that occurs right after the first '\' (remember we're going in reverse) and since the position parameter starts at zero our query will have a zero there.  Also, because of escape characters you have to prepend a '\' with another '\' to have it actually read properly. Our EXTRACT_SUFFIX query looks like this:

EXTRACT_SUFFIX(message,0,'\\')

This gives us a result of:

dllhost.exe Token Elevation Type: %%1936 Creator Process ID: 0x2a8 Token Elevation Type indicates the type of token that was assigned to the new process in accordance with User Account Control policy.
<...snip>

That's a good start. Now we need to refine the query so that all we get is the process name. By nesting the EXTRACT_SUFFIX within an EXTRACT_PREFIX we can parse the beginning portion of the suffix query results.

EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'\\'),0,' Token Elevation Type:')

The result now is that we get the process name only. 

Quick side notes - In the query below the %SRC% parameter is passed from the Log Parser command as you can see in the comments section. This makes the query file re-usable and allows us to write the output results to a unique filename. I always like to put the command line that I use at the beginning of the query file so that I don't constantly have to recreate it, all I have to do is update the parameter I pass it for the computer I want to run the process trace on.

Now that we've created our own column of data based on the process name let's extend this out and look at the entire query.

/*
logparser file:"C:\Scripts\sql\ProcessTrace.sql?SRC=PC001" -i:EVT -o:CSV
*/
SELECT TimeGenerated AS Time,
EventID AS ID,
EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'Account Name: '),0,' Account Domain:') AS userID,
EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'New Process ID:'),0,'New Process Name:') AS newProcessID,
EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'\\'),0,'Token Elevation Type:') AS processName,
EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'New Process Name: '),0,' Token Elevation Type:') AS processPath,
EXTRACT_PREFIX(EXTRACT_SUFFIX(message,0,'Creator Process ID:'),0,'Token') AS parentProcessID,
Message AS RawEvent
INTO 'C:\temp\ProcTrace-%SRC%.csv'
FROM \\%SRC%\Security
WHERE EventID = 4688

If you don't use the AS function then the column name will be the query that was used to extract the results for that column.

If you've done everything right then you should be looking at a CSV file of the process execution history of your target system. In the example below we see that explorer.exe has a newProccessID of 0x1984 and OUTLOOK.exe at the bottom has a parentProcessID of 0x1984 indicating the it was launched by the explorer.exe process.





When I find a process that I want to trace back to it's parent I copy it to a separate tab and then create a filter in the original Excel tab that shows me only the processes that have a new process ID that matches the parent process ID.  Once I locate the row containing the parent process I copy that into the separate tab and continue until I have the full process history.  The final results look like this:







<...snip>

That's how I simplify process tracing using Log Parser and Excel.

<edited for grammar>

No comments: