How do I capture .NET trace output from a Powershell job?

Question

I am using a .NET component in Powershell which uses Trace.TraceWarning, Trace.TraceInformation etc.

I want to output these traces to the console when I run my Powershell script.

This works when I use the component in the current session. For example (simulating the effect of trace) gives me 'Hello' output to the console:

 $listener = new-object "system.diagnostics.consoletracelistener"
 [System.Diagnostics.Trace]::Listeners.Add($listener) | Out-Null
 [System.Diagnostics.Trace]::TraceInformation("Hello")

But if I do the same within a Powershell job I get no output, even though ConsoleTraceListener should be writing to STDOUT which in turn I expected to get captured by the job. (Interestingly Console.WriteLine doesn't work from a job either - but Write-Host does).

I am starting my job like so:

$work = {
     $listener = new-object "system.diagnostics.consoletracelistener"
     [System.Diagnostics.Trace]::Listeners.Add($listener) | Out-Null
     [System.Diagnostics.Trace]::TraceInformation("Hello")
}
$job = Start-Job -RunAs32 -ScriptBlock $work
$job | Receive-Job -Wait

Hooghly

ConsoleTraceListener writes to console, so related: serverfault.com/questions/399854/powershell-start-job-output – Pantagruel

ConsoleTraceListener appears to write to stdout referencesource.microsoft.com/#System/compmod/system/…. But for some reason with jobs it's not being picked up – Hooghly

After some more testing I found some interesting things about jobs and child jobs. I think ultimately the issue is that powershell is not using the System.Console class but a custom System.Management.Automation.Host.PSHost class and redirecting the streams. This doesn't seem to be implemented as expected in certain edge cases like yours though. – Goebbels

ConsoleTraceListener just uses STDOUT though. Not sure I see how it's an edgecase! – Hooghly

Answer 1

I remember running into something similar to this years ago where expected STDOUT and STDIN weren't behaving as expected with start-job and exe's. I ended up using System.Diagnostics.Process and redirecting the STDIN and STDOUT. Here's an example that demonstrates this workaround in a way that may assist you with what you are trying to do.

#added extra trace messages with Get-Date and implemented a random delay for demo purpose
$work = {
     $listener = new-object "system.diagnostics.consoletracelistener"
     [System.Diagnostics.Trace]::Listeners.Add($listener) | Out-Null
     1..10 | % {
         Start-Sleep $(Get-Random 5)
         [System.Diagnostics.Trace]::TraceInformation((Get-Date))
    }
}
#Create a process
$process = New-Object System.Diagnostics.Process 
$process.StartInfo.UseShellExecute = $false
#redirect stdout
$process.StartInfo.RedirectStandardOutput = $true
#call powershell
$process.StartInfo.FileName = "powershell.exe"
#pass the $work scriptblock
$process.StartInfo.Arguments = "-noprofile -command $work"
#start the process
$process.Start() | Out-Null
#readlines as they come in and exit when process is done
while(-not $process.HasExited){
    $process.StandardOutput.ReadLine()
}

Output:

powershell.exe Information: 0 : 01/30/2015 12:27:17
powershell.exe Information: 0 : 01/30/2015 12:27:20
powershell.exe Information: 0 : 01/30/2015 12:27:21
powershell.exe Information: 0 : 01/30/2015 12:27:25
powershell.exe Information: 0 : 01/30/2015 12:27:26
powershell.exe Information: 0 : 01/30/2015 12:27:28
powershell.exe Information: 0 : 01/30/2015 12:27:29
powershell.exe Information: 0 : 01/30/2015 12:27:33
powershell.exe Information: 0 : 01/30/2015 12:27:36
powershell.exe Information: 0 : 01/30/2015 12:27:40

Goebbels

Thanks for your answer, but I consider Start-Process to be "cheating" ;). I'm trying to work out why it doesnt' work for jobs – Hooghly

@JackUkleja this answer, same as Start-Process are your only alternatives for this. The output of [System.Diagnostics.Trace]::TraceInformation(..) cannot be captured by any type of redirection *>&1 same as [console]::WriteLine(..) or attempting to capture the output of -WhatIf. – Mann

Answer 2

It's not clear where you want the captured output to go. Most of the discussion so far revolves around the Console, but since you called it a "job" (I presume you mean Scheduled Task), I'm not so sure the Console is the best place. You'd never see the results. A log file sounds much more appropriate. If that's the case, you should create a TextWriteTraceLister. That will allow you to set a log file for the results.

Additionally, one of the nice features of Tracing in .Net is that you can have more than one listener attached. So if you want to see the output as it runs, you can also attach the ConsoleTraceListener, and it won't interfere with writing to the log file.

Finally, it's also possible to write your own TraceListener. This is useful for things like writing to a logging database or web service. To use your own TraceListener from PowerShell, you would need to build the listener using a .Net language that can be compiled into a class library assembly (dll) that can be deployed to the GAC for use in your project.

Reginaldreginauld

It's a powershell job, as in something that is being started with Start-Job. The reason I am using a job btw is because I am needing to load and use a x86 .NET assembly from 64bit powershell. Job provides a nice easy way to do that – Hooghly

The trace statements when running in a regular psh session get output into the pipeline. So ideally they would be returned from the receive-job command in the same way normal output results are. – Hooghly

You might find this helpful: #11974275 – Reginaldreginauld

Thanks but not sure an explanation of .NET tracing really helps me. I'm fairly familiar with it. I had considered writing a custom trace listener to hook the events and output them to parts of PSH that I know do work, such as write-host but I'm hoping for a definitive answer on why the scenario in the question doesn't work. – Hooghly

This the programmer's equivalent to the theoretical physicist's standard excuse. In stead of "Because Quantum", we get to say "Because Threads." Start-Job pushes the work into a separate thread, and Trace events are fired in separate threads still. Each thread has it's own hidden standard output. Start-Job keeps those results and eventually pushes them back via Receive-Job. For the Trace events... it looks like not so much, at least in this scenario. – Reginaldreginauld

I'm not convinced :) The .NET tracing system doesn't really stipulate an approach to "thread safety". Some listeners are thread safe, some aren't. I think the CTL happens to be block when it gets to the console writing step (because that has a global lock I think), but in general there is no "separate thread" for tracing. – Hooghly

The code example do use Start-Job, so it's not a scheduled task. – Propriety