Pester: Exceptions thrown in Describe/Context BeforeAll or BeforeEach are undiagnosable.

[dantraMSFT]

1. Provide a general summary of the issue in the Title above

When a BeforeAll or BeforeEach block throws an exception, Pester error output doesn't include any information about the failure. Instead, a secondary exception is thrown due to the call to AddTestResult failing.

For example:

[-] Error occurred in Context block 3.4s
ValidationMetadataException: The attribute cannot be added because variable Result with value would no longer be valid.
MethodInvocationException: Exception calling "AddTestResult" with "8" argument(s): "The attribute cannot be added because variable Result with value would no longer be valid."

The same behavior occurs in both Describe and Context Before* blocks with the only difference being the block type (Context or Describe).

When this occurs, the only solution I've found is to edit the catch blocks in It.ps1 and Describe.ps1 and Write-Host the original failure details. Neither the console output nor the test result file contain this inforamation.

2. Describe Your Environment

Operating System, Pester version and PowerShell version:

Pester version     : 4.4.0 /home/psrptest/.local/share/powershell/Modules/Pester/4.4.0/Pester.psm1
PowerShell version : 6.1.0-rc.1
OS version         : Unix 4.15.0.1022

3. Expected Behavior

If you're describing a bug, tell us what should happen.

The error details ($_) from the catch block should be reported and/or logged.

4.Current Behavior

The subsequent call to AddTestResult itself throws and this is the information reported; as indicated above.

Context 'Verify NTLM PSSession' {
    BeforeEach {
        # If this throws, a ValidationMetadataException is thrown and reported instead of the exception 
        # caused by the this call.
        $session = New-PSSession -ComputerName $TestVariables.HostName -Credential $TestVariables.Credential -Authentication Negotiate
    }

    It 'Verifies New-PSSession -Authentication Negotiate connects with no errors' -Skip:$Skip {
            $session.ComputerName | Should -BeExactly $TestVariables.HostName
            $session.Transport | Should -BeExactly 'WSMan'
        }

5. Possible Solution

Have a solution in mind?

https://github.com/pester/Pester/wiki/Contributing-to-Pester has detailed instructions on how to contribute.

6. Context

How has this issue affected you? What are you trying to accomplish?

[nohwnd]

Thanks for reporting will have a look on this.

[bergmeister]

@nohwnd I see these errors now as well after the last update of AppVeyor's Ubuntu image where it clearly shows it is a Pester issue with PowerShell 6.1 on Linux only because I do nothing in the Describe block (only before) and also do not have a BeforeAll or BeforeEach block either. For some reason this happens only in the Ubuntu image of AppVeyor (not Windows) but I can repro this issue locally also using Ubuntu 18 in WSL or get more info by running the code before the Before block outside of Pester, which indicates to me it is rather a bug with Pester. Let me know if you need more details and what you need (like diagnostic logs?), here is a link to the build. My build installs the latest version of Pester and I just re-ran it since you published a new Pester version yesterday and the behaviour has not changed. By looking at Pester's release history, it seems I cannot blame it on a new release though, so it must be the integration with something else in the image update (which is probably the newer PowerShell version of 6.1.1 since the last green build was on 6.0.2)

[nohwnd]

@bergmeister all our linux an macos builds run fine on Travis, and I am running pester locally in docker just fine as well. Could you share your appveyor.yml so I can try it myself? I would actually find it useful to setup Linux build for Assert, two birds one scone :)

[bergmeister]

@nohwnd Ok, thanks, I opened a few PRs for your Assert module including Linux in AppVeyor.
Today, I could reproduce the failure locally, it happens also in Ubuntu 18.04 when using WSL (the AppVeyor image uses Ubuntu 16.0.4) using the latest and also previous versions of Pester. I have a simplified repro branch here where the appveyor.yml just calls Invoke-Pester on this tests.ps1 file without the need to build anything before at all. The line(s) that seem to cause it are the 2 lines that call Compare-Object because the failure goes away when commenting those out but executing them outside of Pester does not produce any errors. So far I can also say that it happened in AppVeyor after the minor update to 6.1, so I suspect a subtle integration bug between PowerShell and Pester.

[nohwnd]

The errors are most likely filtered out by https://github.com/pester/Pester/blob/master/Functions/Output.ps1#L475 if you get rid of the pipeline it won't limit the output and will print the internals of Pester as well. Could you try that first to see if it gives relevant info please?

