NUnit XML does not contain output logging for the cmdlets

[theficus]

The NUnit XML that's created by Pester doesn't seem to contain any output logging from tests including information, warnings, or errors. This makes reviewing test runs difficult since while I can tell what passed and what didn't, there's zero fidelity regarding what actually happened when the test ran and that is important information.

I've used NUnit in the past to run unit tests and I know it can contain this information (obviously at the cost of much larger XML result outputs).

Is it possible for Pester to capture output to the host and attach it to the XML results that are created to provide more context about what's happening?

[dlwyatt]

Can you provide examples of what you're seeing in the file now, and what you'd like to see?

[theficus]

Any Write-Warning/Write-Verbose/Write-Host that runs I'd like to see in the test case output. In the XML it would look something like this:

<test-case name="..." executed="True" time="1" asserts="0" success="True" result="Success">
    <message>... powershell output goes here ...</message>
</test-case>

This way when viewing the test results I can see the actual output of the test execution.

Similarly when an error occurs, those error details including stack trace should be written.

Today it looks like the bare minimum of information is written to the NUnit XML which is ok, but I'd like to see more so it's more in line with what I would expect from test cases run in NUnit or MSTest.

[dlwyatt]

I'll think about it, but capturing that output (particularly when we still need to support PowerShell v2) is tricky. Write-Host, in particular, is a problem (which is why it's generally recommended to not use that command at all, prior to the latest builds of PowerShell v5.)

[theficus]

Understood.

Even if some other command needed to be used for logging I think it's important to have more details captured in the output XML. Pass/fail results are useful for a quick glance but when it comes to auditing what happened you either need to re-run the tests and hope they behave the same way, or capture the full output to a separate file and x-ref between that and the NUnit output which is definitely not ideal. :)

[theficus]

If Write-Host would present compatibility problems, capturing things like Write-Verbose/Write-Warning into the NUnit XML would certainly be valuable as well.

[nohwnd]

There is Output element in NUnit 3. In the schema of 2.5 that we use I don't see output. So to be able to do this we probably need to add another ouitput formatter for NUnit 3. https://github.com/nunit/docs/wiki/Test-Result-XML-Format#output

[davinci26]

Is anyone actively on this issue? @nohwnd @rdbartram

[nohwnd]

@davinci26 marked you in the other issue that adds NUnit 3. Even if that is done this still needs more work because we are imho not capturing the output.

To capture the Write-Host output we could potentially add a "mock" of Write-Host that would capture the output and then called through into the real cmdlet. Internally we are holding onto the real Write-Host so the Pester output and the user outout would not be mixed (if my thinking is correct). This would fall apart when user mocks Write-Host, then we would not be able to capture the output if they called through to the real Write-Host, but that is imho an edgecase and okay.

[davinci26]

So if I understand correctly @rdbartram is working on adding the NUnit 3 without working on capturing the output and then further work is required to capture the output?

@nohwnd so the idea is to mock Write-Host function and store the $message that the user is sending before forwarding to PS-Write-Host( The user probably would want to see the $message printed on the screen if the Pester is running without the Quiet flag ) and the end we add all the collected/stored $message to the NUnit 3.0 output. My only concern here is how we would know in which Test Case this Write-Host happened to? Do we have this information inside the mocked Write-Host?

If Write-Host is problematic we could add another function Comment-Test that would behave similarly as the implementation above. The sole responsibility of Comment-Test would be just that and hopefully users will be less tempted to modify it. Does this idea makes any sense to you?

[nohwnd]

Yes.

Yes. There is global state where you know in which place you are.

The last idea I don't like, the problem is that he user chose to Mock Write-Host, so I think it's okay we just don't capture his output from the mocked command.

---

I would not stress much about capturing Write-Host, let's start from capturing standard output.

[davinci26]

I will be more than happy to work on this feature if noone else is working on it!

[davinci26]

Hey again,

I have made a quick implementation that looks like this:

    Mock Write-Host {
        param($Object)
        ${Write-Host} = & (Pester\SafeGetCommand) -Name Write-Host -Module Microsoft.PowerShell.Utility -CommandType Cmdlet
        & ${Write-Host} 'I was inside the mock'
        $null = $Pester.TestGroupStack.Peek().UserMessages.Add($Object)
    }.GetNewClosure()

And this Mock will be put in the describe.ps1 in the DescribeImpl. What do you think about it? Is this what you had in mind?

[nohwnd]

@davinci26 In pester v5 I am capturing the standard output of the command and saving it into the test result object, so it can be used for the NUnit output. I am not doing anything special regarding Write-Host, Write-Warning, Write-Debug or Write-Verbose yet, but if we figure out a way how to capture the output in a transparent way then it can be done in a single place, because in v5 all the user code runs via a single point.

I think that implementing this functionality reliably will not be trivial and will need some tweaking over time so I would leave this for Pester version 5.x, because after v5 is released v4 will (most likely) only get major fixes but no new features, so keeping it stable is key.

[davinci26]

@nohwnd I checked the v5 branch at it looks a huge improvement :) I am seriously impressed!

• The current implementation is really helpful,
• I want to give a go and see how the approach above would work in v5.x Capturing the rest of the streams can be useful for better logging experience.

Independently of this, I observed that Pester v5 has breaking changes in terms of the PassThru object returned and I am consuming this object. Is there an ETA for Pester v5?

[nohwnd]

@davinci26 the eta is in next few months, depending on how much time I have over weekends :) The passthru object can by transformed to the old one, so current integrations keep working. I started with that (iirc I called it Get-LegacyResult)so if you want to continue with that then that would be a nice addition.

[ndinev]

Hi all, Is there any progress on this? I recently started to use Pester and missing console output in the xml file makes analysis of tests hard to do. I am willing to use another command for writing to the output. Let's say Write-Pester. And this command may have option to be transparent and print to the console as well.

[fflaten]

It's planned for the NUnit3 format that I've started working on.

Unfortunately I haven't had any time to work on Pester last weeks, so it might be delayed until 5.4

Edit: To clarify, the currently planned work is standard output (stream 1), not information/errors/warnings etc. as we don't capture those like nohwnd mentinos above. They will however be displayed by the host output locally or in CI run log.

[fflaten]

I've made a simple PoC for NUnit3 with output-node for standard output (not write-host/Information etc.), but it doesn't look like Azure Pipelines show "Console log" anywhere even though they specify it in the NUnit3 mapping-docs. There's not tab/field like there is for error message etc. in the report.

Console log: /test-suite[@type='Assembly']/test-case/failure/output

Anyone used this before? Or NUnit3 with other CIs? :)

<test-case name="foo-bar.four" fullname="foo-bar.four" methodname="foo-bar.four" classname="foo-bar.four" start-time="2022-07-07T10:20:02.2376536Z" end-time="2022-07-07T10:20:02.2446586Z" duration="0.007" result="Passed">
    <output>
        <![CDATA[ hello world! foo bar ]]>
    </output>
</test-case>

[fflaten]

Never mind. AzDO only shows standard output for failed tests and puts it in an attachment