I'm using PowerShell v2.0 to execute a given process using a System.Diagnostics.Process object, intercepting stdout/stderr messages asynchronously, writing the respective $EventArgs.Data to the host (for debug purposes) and pre-pending it with a timestamp, ultimately for logging purposes:
$ProcessInfo = New-Object System.Diagnostics.ProcessStartInfo
$ProcessInfo.RedirectStandardOutput = $true
$ProcessInfo.RedirectStandardError = $true
$ProcessInfo.UseShellExecute = $false
$ProcessInfo.CreateNoWindow = $true
$ProcessInfo.FileName = "ping"
$ProcessInfo.Arguments = "google.com"
$Process = New-Object System.Diagnostics.Process
$Process.StartInfo = $ProcessInfo
$CaptureStandardOutputStandardError = {
If (![String]::IsNullOrEmpty($EventArgs.Data)) {
Write-Host "$(Get-Date -Format "yyyy-MM-dd HH:mm:ss.fffffff") [ExecCmd]: $($EventArgs.Data)"
}
}
Register-ObjectEvent -InputObject $Process -SourceIdentifier StdOutEvent -Action $CaptureStandardOutputStandardError -EventName 'OutputDataReceived' | Out-Null
Register-ObjectEvent -InputObject $Process -SourceIdentifier ErrOutEvent -Action $CaptureStandardOutputStandardError -EventName 'ErrorDataReceived' | Out-Null
$Process.Start() | Out-Null
$Process.BeginOutputReadLine()
$Process.BeginErrorReadLine()
If ($Process.WaitForExit(10000)) {
# Ensure streams are flushed
$Process.WaitForExit()
# Do stuff
} Else {
# Timeout
}
Unregister-Event StdOutEvent
Unregister-Event ErrOutEvent
I'm expecting the stdout/stderr messages written to the console to have timestamps a second apart (as ping writes to the pipeline every second obviously), but for some reason the timestamps are all within about 10 milliseconds of each other, so the registered events are obviously firing when the process completes. So I'm expecting this:
2016-11-27 14:53:15.6581302 [ExecCmd]: Pinging google.com [172.217.17.110] with 32 bytes of data: 2016-11-27 14:53:15.8778445 [ExecCmd]: Reply from 172.217.17.110: bytes=32 time=1ms TTL=59 2016-11-27 14:53:16.6796113 [ExecCmd]: Reply from 172.217.17.110: bytes=32 time=1ms TTL=59 2016-11-27 14:53:17.7548025 [ExecCmd]: Reply from 172.217.17.110: bytes=32 time=1ms TTL=59 etc...
But instead, seeing this...
2016-11-26 19:00:53.0813327 [ExecCmd]: Pinging google.com [172.217.17.46] with 32 bytes of data: 2016-11-26 19:00:53.0842700 [ExecCmd]: Reply from 172.217.17.46: bytes=32 time=1ms TTL=59 2016-11-26 19:00:53.0860183 [ExecCmd]: Reply from 172.217.17.46: bytes=32 time=1ms TTL=59 2016-11-26 19:00:53.0899003 [ExecCmd]: Reply from 172.217.17.46: bytes=32 time=1ms TTL=59 etc...
I've re-created this in C# using .NET Framework v2.0 (as I'm using PSv2) and it works as expected. Code for reference:
ProcessStartInfo processInfo = new ProcessStartInfo();
processInfo.RedirectStandardError = true;
processInfo.RedirectStandardOutput = true;
processInfo.UseShellExecute = false;
processInfo.CreateNoWindow = true;
processInfo.FileName = "ping";
processInfo.Arguments = "google.com";
Process process = new Process();
process.StartInfo = processInfo;
process.OutputDataReceived += (sender, e) => {
if (!string.IsNullOrEmpty(e.Data))
{
Console.WriteLine("{0} [ExecCmd]: {1}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fffffff"), e.Data);
}
};
process.ErrorDataReceived += (sender, e) => {
if (!string.IsNullOrEmpty(e.Data))
{
Console.WriteLine("{0} [ExecCmd]: {1}", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fffffff"), e.Data);
}
};
process.Start();
process.BeginOutputReadLine();
process.BeginErrorReadLine();
if (process.WaitForExit(10000))
{
// Ensure streams are flushed
process.WaitForExit();
// Do stuff
}
else
{
// Timeout
}
What am I missing? I don't understand why effectively the same code works in C# but not in PS with the same .NET framework version. Omitting the $Process.WaitForExit(1000) statement returns the correct timestamp values so I know PS is capable of returning the correct values. The closest I can get is to replace the if ($Process.WaitForExit(10000)) statement with a while (!$Process.HasExited) {} statement. This works, but is not a viable solution as it (understandably) kills the CPU - and strangely, adding Start-Sleep x causes the process to not exit. I've played around with the $Process.Exited event but that causes the process to never exit, although the event fires and the $Process.HasExited event returns $true. Similarly creating a Timer object and checking for $Process.HasExited causes the process to never exit too.
I've seen lots of questions related to capturing stdout/stderr asynchronously with Process objects in PS, but couldn't find any specific questions related to my use case. Any help/advice/guidance would be much appreciated as I'm scratching my head with this one! Thank you in advance!
Simon
I couldn't figure out how to display stdout/err streams real-time on the console and writing to file with additional values (timestamp etc) when subscribing to Process.OutputDataReceived and ErrorDataReceived events, so in the end I changed tact and ended up doing the following:
Function Write-Log ($Message) {
Write-Output $Message
Add-Content -Path "C:\temp\test.txt" -Value "$(Get-Date -Format "yyyy-MM-dd HH:mm:ss.fffffff") [ExecCmd]: $Message"
}
Invoke-Expression "ping google.com" | ForEach-Object {Write-Log $_}
This works, however I'm not sure if it's best practice or not - it appears to be efficient and reliable though.