[bergmeister]

@nohwnd OK, thanks, this is what I get now as an output:

   [-] Error occurred in Describe block 156ms
      ValidationMetadataException: The attribute cannot be added because variable Result with value  would no longer be valid.
      MethodInvocationException: Exception calling "AddTestResult" with "8" argument(s): "The attribute cannot be added because variable Result with value  would no longer be valid."
      at Invoke-Test, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Functions/It.ps1: line 310
      at ItImpl, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Functions/It.ps1: line 231
      at It, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Functions/It.ps1: line 121
      at <ScriptBlock>, /mnt/c/Users/cberg/git/PSScriptAnalyzer/Tests/Documentation/RuleDocumentation.tests.ps1: line 38
      at DescribeImpl, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Functions/Describe.ps1: line 171
      at Describe, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Functions/Describe.ps1: line 85
      at <ScriptBlock>, /mnt/c/Users/cberg/git/PSScriptAnalyzer/Tests/Documentation/RuleDocumentation.tests.ps1: line 6
      at <ScriptBlock>, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Pester.psm1: line 847
      at Invoke-Pester<End>, /home/chris/.local/share/powershell/Modules/Pester/4.4.3/Pester.psm1: line 862
      at <ScriptBlock>, <No file>: line 1

[nohwnd]

ok, that did not help at all 🤣

[ffeldhaus]

I also see this issues showing up in AppVeyor Pester tests after the PowerShell 6.1 update in the recent Ubuntu image update.

[bergmeister]

The error comes from here in PowerShell in case that helps as it could be an integration bug with PowerShell as well.

[ffeldhaus]

I was able to reproduce it while running Appveyor with SSH access using a the following very simple test:

Describe "describe" {
    Context "context" {
        try {
            throw "test"
        }
        catch {
        }
        it "it" {
            throw "inside it"
            Write-Host "everything ok"
        }
    }
}

PS /home/appveyor> Invoke-Pester -Script "./test.ps1"      
Executing all tests in './test.ps1'

Executing script ./test.ps1

  Describing describe

    Context context
      [-] Error occurred in Context block 62ms
        ValidationMetadataException: The attribute cannot be added because variable Result with value  would no longer be valid.
        MethodInvocationException: Exception calling "AddTestResult" with "8" argument(s): "The attribute cannot be added because variable Result with value  would no longer be valid."
Tests completed in 62ms
Tests Passed: 0, Failed: 1, Skipped: 0, Pending: 0, Inconclusive: 0 

This is the PSVersionTable of the AppVeyor image

PS /home/appveyor> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      6.1.1
PSEdition                      Core
GitCommitId                    6.1.1
OS                             Linux 4.15.0-43-generic #46~16.04.1-Ubuntu SMP Fri Dec 7 13:31:08 UTC 2018
Platform                       Unix
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Without the catch block, Pester correctly shows the thrown exception inside the Context block.

I also confirmed that running the same code on Mac OS X with the same PowerShell version does not result in the issue and instead shows the exception thrown inside the it block.

I expect that the Linux PowerShell build somehow has issues with handling exceptions which were captured.

[ffeldhaus]

I tracked down the issue to Hashtable properties being case sensitive in the Appveyor Ubuntu (16.04) and Ubuntu1804 (18.04) images. I couldn't recreate the issue with the official Ubuntu docker images and the official steps from Microsoft to install PowerShell.

The following highlights the issue in the Appveyor images:

PS /home/appveyor> $test=@{result="result"}
PS /home/appveyor> $test.Result
PS /home/appveyor> $test.result
result

Pester defines the result as lowercase property in a Hashtable used in the function ConvertTo-PesterResult. Then the property is accessed as $result.Result starting with an uppercase letter in the Invoke-Test function.

Changing the property access to start with an uppercase would fix the issue. I'd be glad to contribute a pull request if someone can confirm that changing $result.Result to $result.result is the correct way to fix this. In parallel we can figure out why this is only affecting Appveyor images. I opened a support ticket to get more information from Appveyor how the build / installed PowerShell.

[FeodorFitsner]

I'm not sure the problem is AppVeyor-specific though. These are the results of the same test on my local WSL with Ubuntu 18.04 and PS 6.1.1:

[ffeldhaus]

