4.0.2 output breaks PowerShell extension problem matcher in VS Code. #725

Closed
rkeithhill opened this Issue Feb 8, 2017 · 18 comments

Comments

Projects
None yet
4 participants
@rkeithhill

The PowerShell extension for VSCode provides a task.json problem matcher that causes Pester test failures to appear in the VSCode Problems window. And when it works, you can click on the entries to go to the line of script that failed.

However with 4.0.2 I'm seeing a number of entries that have no filename:

        at line: 92 in 

Hopefully that is a bug and not by design.

@gerane

This comment has been minimized.

Show comment
Hide comment
@gerane

gerane Feb 8, 2017

This almost seems random for me. I was going to take a screenshot of one that did this for me, but now I can't seem to get it to omit the file.

I do still have the text output of one. There were 2 other failures that had the files in this output.

[-] Should call Write-EventLog 1 time 25ms
        Expected Write-EventLog to be called 1 times exactly but was called 2 times
        at line: 179 in
        179:             Assert-MockCalled -CommandName Write-EventLog -Times 1 -Exactly

gerane commented Feb 8, 2017

This almost seems random for me. I was going to take a screenshot of one that did this for me, but now I can't seem to get it to omit the file.

I do still have the text output of one. There were 2 other failures that had the files in this output.

[-] Should call Write-EventLog 1 time 25ms
        Expected Write-EventLog to be called 1 times exactly but was called 2 times
        at line: 179 in
        179:             Assert-MockCalled -CommandName Write-EventLog -Times 1 -Exactly
@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Feb 9, 2017

Here is what changed between 3.4.0 and 4.0.2, both utilizing the special property -PesterOption @{IncludeVSCodeMarker=$true} that @dlwyatt added for me last year.
3.4.0 output:

 [-] Processes multiple relative path via -Path param 61ms
   at <ScriptBlock>, C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1: line 83
   Expected: {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json2}
   But was:  {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json}
   84:             Should Be @("$WorkspaceRoot\README.md", "$WorkspaceRoot\.vscode\launch.json2")
   at <ScriptBlock>, C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1: line 83
 [+] DefaultParameterSet should be Path 116ms

v4.0.2 output:

v4.0.2
    [-] Processes multiple relative path via -Path param 74ms
      Expected: {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json2}
      But was:  {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json}
      at line: 84 in C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1
      84:             Should Be @("$WorkspaceRoot\README.md", "$WorkspaceRoot\.vscode\launch.json2")
    [+] DefaultParameterSet should be Path 26ms

Note that in v3.4.0 the file/line info is displayed right after the [-] line.

This was necessary to make the problem matcher in VS Code work properly. I see the format of the line has changed as well but I can handle that with an updated regex. However, having the Expected and But was lines appear between the two really messes up the problem matcher - particularly because the number of lines is not fixed.

Can you please fix this for IncludeVSCodeMarker=$true by moving the line/file info back to being the next line after [-]? I already have PowerShell extension users running into this - https://twitter.com/BrandonPadgett/statuses/829449073300234241

rkeithhill commented Feb 9, 2017

Here is what changed between 3.4.0 and 4.0.2, both utilizing the special property -PesterOption @{IncludeVSCodeMarker=$true} that @dlwyatt added for me last year.
3.4.0 output:

 [-] Processes multiple relative path via -Path param 61ms
   at <ScriptBlock>, C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1: line 83
   Expected: {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json2}
   But was:  {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json}
   84:             Should Be @("$WorkspaceRoot\README.md", "$WorkspaceRoot\.vscode\launch.json2")
   at <ScriptBlock>, C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1: line 83
 [+] DefaultParameterSet should be Path 116ms

v4.0.2 output:

v4.0.2
    [-] Processes multiple relative path via -Path param 74ms
      Expected: {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json2}
      But was:  {C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\README.md C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\.vscode\launch.json}
      at line: 84 in C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\examples\Tests\PathProcessing.Tests.ps1
      84:             Should Be @("$WorkspaceRoot\README.md", "$WorkspaceRoot\.vscode\launch.json2")
    [+] DefaultParameterSet should be Path 26ms

Note that in v3.4.0 the file/line info is displayed right after the [-] line.

This was necessary to make the problem matcher in VS Code work properly. I see the format of the line has changed as well but I can handle that with an updated regex. However, having the Expected and But was lines appear between the two really messes up the problem matcher - particularly because the number of lines is not fixed.

