Parsing Group Policy’s gpsvc.log with PowerShell

Troubleshooting a Group Policy issue this week has had me enabling the Group Policy debug log and trying to make head or tail of it.

The log looks like this:

GPSVC(23ec.341c) 23:25:15:981 Waiting for machine group policy thread to terminate.
GPSVC(23ec.341c) 23:25:16:008 CGPService::KeepServiceAlive: Beginning WaitForSingleObject.
GPSVC(23ec.341c) 23:25:16:031 CGPService::KeepServiceAlive: Completed WaitForSingleObject.
GPSVC(23ec.341c) 23:25:16:061 machine group policy thread has terminated.
GPSVC(23ec.341c) 23:25:16:091 CGroupPolicySession::CleanupEnvironment:--
GPSVC(23ec.341c) 23:25:16:573 Deleting machine
GPSVC(1478.1d60) 23:50:10:565 CGPNotify::OnNotificationTriggered: SetEvent = 0x30c
GPSVC(1478.1d60) 23:50:10:595 CGPNotify::OnNotificationTriggered: SetEvent = 0x288
GPSVC(1478.1d60) 23:50:10:631 CGPNotify::OnNotificationTriggered: SetEvent = 0x38c
GPSVC(1478.1d60) 23:50:10:674 CGPNotify::OnNotificationTriggered: SetEvent = 0x3cc

Since the log includes timestamps, I thought it would be a good idea to parse the log with PowerShell so that I could do some comparisons between log entries. I started down this path, and then discovered later on that there are multiple processes, and multiple threads, all logging to the same log file. That leads to entries being a bit all over the place.

Regardless of that, I soldiered on – more for the sake of experimentation, and ended up with a function that will parse each line from the log into a custom PSObject containing process ID, thread ID, timestamp, and the message:

function Get-GPLog {
    if (!(Test-Path "$env:windirdebugusermodegpsvc.log")) { Write-Error "Can't access gpsvc.log"; return }

    # Our regular expression to capture the parts of each log line that are of interest
    $regex = "^GPSVC((?<pid>[0-9A-Fa-f]+).(?<tid>[0-9A-Fa-f]+)) (?<time>d{2}:d{2}:d{2}:d{3}) (?<message>.+)$"

    # Get the content of gpsvc.log, ensuring that blank lines are excluded
    $log = Get-Content $env:windirdebugusermodegpsvc.log -Encoding Unicode | Where-Object {$_ -ne "" } 

    # Loop through each line in the log, and convert it to a custom object
    foreach ($line in $log) {
        # Split the line, using our regular expression
        $matchResult = $line | Select-String -Pattern $regex

        # Split up the timestamp string, so that we can convert it to a DateTime object
        $splitTime = $matchResult.Matches.Groups[3].Value -split ":"

        # Create a custom object to store our parsed data, and put it onto the pipeline.
        # Note that we're also converting the hex PID and TID values to decimal
        [pscustomobject]@{
            process_id = [System.Convert]::ToInt32($matchResult.Matches.Groups[1].Value,16);
            thread_id = [System.Convert]::ToInt32($matchResult.Matches.Groups[2].Value,16);
            time = (Get-Date -Hour $splitTime[0] -Minute $splitTime[1] -Second $splitTime[2] -Millisecond $splitTime[3])
            message = $matchResult.Matches.Groups[4].Value
        }
    }
}

From there, it’s easy to pipe the output to Group-Object or Where-Object to narrow down your search.

# Get all log entries, and group by process ID
Get-GpLog | Group-Object process_id | Sort-Object -Property Count -Descending

# or

# Get all log entries for a specific process ID
Get-GpLog | Where-Object {$_.process_id -eq 11280}

image

There’s one caveat with this whole process, and that’s the fact that the gpsvc.log entries don’t contain a full date – only the time component. This means that all log entries parsed by this function appear to be “today”.

I’m particularly happy that I got the regular expression working correctly. It ended up looking like this:

^GPSVC((?<pid>[0-9A-Fa-f]+).(?<tid>[0-9A-Fa-f]+)) (?<time>d{2}:d{2}:d{2}:d{3}) (?<message>.+)$

This regex, which I’m sure could be done much more efficiently by a regex guru, uses capturing groups to extract the various segments of each line. When combined with Select-String –Pattern, you get the following output:

image

We’re not interested in the first group as it’s returning the entire log line, but the subsequent groups are exactly what we’re after:

  1. PID
  2. TID
  3. Timestamp
  4. Message

There’s a tool that already does this and more. It’s called SysProSoft Policy Reporter, and it’s free. Download it here. Below is one of the screenshots from their “tour”.

Additionally, gpresult outputs some great stuff when you use /H, just ensure that it’s run with elevated privileges:

image

image

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s