Tuesday, October 26, 2010

Episode #118: We're Watching... Well, Ed mostly

Tim logs in:

One of our (presumably) faithful followers, wrote in asking how to track a user's login and logout times. Here at CLKF, we don't have a problem with keeping an eye on employees, since we don't have any (yet). But once we get them, we will ensure they begin work promptly at 5am and work until at least 9pm. How, do you ask? Lashings. The same goes for poor performace. If morale drops, the beatings will continue until morale increases. Simple. And that is the way that Hal and Ed brought me onboard.

For those of you who don't live in a utopia similar to ours, you may need to track the login and logout times. We can do this a few different ways depending on your environment. Windows keeps track of the logon and logoff events in the event log. The way they are tracked depends on the version of Windows. That divide is between the newer versions, beginning with Vista, and the older versions.

Let's first look at Windows Vista, 7 and 2008. While only Windows 7 and 2008R2 come with PowerShell installed by default, these newer version have a new logging system. With the new system, the logon event ID is 4648 and the logoff event ID is 4647. With this new logging system (and PowerShell v2), we can use the cmdlet Get-WinEvent. However, all versions of Windows and PowerShell support Get-EventLog.

The Get-WinEvent cmdlet abstracts the log objects. This abstractions allows for searching of multiple logs at once, but it comes at a price. The abstraction makes searching for specific data is a little quirky. Here is what I mean.

PS C:\> Get-WinEvent -FilterHashtable @{LogName="Security";Id=4647,4648}

TimeCreated ProviderName Id Message
----------- ------------ -- -------
9/8/2010 6:51:42 PM Microsoft-Windows-Security-Auditing 4648 A logon was attempted...
9/8/2010 5:30:40 PM Microsoft-Windows-Security-Auditing 4647 User initiated logoff...
9/8/2010 4:40:24 PM Microsoft-Windows-Security-Auditing 4648 A logon was attempted...
9/8/2010 1:54:30 PM Microsoft-Windows-Security-Auditing 4647 User initiated logoff...
...


This abstracted command doesn't allow us to filter with using the -Id paramter, so we have to use a hashtable. The hashtable allows us to filter on any property of the underlying log. All we need to do is pick the property and the value for filtering, like this @{name1=value1,name2=value2}. It isn't that bad, but there is no tab completion for the properties used in the hash table.

Now we have a list of all the logon and logoff events, but we have to find events specific to our user. The username is in the message, so we need to filter for events related to the user in question.

PS C:\> Get-WinEvent -FilterHashtable @{LogName="Security";Id=4647,4648} | 
? { $_.Message | Select-String "skodo" }


TimeCreated ProviderName Id Message
----------- ------------ -- -------
9/8/2010 5:30:40 PM Microsoft-Windows-Security-Auditing 4647 User initiated logoff...
9/8/2010 4:40:24 PM Microsoft-Windows-Security-Auditing 4648 A logon was attempted...


The Where-Object (alias ?) is used to filter for events related to our user. We take the Message property and search it, with Select-String, for the username of that pesky Ed Skoudis. This gives us the full object for the event, and we have all the associated data. This data can exported to CSV, XML, or other formats.

Now on to those older versions which don't support Get-WinEvent, we have to use Get-EventLog cmdlet. The nice thing with Get-EventLog is that it is supported on all version of Windows and both versions of PowerShell.

PS C:\> Get-EventLog -LogName Security -InstanceId 528,538

Index Time EntryType Source InstanceID Message
----- ---- --------- ------ ---------- -------
337 Oct 9 8:35 SuccessAudit Security 528 Successful Logon:...
335 Oct 9 8:34 SuccessAudit Security 538 User Logoff:...
333 Oct 9 8:33 SuccessAudit Security 528 Successful Logon:...
331 Oct 9 8:32 SuccessAudit Security 538 User Logoff:...
329 Oct 9 8:31 SuccessAudit Security 528 Successful Logon:...
327 Oct 9 8:30 SuccessAudit Security 538 User Logoff:...
325 Oct 9 8:29 SuccessAudit Security 528 Successful Logon:...


This is a list of all the logon and logoff events, and to find entries for a specific user we filter just like we did above.

PS C:\> Get-EventLog -LogName Security -InstanceId 528,538 | ? { $_.Message | Select-String "skodo" }

Index Time EntryType Source InstanceID Message
----- ---- --------- ------ ---------- -------
333 Oct 9 8:33 SuccessAudit Security 528 Successful Logon:...
331 Oct 9 8:32 SuccessAudit Security 538 User Logoff:...


Now we know where Ed has been on "my" machines, let's see if Hal can track him down on his machines.

Hal checks out

Yes, let's see what the devious Ed has been up to with all his free time since he's not writing Command Line Kung Fu every week:


$ last
halpo pts/1 ip198-166-98-130 Fri Oct 1 22:29 - 22:47 (00:18)
tinytim pts/1 pool-196-22-144- Fri Oct 1 21:13 - 21:44 (00:31)
mrbucket pts/1 ip198-166-98-35. Fri Oct 1 16:51 - 16:52 (00:00)
tinytim pts/6 10.20.30.40 Fri Oct 1 14:57 - 15:29 (00:31)
skodo pts/1 h-68-202-198-66. Fri Oct 1 14:56 - 15:04 (00:08)
halpo pts/6 10.20.30.20 Fri Oct 1 08:27 - 11:14 (02:47)
halpo pts/6 10.20.30.20 Fri Oct 1 07:59 - 07:59 (00:00)
root console :0 Fri Oct 1 07:55 still logged in
skodo pts/1 h-68-202-198-66. Thu Sep 30 23:16 - 10:25 (11:08)
reboot system boot Thu Sep 30 23:15
reboot system down Thu Sep 30 23:09
skodo pts/14 h-68-202-198-66. Thu Sep 30 22:43 - down (00:31)
skodo pts/9 h-68-202-198-66. Thu Sep 30 22:38 - down (00:36)
halpo pts/7 ip198-166-98-130 Thu Sep 30 22:34 - 22:40 (00:05)
skodo pts/9 h-68-202-198-66. Thu Sep 30 22:24 - 22:35 (00:11)
skodo pts/9 h-68-202-198-66. Thu Sep 30 18:24 - 18:25 (00:00)
skodo pts/14 h-68-202-198-66. Thu Sep 30 17:45 - 18:22 (00:37)
skodo pts/7 h-68-202-198-66. Thu Sep 30 17:42 - 18:22 (00:39)
skodo pts/9 h-68-202-198-66. Thu Sep 30 17:18 - 18:22 (01:04)
halpo pts/7 ip198-166-98-130 Thu Sep 30 16:06 - 16:08 (00:02)
halpo pts/7 ip198-166-98-130 Thu Sep 30 16:02 - 16:03 (00:01)
tinytim pts/9 pool-196-22-144- Thu Sep 30 16:01 - 16:15 (00:13)
[...]

wtmp begins Fri Jul 8 10:49

Hmmm, suspiciously user "skodo" was the only person on the box the last time it rebooted. Ed, you've got some 'splaining to do! Actually, the person I really want to visit with the old "clue by four" is whoever left root logged in on the console. Bad form.

The last command operates on the system default wtmp file, usually /var/log/wtmp. On some Unix machines, this log grows forever without bound during the entire lifetime of the system. On other machines, the wtmp gets rotated weekly like other logs. If you want to look at an older wtmp file, use "last -f <filename>". This is also helpful when you're doing forensics on a Unix system image and you want to examine the wtmp file.

Notice in the above output that host names are displayed when reverse DNS information is available. The Linux version of the last command has a "-i" flag to always show IP addresses. Unfortunately, this option isn't widely available on older, proprietary Unix flavors. One option that is common to most Unix-like OSes that I've tried is the "-a" flag that moves the host information to the last column of output so that it doesn't get truncated.

The last command also lets you be selective. For example, you can ask for the most recent 5 logins:

$ last -5
halpo pts/1 ip198-166-98-130 Fri Oct 1 22:29 - 22:47 (00:18)
tinytim pts/1 pool-196-22-144- Fri Oct 1 21:13 - 21:44 (00:31)
mrbucket pts/1 ip198-166-98-35. Fri Oct 1 16:51 - 16:52 (00:00)
tinytim pts/6 10.20.30.40 Fri Oct 1 14:57 - 15:29 (00:31)
skodo pts/1 h-68-202-198-66. Fri Oct 1 14:56 - 15:04 (00:08)

Or perhaps we'd like to see Ed's last three logins:

$ last -3 skodo
skodo pts/1 h-68-202-198-66. Fri Oct 1 14:56 - 15:04 (00:08)
skodo pts/1 h-68-202-198-66. Thu Sep 30 23:16 - 10:25 (11:08)
skodo pts/14 h-68-202-198-66. Thu Sep 30 22:43 - down (00:31)


We can even get a history of the system reboots:

$ last reboot
reboot system boot Thu Sep 30 23:15
reboot system down Thu Sep 30 23:09
reboot system boot Thu Mar 18 10:44
reboot system down Thu Mar 18 10:38
reboot system boot Thu Mar 18 10:25
reboot system down Thu Mar 18 10:08
[...]

Unfortunately, there aren't any options to select specific fields out of the last output. So you're pretty much stuck with piping last into awk to pull out the information you want.