Can you please fix this for IncludeVSCodeMarker=$true by moving the line/file info back to being the next line after [-]? I already have PowerShell extension users running into this - https://twitter.com/BrandonPadgett/statuses/829449073300234241

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 9, 2017

Contributor

Is it just a matter of putting the stack trace above the error message? I can fix that...

Contributor

Jaykul commented Feb 9, 2017

Is it just a matter of putting the stack trace above the error message? I can fix that...

@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Feb 9, 2017

More or less. @dlwyatt did this before in PR #479 but only when IncludeVSCodeMarker is specified as $true in the PesterOption parameter, which he added for this issue. Details here a1e7ce2

rkeithhill commented Feb 9, 2017

More or less. @dlwyatt did this before in PR #479 but only when IncludeVSCodeMarker is specified as $true in the PesterOption parameter, which he added for this issue. Details here a1e7ce2

Jaykul added a commit to Jaykul/Pester that referenced this issue Feb 9, 2017

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 9, 2017

Contributor

Yeah, his code is all still there for the option, just the switch in the output got lost. I don't know how you're using this in VS Code, but it looks like this in the output:

  Scenario: Scope Should Still Be Easy
    [+] Given I initialize the variable Script:Two to "Uno" 0ms
    [+] When I set the variable Script:Two to "Hello" 0ms
    [-] Then the variable Script:Two should be "Hello World" 4ms
      at <ScriptBlock>, C:\Users\Joel\Projects\Modules\Pester\Examples\Gherkin\VariableScope.Steps.ps1: line 34
      From C:\Users\Joel\Projects\Modules\Pester\Examples\Gherkin\Gherkin-Scope.feature: line 14
      Expected string length 11 but was 3. Strings differ at index 0.
      Expected: {Hello World}
      But was:  {Hello}
      ----------------^

Obviously that's Gherkin, but the output is the same, which is why we rock 😉

Contributor

Jaykul commented Feb 9, 2017

Yeah, his code is all still there for the option, just the switch in the output got lost. I don't know how you're using this in VS Code, but it looks like this in the output:

  Scenario: Scope Should Still Be Easy
    [+] Given I initialize the variable Script:Two to "Uno" 0ms
    [+] When I set the variable Script:Two to "Hello" 0ms
    [-] Then the variable Script:Two should be "Hello World" 4ms
      at <ScriptBlock>, C:\Users\Joel\Projects\Modules\Pester\Examples\Gherkin\VariableScope.Steps.ps1: line 34
      From C:\Users\Joel\Projects\Modules\Pester\Examples\Gherkin\Gherkin-Scope.feature: line 14
      Expected string length 11 but was 3. Strings differ at index 0.
      Expected: {Hello World}
      But was:  {Hello}
      ----------------^

Obviously that's Gherkin, but the output is the same, which is why we rock 😉

@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Feb 9, 2017

That is perfect - even uses the old syntax e.g. ... filename: line ##. I could have changed the regex to use the new syntax at line: ## in filename but folks with the newer PowerShell extension would be broken until they updated to Pester 4.0.3.

That is perfect - even uses the old syntax e.g. ... filename: line ##. I could have changed the regex to use the new syntax at line: ## in filename but folks with the newer PowerShell extension would be broken until they updated to Pester 4.0.3.

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 9, 2017

Contributor

Oh, hmm. That's interesting. Apparently, I was wrong ... the RSpec runner is flipping the stacktrace around?

Actually, I don't know how that's happening 😕 it looks like this:

Executing script .\some.tests.ps1

  Describing tests
    [-] will fail 37ms
      at line: 2 in C:\Users\Joel\OneDrive\Documents\WindowsPowerShell\some.tests.ps1
      2: It "does not pass" { "Hello" | Should Be "Hello World" }
      Expected string length 11 but was 5. Strings differ at index 5.
      Expected: {Hello World}
      But was:  {Hello}
      ----------------^
Tests completed in 37ms
Tests Passed: 0, Failed: 1, Skipped: 0, Pending: 0, Inconclusive: 0
Contributor

Jaykul commented Feb 9, 2017

Oh, hmm. That's interesting. Apparently, I was wrong ... the RSpec runner is flipping the stacktrace around?

Actually, I don't know how that's happening 😕 it looks like this:

Executing script .\some.tests.ps1

  Describing tests
    [-] will fail 37ms
      at line: 2 in C:\Users\Joel\OneDrive\Documents\WindowsPowerShell\some.tests.ps1
      2: It "does not pass" { "Hello" | Should Be "Hello World" }
      Expected string length 11 but was 5. Strings differ at index 5.
      Expected: {Hello World}
      But was:  {Hello}
      ----------------^
