I recently had the opportunity to teach at the US Cyber Challenge Camp. The campers were awesome and we had tons of geeky fun.
Among other topics, I covered securing Linux systems, including some work with SELinux. One of the problems you run into when dealing with SELinux is reading the SELinux-related messages in the system audit.log file. Here's a sample entry:
# egrep '^type=(AVC|SELINUX)' /var/log/audit/audit.log | tail -1
type=AVC msg=audit(1279670222.302:199): avc: denied { name_bind } for pid=18232 comm="httpd"
src=31337 scontext=user_u:system_r:httpd_t:s0 tcontext=system_u:object_r:port_t:s0 tclass=tcp_socket
The audit.log files live under /var/log/audit, and the SELinux entries start with either "type=AVC" or "type=SELINUX". I use "tail -1" above to pull out just the last line of output.
The first thing you might notice is that, unlike most Unix log files, the audit.log lines don't appear to contain a timestamp. In fact, there is a timestamp on each line-- it's just in Unix epoch time, or seconds since Jan 1, 1970. The big number inside the "msg=audit(...)" section is the epoch time value (so "1279670222" in the example above). Back in Episode #77, Adrian Shaw showed us how to convert this value into a human-readable timestamp:
# date -d @1279670222
Tue Jul 20 16:57:02 PDT 2010
One of the campers challenged me to come up with some Command-Line Kung Fu to automatically translate the epoch time values and rewrite each line with the human-readable time format at the beginning of the line. It took me a little while to figure out a solution, but I eventually ended up with:
# egrep '^type=(AVC|SELINUX)' /var/log/audit/audit.log |
while read line; do
time=`echo $line | sed 's/.*audit(\([0-9]*\).*/\1/'`;
echo `date -d @$time` $line;
done
[...]
Tue Jul 20 16:57:02 PDT 2010 type=AVC msg=audit(1279670222.302:199): avc: denied { name_bind }
for pid=18232 comm="httpd" src=31337 scontext=user_u:system_r:httpd_t:s0
tcontext=system_u:object_r:port_t:s0 tclass=tcp_socket
I decided to use a while loop to read the input line-by-line because it gave me more flexibility to run multiple commands against each line. First I use sed to filter out the epoch time value and store it in the variable $time. The sed expression is a substitution. The LHS matches the entire line, but specifically matches the epoch time value as a sub-expression which we delimit with "\(...\)". Read the regex on the LHS as "any amount of stuff (`.*'), then `audit(' followed by zero or more digits (`[0-9]*'), followed by a bunch more stuff (`.*')". We replace everything we matched on the LHS with the epoch time value we matched in the subexpression ("\1"). Thus the output of the sed expression will be just the epoch time value.
Once we extract the epoch time value, we can call "date -d @$time". All we have to do at that point is output the result of the date command followed by the original input line which has been hanging out in $line all this time. Whee!
While this is really useful on Linux systems, there's no real equivalent in the Windows environment. But I sent Tim a copy of a Linux audit.log file to see what he could do with it in Powershell. This is a situation you might legitimately have to deal with if you were analyzing a Linux system using a Windows forensics tool. Let's see how good Tim's parsing skills are, shall we?
Tim pitches a tent:
I find it rather ironic that the Security Enhanced Linux's audit log seems to be lacking an enhancement that would be useful for auditing. Now, let's dive into some level 1 parsing!
PS C:\> Select-String "[0-9]{10}" audit.log | select @{Name="Epoch";
Expression={$_.Matches[0].Value}}, line | fl
Epoch : 1279670222
Line : type=AVC msg=audit(1279670222.302:199): avc: denied { name_bind } for
pid=18232 comm="httpd" src= 31337 scontext=user_u:system_r:
httpd_t:s0 tcontext=system_u:object_r:port_t:s0 tclass=tcp_socketWe start off using Select-String to both read the file and find the epoch timestamp. The results are piped into Select-Object (alias select), which is used to display the line as well as create a new epoch property.There are now two properties, the epoch stamp and the line. Let's crank it up a notch and reformat the timestamp. Get ready for level 2 parsing!
PS C:\> Select-String "[0-9]{10}" audit.log | select @{Name="TimeStamp";
Expression={(Get-Date 1/1/1970).AddSeconds($_.Matches[0].Value)}}, line | fl
TimeStamp : 7/20/2010 11:57:02 PM
Line : type=AVC msg=audit(1279670222.302:199): avc: denied { name_bind } for
pid=18232 comm="httpd" src=31337 scontext=user_u:system_r:
httpd_t:s0 tcontext=system_u:object_r:port_t:s0 tclass=tcp_socketIn Level 2, we do the same thing as Level 1, except we reformat the timestamp. How do we rewrite the timestamp? Epoch time is just the number of seconds since 1/1/1970. So all we need to do is the math.(Get-Date 1/1/1970).AddSeconds($_.Matches[0].Value)Ok, so we have the results we are looking for, and we could leave it here. But Hal filtered for lines containing AVC or SELINUX, and we can't let Hal beat us. Get ready for Level 3!
PS C:\> Select-String "[0-9]{10}" audit.log | select @{Name="TimeStamp";
Expression={(Get-Date 1/1/1970).AddSeconds($_.Matches[0].Value)}}, line |
? { $_.Line -match "type=(AVC|SELINUX)" }Nothing fancy here, just added filtering. One minor problem, Select-String is being used for parsing and then the line is searched again by the Where-Object (alias ?) filter. The redundant searching will slow things down, so let's speed it up. Get ready for Level 4!PS C:\> Select-String "type=(AVC|SELINUX) msg=audit\(([0-9]+)" audit.log |The regular expression is juiced up to do the filtering and find the timestamp. The juiced regex returns multiple groups and must be accesses differently (as shown above).
select @{Name="TimeStamp"; Expression={(Get-Date 1/1/1970).AddSeconds($_.Matches[0].Groups[2].Value)}}, line
Group 0: type=AVC msg=audit(1279670222That is how you parse the audit.log with PowerShell. I hope it wasn't too painful parsing my parsing.
Group 1: AVC
Group 2: 1279670222