reading the ETW events in PowerShell
When testing or otherwise controlling a service, you need to read its log that gets written in the form of ETW events. There is the basic cmdlet Get-WinEvent that does this but with it you can't just read the events continuously. Instead you have to keep polling and connecting the new events to the previous ones. I want to show the code that does this polling.
The basic use that starts this reading in a job whose output can be sent into expect is like this:
$col_job = Start-Job -Name $LogJobName -ScriptBlock {
param($module)
Import-Module $module
# -Nprev guards against the service starting earlier than the poller
Read-WinEvents -LogName Microsoft-Windows-BootEvent-Collector/Admin -Nprev 1000 | % {
"$($_.TimeCreated.ToString('yyyy-MM-dd HH:mm:ss.fffffff')) $($_.Message)"
}
} -Args @("myscriptdir\TextTools.psm1")
The job starting itself is a bit convoluted because the interpreter in the job doesn't inherit anything at all from the current interpreter. All it gets is literally its arguments. So to use a function from a module, that module has to be imported explicitly from the code in the job.
The reading of events is pretty easy - just give it the ETW log name. If you don't care about the events that might be in the log from before, that's it. If you do care about the previous events (such as if you are just starting the service and want to see all the events it had sent since the start), the parameter -Nprev says that you want to see up to this number of the previously logged events. This is more reliable than trying to start the log reading job first and then the service.
Of course, if you've been repeatedly stopping and starting the service, the log would also contain the events from the previous runs. That's why the limit N is useful, and also you can clean the event buffer in ETW with
wevtutil qe Microsoft-Windows-BootEvent-Collector/Admin
The default formatting of the event objects to strings is not very useful, so this example does its own formatting.
After you're done reading the events, you can just kill the job. The proper sequence for it together with expect would be:
Stop-Job $col_job
Skip-ExpectJob -Timeout $tout -Buf $col_buf -WaitStop
Remove-Job $col_job
And here is the implementation:
function Get-WinEventSafe
{
<#
.SYNOPSIS
Wrapper over Get-WinEvent that doesn't throw if no events are available.
Using -ea SilentlyContinue is still a good idea because PowerShell chokes
on the strings containing the '%'.
#>
try {
Get-WinEvent @args
} catch {
if ($_.FullyQualifiedErrorId -ne "NoMatchingEventsFound,Microsoft.PowerShell.Commands.GetWinEventCommand") {
throw
}
}
}
function Get-WinEventsAfter
{
<#
.SYNOPSIS
Do one poll of an online ETW log, returning the events received after
the last previous event.
#>
[CmdletBinding()]
param(
## Name of the log to read the events from.
[parameter(Mandatory=$true)]
[string] $LogName,
## The last previous event, get the events after it.
[System.Diagnostics.Eventing.Reader.EventLogRecord] $Prev,
## The initial scoop size for reading the events, if that scoop doesn't
## reach the previous event, the scoop will be grown twice on each
## attempt. If there is no previous event, all the available events will be returned.
[uint32] $Scoop = 128
)
if ($Prev -eq $null) {
# No previous record, just return everything
Get-WinEventSafe -LogName $LogName -Oldest -ea SilentlyContinue
return
}
$ptime = $Prev.TimeCreated
for (;; $Scoop *= 2) {
# The events come out in the reverse order
$ev = @(Get-WinEventSafe -LogName $LogName -MaxEvents $Scoop -ea SilentlyContinue)
if ($ev.Count -eq 0) {
return # no events, nothing to do
}
$last = $ev.Count - 1
if ($ev.Count -ne $Scoop -or $ev[$last].TimeCreated -lt $Prev.TimeCreated) {
# the scoop goes past the previous event, find the boundary in it
for (; ; --$last) {
if ($last -lt 0) {
return # no updates, return nothing
}
$etime = $ev[$last].TimeCreated
if ($etime -lt $ptime) {
continue
}
if ($etime -gt $ptime) {
break
}
if ($ev[$last].Message -eq $Prev.Message) {
--$last # skip the copy of the same event
if ($last -lt 0) {
return # no updates, return nothing
}
break
}
}
$ev = $ev[0..$last]
[array]::Reverse($ev) # in-place
$ev
return
}
# otherwise need to scoop more
}
}
function Read-WinEvents
{
<#
.SYNOPSIS
Poll an online ETW log forever, until killed.
#>
[CmdletBinding()]
param(
## Name of the log to read the events from.
[parameter(Mandatory=$true)]
[string] $LogName,
## The poll period, in seconds, floating-point.
[double] $Period = 1.,
## The initial scoop size for Get-WinEventsAfter.
[uint32] $Scoop = 128,
## Number of previous records to return at the start.
[uint32] $Nprev = 0
)
$prev = $null
[int32] $msec = $Period * 1000
$isVerbose = ($VerbosePreference -ne "SilentlyContinue")
# read the initial records
if ($Nprev -gt 0) {
$ev = @(Get-WinEventSafe -LogName $LogName -MaxEvents $Nprev -ea SilentlyContinue)
[array]::Reverse($ev) # in-place
if ($isVebose) {
& {
"Got the previous events:"
$ev | fl | Out-String
} | Write-Verbose
}
$ev
$prev = $ev[-1]
$ev = @()
} else {
$ev = @(Get-WinEventSafe -LogName $LogName -MaxEvents 1 -ea SilentlyContinue)
& {
"Got the previous event:"
$ev | fl | Out-String
} | Write-Verbose
$prev = $ev[0]
}
for (;;) {
Sleep -Milliseconds $msec
$ev = @(Get-WinEventsAfter -LogName $LogName -Prev $prev -Scoop $Scoop)
& {
"Got more events:"
$ev | fl | Out-String
} | Write-Verbose
if ($ev) {
$ev
$prev = $ev[-1]
$ev = @()
}
}
}
As a last note, if you just want to read the collected online events or an ETL file from the start, the commands for that are:
Get-WinEvent -path myfile.etl -Oldest
Get-WinEvent -LogName Microsoft-Windows-BootEvent-Collector/Admin –Oldest
See Also: all the text tools