Tests completed in 37ms
Tests Passed: 0, Failed: 1, Skipped: 0, Pending: 0, Inconclusive: 0
@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 9, 2017

Contributor

Ok, I think that needs to be fixed (in the RSpec output). The at line: 2 is only on the front because those are being written in "by hand":

Get-PesterResult is doing this on It,ps1#L347

    $testResult.failureMessage = $failureMessage
    $testResult.stackTrace = "at line: $line in ${file}${lineText}"
    $testResult.ErrorRecord = $ErrorRecord

    return $testResult

At first I thought it was ConvertTo-FailureLines in Output.ps1#L167-L178

        if ( -not ($ErrorRecord | & $SafeCommands['Get-Member'] -Name ScriptStackTrace) )
        {
            if ($ErrorRecord.FullyQualifiedErrorID -eq 'PesterAssertionFailed')
            {
                $lines.Trace += "at line: $($ErrorRecord.TargetObject.Line) in $($ErrorRecord.TargetObject.File)"
            }
            else
            {
                $lines.Trace += "at line: $($ErrorRecord.InvocationInfo.ScriptLineNumber) in $($ErrorRecord.InvocationInfo.ScriptName)"
            }
            return $lines
        }

But it looks like that function isn't even being used at all. <cue rant>

To me, it seems wrong that the fake stacktrace doesn't match a normal PowerShell stacktrace.

In the Gherkin stuff, I'm returning the actual line from the stacktrace, after skipping lines that came from Pester (similar to what ConvertTo-FailureLines does, but without manually re-writing the error).

I guess I should be calling Get-PesterResult or at least ConvertTo-FailureLines but now I'm torn about making that change. Anyone have opinions?

Contributor

Jaykul commented Feb 9, 2017

Ok, I think that needs to be fixed (in the RSpec output). The at line: 2 is only on the front because those are being written in "by hand":

Get-PesterResult is doing this on It,ps1#L347

    $testResult.failureMessage = $failureMessage
    $testResult.stackTrace = "at line: $line in ${file}${lineText}"
    $testResult.ErrorRecord = $ErrorRecord

    return $testResult

At first I thought it was ConvertTo-FailureLines in Output.ps1#L167-L178

        if ( -not ($ErrorRecord | & $SafeCommands['Get-Member'] -Name ScriptStackTrace) )
        {
            if ($ErrorRecord.FullyQualifiedErrorID -eq 'PesterAssertionFailed')
            {
                $lines.Trace += "at line: $($ErrorRecord.TargetObject.Line) in $($ErrorRecord.TargetObject.File)"
            }
            else
            {
                $lines.Trace += "at line: $($ErrorRecord.InvocationInfo.ScriptLineNumber) in $($ErrorRecord.InvocationInfo.ScriptName)"
            }
            return $lines
        }

But it looks like that function isn't even being used at all. <cue rant>

To me, it seems wrong that the fake stacktrace doesn't match a normal PowerShell stacktrace.

In the Gherkin stuff, I'm returning the actual line from the stacktrace, after skipping lines that came from Pester (similar to what ConvertTo-FailureLines does, but without manually re-writing the error).

I guess I should be calling Get-PesterResult or at least ConvertTo-FailureLines but now I'm torn about making that change. Anyone have opinions?

@nohwnd

This comment has been minimized.

Show comment
Hide comment
@nohwnd

nohwnd Feb 9, 2017

Member

I'd say go with the same output as in v3 to avoid breaking the VSCode problem matcher, if the change is easy to make. Then, if needed, we can work with Keith to introduce format that will be accurate and will work for him.

Member

nohwnd commented Feb 9, 2017

I'd say go with the same output as in v3 to avoid breaking the VSCode problem matcher, if the change is easy to make. Then, if needed, we can work with Keith to introduce format that will be accurate and will work for him.

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 10, 2017

Contributor

Ok, I spent the evening looking into this and I'm torn.

Pester 3

Basically what's going on is that there's a function Get-PesterResult in It.ps1 which creates a result object with a stackTrace string on it which is never actually used in v3. Instead, in v3, the output is recalculated all over again using ConvertTo-FailureLines in PesterState.ps1

Pester 4

The ConvertTo-FailureLines function is still there (moved to Output.ps1), but it's never used. Instead, the error messages and stackTrace that was calculated by Get-PesterResult in It.ps1 is actually output.

