Pester 4 output different to Pester 3 due to missing stack trace exclusion regex, and Gherkin too

codykonior commented 6 years ago

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

I find that the stack trace output is often too verbose and after some investigation it changed between Pester 3 and Pester 4 and I believe it's due to a missing regex.

In Pester 3:

Describe "some description" {
    Context "some context" {
        It "some test" {
            $null | Should Be 1
        }
    }
}

Results in:

Describing some description
   Context some context
    [-] some test 92ms
      Expected: {1}
      But was:  {}
      4:             $null | Should Be 1
      at <ScriptBlock>, C:\temp\Blah2.test.ps1: line 4
Tests completed in 92ms
Passed: 0 Failed: 1 Skipped: 0 Pending: 0 Inconclusive: 0

In Pester 4:

Describe "some description" {
    Context "some context" {
        It "some test" {
            $null | Should -Be 1
        }
    }
}

Results in:

Executing all tests in '.\Blah.test.ps1'

Executing script .\Blah.test.ps1

  Describing some description

    Context some context
      [-] some test 351ms
        Expected {1}, but got {}.
        4:             $null | Should -Be 1
        at Invoke-Assertion, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Assertions\Should.ps1: line 206
        at <ScriptBlock>, C:\temp\Blah.test.ps1: line 4

The difference is the extra Invoke-Assertion line which shouldn't be there. This is because of Output.ps1 and this code:

            [String]$pattern1 = '^at (Invoke-Test|Context|Describe|InModuleScope|Invoke-Pester), .*\\Functions\\.*.ps1: line [0-9]*$'
            [String]$pattern2 = '^at Should<End>, .*\\Functions\\Assertions\\Should.ps1: line [0-9]*$'
            [String]$pattern3 = '^at Assert-MockCalled, .*\\Functions\\Mock.ps1: line [0-9]*$'

To rectify this we need a $pattern4 (it should not be put into the other patterns, it does not work this way in $pattern1):

[String]$pattern4 = '^at Invoke-Assertion, .*\\Functions\\.*.ps1: line [0-9]*$'

And an updated match statement a few lines down:

                $_ -notmatch $pattern2 -and
                $_ -notmatch $pattern3 -and
                $_ -notmatch $pattern4

That gives you this Pester 4 result which matches the Pester 3 result.

Executing all tests in '.\Blah.test.ps1'

Executing script .\Blah.test.ps1

  Describing some description

    Context some context
      [-] some test 69ms
        Expected {1}, but got {}.
        4:             $null | Should -Be 1
        at <ScriptBlock>, C:\Temp\Blah.test.ps1: line 4
Tests completed in 69ms
Tests Passed: 0, Failed: 1, Skipped: 0, Pending: 0, Inconclusive: 0

There is a second part to this though because when you run a Gherkin step test it also includes a lot of non-excluded stack trace garbage:

    [-] something something test conditions 5.56s
      Expected {1} to be greater or equal to the actual value, but got {0}.
      69:     $passCount | Should -Not -BeLessThan $Count
      at Invoke-Assertion, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Assertions\Should.ps1: line 206
      at <ScriptBlock>, C:\somethingsomething\Feature.Steps.ps1: line 69
      at <ScriptBlock>, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Gherkin.ps1: line 705
      at Invoke-GherkinStep, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Gherkin.ps1: line 711
      at Invoke-GherkinScenario, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Gherkin.ps1: line 558
      at Invoke-GherkinFeature, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Gherkin.ps1: line 502
      at Invoke-Gherkin<End>, C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Functions\Gherkin.ps1: line 285
      at <ScriptBlock>, <No file>: line 1
    [+] Given server instance ...

This needs one further pattern added exclude the Gherkin parts and the very last ScriptBlock which seems consistent in every test and caused by the implementation rather than anything useful:

[String]$pattern5 = '^at (<ScriptBlock>|Invoke-Gherkin.*), (<No file>|.*\\Functions\\.*.ps1): line [0-9]*$'

Together with the above Invoke-Assertion pattern, this results in this correct equivalent output for Gherkin tests:

    [-] something something test conditions 5.56s
      Expected {1} to be greater or equal to the actual value, but got {0}.
      69:     $passCount | Should -Not -BeLessThan $Count
      at <ScriptBlock>, C:\somethingsomething\Feature.Steps.ps1: line 69
    [+] Given server instance ...

2. Describe Your Environment

Operating System, Pester version and PowerShell version:

Pester version     : 4.2.0 C:\Program Files\WindowsPowerShell\Modules\pester\4.2.0\Pester.psm1
PowerShell version : 5.1.14393.1944
OS version         : Microsoft Windows NT 10.0.14393.0

6. Context

I'm experimenting with running tests with the idea of running a lot of tests. While you can go to some lengths to pass through the objects and manipulate the output I think that the default output should be kinda sane.

alx9r commented 6 years ago

@codykonior I have a branch here that I think addresses this issue: https://github.com/alx9r/Pester/tree/improve-stacktrace-output

_{Sent with GitHawk}

codykonior commented 6 years ago

@alx9r Thanks but I think that PR went too far because it didn't realise that the stack trace output is caused by the incorrect regex string. The fix is just adding Invoke-Assertion to the regex string... it doesn't require all that other stuff. What do you think?

pester / Pester