The issue is very likely caused by https://github.com/PowerShell/PowerShell/issues/7761

[FeodorFitsner]

...and HashTable experiment on the same WSL:

Looks like a regression (or new behavior) in PS Core?

[bergmeister]

Thanks everyone for trying to boil down the issue. I'll try the suggested changes by @ffeldhaus next Tuesday when I've got access to my dev environment again. Can you maybe also please give us a simple one line to change the LANG as described in the AppVeyor support issue.

As per my comments above, I can reproduce the bug locally in my WSL (Ubuntu 18 but not 16 in my case for WSL) environment for my test suite, therefore I agree this is a general problem of Pester on PowerShell 6.1.1 that did not happen with PowerShell 6.0. However, a race condition or something environment specific might be involved in it as well since the bug does not repro on the hosted Ubuntu agent provided by Azure DevOps.

[bergmeister]

I can confirm that changing the Pester hashtable access in the functions that @ffeldhaus points, it fixes the problem, I opened a PR in Pester since a publishing an updated Version of Pester might be quicker until the proper fix gets deployed in PowerShell 6.2

@FeodorFitsner However, setting LANG to en_US.UTF-8 does not seem to fix the AppVeyor build, see here for a minimum example. It seems to be that the pwsh session gets re-used but according to the PowerShell team, one needs to restart pwsh after the environment variable change to take effect. I set the env variable in YAML as follows:

environment:
  LANG: en_US.UTF-8

[FeodorFitsner]

Yep, the language should be set "higher" in the process hierarchy. We are working on build agent update. Thanks for your patience guys.

[nohwnd]

I just published the referenced PR as 4.4.4 (merged into master and cherrypicked to branch based on 4.4.3). 4.4.4 is the last stable version so AppVeyor users should be getting it unless they specified a version explicitly. Great work guys!

Could someone test it out please ? @bergmeister ?

[ffeldhaus]

@nohwnd I can confirm the fix is working! Thanks a lot for merging the pull request and creating a new release! Very much appreciated!

@bergmeister Great job with the pull request!

Here is the test which was previously returning the ValidationMetadataException instead of the exception inside the itblock:

PS /home/appveyor> Get-Module -ListAvailable -Name Pester


    Directory: /home/appveyor/.local/share/powershell/Modules


ModuleType Version    Name                                PSEdition ExportedCommands
---------- -------    ----                                --------- ----------------
Script     4.4.4      Pester                              Desk      {Describe, Context, It, Should...}

PS /home/appveyor> @"
>> Describe "describe" {
>>     Context "context" {
>>         try {
>>             throw "test"
>>         }
>>         catch {
>>         }
>>         it "it" {
>>             throw "inside it"
>>             Write-Host "everything ok"
>>         }
>>     }
>> }
>> "@ | Out-File -FilePath test.ps1
PS /home/appveyor> Invoke-Pester -Script ./test.ps1
Executing all tests in './test.ps1'

Executing script ./test.ps1

  Describing describe

    Context context
      [-] it 448ms
        RuntimeException: inside it
        at <ScriptBlock>, /home/appveyor/test.ps1: line 9
Tests completed in 448ms
Tests Passed: 0, Failed: 1, Skipped: 0, Pending: 0, Inconclusive: 0 

[bergmeister]

@nohwnd Awesome, thanks for publishing it. It fixes the problems that I have seen, there seem to be new failures (again only on that special Ubuntu environment) that I have to look into but those failures are not a problem of Pester itself, it is a problem of my module now due to PowerShell being case sensitive.

[nohwnd]

@bergmeister that sucks. Good luck solving it!

[bergmeister]

Thanks, I could solve it in the end with only a few tweaks. P.S.: I re-ran Pester's own test suite on that environment and it only showed me 3 test failures after my PR (before it was 10) and the gist seems to be that Pester's mocking feature is not working in those environments (I guess again due to hashtable key casing mismatches either in Pester or PowerShell itself) but I am not using this feature so it is not a problem for me but might be worthwhile to point out to other people in those environments.
For anyone having to fix their product as well, it is worthwhile noting that not only hashtable entries are case sensitive, also doing string comparisons in C# PowerShell modules will suffer from that, the way I solved it was to change from CurrentCultureIgnoreCase to OrdinalIgnoreCase to actually get a really case insensitive comparison