My feeling is that this is the worst of both worlds.

We created the Output.ps1 file to collect all the string formatting functions, but we didn't move Get-PesterResult into it (and I missed that in Gherkin, so I'm not calling it). Then we have this extra function in the Output.ps1 which we're no longer using.

Personally, I think that the algorithm used by Get-PesterResult to build the error message is elegant, but I will point out that the exception message in the stack trace is more likely to be localized. The nice thing about it is that most of the time it does not rely on a regex filter to remove lines from the ScriptStackTrace...

So: do we "improve" the output, or do we duplicate what's in Pester 3?

Duplicate Pester 3

Do we calculate the line, or use regex to capture the data from the ScriptStackTrace?

Calculate it

How do we clean up?

I pushed another commit to #725 -- I think that the output now matches Pester 3, except that we don't double-print things when -PesterOption @{ IncludeVSCodeMarker = $true }

Contributor

Jaykul commented Feb 10, 2017

Ok, I spent the evening looking into this and I'm torn.

Pester 3

Basically what's going on is that there's a function Get-PesterResult in It.ps1 which creates a result object with a stackTrace string on it which is never actually used in v3. Instead, in v3, the output is recalculated all over again using ConvertTo-FailureLines in PesterState.ps1

Pester 4

The ConvertTo-FailureLines function is still there (moved to Output.ps1), but it's never used. Instead, the error messages and stackTrace that was calculated by Get-PesterResult in It.ps1 is actually output.

My feeling is that this is the worst of both worlds.

We created the Output.ps1 file to collect all the string formatting functions, but we didn't move Get-PesterResult into it (and I missed that in Gherkin, so I'm not calling it). Then we have this extra function in the Output.ps1 which we're no longer using.

Personally, I think that the algorithm used by Get-PesterResult to build the error message is elegant, but I will point out that the exception message in the stack trace is more likely to be localized. The nice thing about it is that most of the time it does not rely on a regex filter to remove lines from the ScriptStackTrace...

So: do we "improve" the output, or do we duplicate what's in Pester 3?

Duplicate Pester 3

Do we calculate the line, or use regex to capture the data from the ScriptStackTrace?

Calculate it

How do we clean up?

I pushed another commit to #725 -- I think that the output now matches Pester 3, except that we don't double-print things when -PesterOption @{ IncludeVSCodeMarker = $true }

@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Feb 10, 2017

I pushed another commit

Was that on your fork? I'd like to test your fix.

I pushed another commit

Was that on your fork? I'd like to test your fix.

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Feb 11, 2017

Contributor

Sorry, yeah @rkeithhill, I meant to say I pushed another commit to #726

Contributor

Jaykul commented Feb 11, 2017

Sorry, yeah @rkeithhill, I meant to say I pushed another commit to #726

Jaykul added a commit to Jaykul/Pester that referenced this issue Feb 11, 2017

Jaykul added a commit to Jaykul/Pester that referenced this issue Feb 11, 2017

Jaykul added a commit to Jaykul/Pester that referenced this issue Feb 11, 2017

@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Feb 18, 2017

So when will PR #726 get merged and we get a 4.0.3? Inquiring VSCode users want to know. :-)

So when will PR #726 get merged and we get a 4.0.3? Inquiring VSCode users want to know. :-)

@rkeithhill

This comment has been minimized.

Show comment
Hide comment
@rkeithhill

rkeithhill Mar 1, 2017

Any update on this? This does negatively impact the Pester / PowerShell integration experience on VS Code. cc @daviwil

Any update on this? This does negatively impact the Pester / PowerShell integration experience on VS Code. cc @daviwil

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Mar 4, 2017

Contributor

It's merged now, @rkeithhill (not released, but merged)

Contributor

Jaykul commented Mar 4, 2017

It's merged now, @rkeithhill (not released, but merged)

@rkeithhill

This comment has been minimized.

Show comment
Hide comment

@Jaykul Thanks!

@Jaykul

This comment has been minimized.

Show comment
Hide comment
@Jaykul

Jaykul Mar 30, 2017

Contributor

Please close.

Contributor

Jaykul commented Mar 30, 2017

Please close.

@nohwnd nohwnd closed this Mar 30, 2017

@nohwnd

This comment has been minimized.

Show comment
Hide comment
@nohwnd

nohwnd Mar 30, 2017

Member

@Jaykul closed :)

Member

nohwnd commented Mar 30, 2017

@Jaykul closed :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment