Adjust failure output to be VSCode problemMatcher friendly

[rkeithhill]

I'm trying to add problemMatcher support to a pester task for the PoweShellEditorServices extension for VSCode. The problem is that the problemMatcher uses line-oriented regexes to extract the following required fields: file, line, message. You can specify a problemMatcher in a task like so:

"tasks": [
    {
        "taskName": "Pester",
        "isTestCommand": true,
        "problemMatcher": {
            "owner": "powershell",
            "fileLocation": ["absolute"],
            "severity": "error",
            "pattern": [
                {
                    "regexp": "^\\s*\\[-\\](.*)$",
                    "message": 1
                },
                {
                    "regexp": "^.*$"
                },
                {
                    "regexp": "^.*$"
                },
                {
                    "regexp": "^\\s+at line: (\\d+) in (.*)$",
                    "line": 1,
                    "file": 2,
                    "message": 2
                }
            ]
        }
    }
]

This will match the following type of Pester output:

 [-] Should accept pipeline input to Path 111ms
   Expected: {C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\foo[1].txt}
   But was:  {}
   at line: 47 in C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\PathProcessing.Tests.ps1
   47:         Get-ChildItem -LiteralPath "$pwd\foo[2].txt" | Import-FileNoWildcard | Should Be "$PSScriptRoot\foo[1].txt"

This results in a reasonable VSCode experience:

Here is where it falls down. The above handles the case when there are two lines of error info between the initial [-] line and the line with the filename/line number info. Here's a different error message that has four lines between those two locations:

Describing Verify Path Processing for Non-existing Paths Allowed Impl
 [-] Processes non-wildcard absolute path to non-existing file via -Path param 483ms
   Expected string length 92 but was 91. Strings differ at index 88.
   Expected: {C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\READMENew2.md}
   But was:  {C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\ReadmeNew.md}
   ---------------------------------------------------------------------------------------------------^
   at line: 10 in C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\PathProcessing.Tests.ps1
   10:         New-File -Path $PSScriptRoot\ReadmeNew.md | Should Be "$PSScriptRoot\READMENew2.md"

This no longer triggers my problemMatcher multiline regex spec because the "number" of lines between the "failure" indicator [-] and the line with the line number and filename is variable. I can't figure out yet if VSCode can handle that situation but initially it appears it can't.

So can Pester modify its error output to help support editors like VSCode by changing the error output such that the first two lines are always the same format? For example:

 [-] <test description> <elapsed mS>
   at line: <line> column: <col> in <test filename>
   <assertion specific error info>

Then after that it's OK if the output is a bit more free form. I realize the column output might be new to some error output. If you never know the column number of the source then skip that field. It defaults to 1 which is sufficient for tagging the problematic "line". For more info on VSCode tasks (and problemMatchers) checkout this page.

[dlwyatt]

That's kind of a mess. I really don't want to have to tiptoe around every change to console output; that's meant to be nice for people to read.

The ideal situation would be for VSCode to use the -OutputFile / -OutputFormat parameters and just read in the NUnit XML. For that, we wouldn't even have to make any changes to Pester. Alternatively, we could add a switch that changes the console output over to something like a single line of JSON, CSV or XML per test, for integration with things that only read the console output and can't deal with objects or files.

[rkeithhill]

Unfortunately VSCode scans the output from the Output view which does need to be human readable.

I have found that I can create multiple problem matchers, each matching a different number of lines between the first [-] line and the at line: xx line. Yay!

Right now I have four matchers with 1, 2, 3 and 4 lines between. Can there ever be more than four lines between? Thanks!

[dlwyatt]

At the moment, I can think of two things that might screw with those assumtions: Should Throw / Should Not Throw, and errors that come from something other than the Should command. For example:

function Level1 {
    Level2
}

function Level2 {
    Level3
}

function Level3 {
    throw 'Up'
}

Describe Testing {
    # Level1
    It 'Throws an error' {
        { Level1 } | Should Not Throw
    }
}

If I run it as-is, I get this:

Describing Testing
 [-] Throws an error 43ms
   Expected: the expression not to throw an exception. Message was {Up}
       from line:10 char:5
       +     throw 'Up'
       +     ~~~~~~~~~~
   16:         { Level1 } | Should Not Throw
   at <ScriptBlock>, <No file>: line 16

And if I uncomment the call to Level1 out in the Describe block, this:

Describing Testing
 [-] Error occurred in Describe block 31ms
   RuntimeException: Up
   at Level3, <No file>: line 10
   at Level2, <No file>: line 6
   at Level1, <No file>: line 2
   at <ScriptBlock>, <No file>: line 14

(The <No file> bits would be replaced with a proper path if I'd saved it first.)

[rkeithhill]

Yeah, that complicates the regexes a bit. :-) Especially that last one as the number of lines between is now arbitrary (dependent on the call stack depth).

If you moved the error location to always be on the second line, it would still be readable, right? :-)

Describing Verify Path Processing for Non-existing Paths Allowed Impl
 [-] Processes non-wildcard absolute path to non-existing file via -Path param 483ms
   at line: 10 in C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\PathProcessing.Tests.ps1
   10:         New-File -Path $PSScriptRoot\ReadmeNew.md | Should Be "$PSScriptRoot\READMENew2.md"
   Expected string length 92 but was 91. Strings differ at index 88.
   Expected: {C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\READMENew2.md}
   But was:  {C:\Users\Keith\.vscode-insiders\extensions\ms-vscode.PowerShell-0.3.1\examples\ReadmeNew.md}
   ---------------------------------------------------------------------------------------------------^

Describing Testing
 [-] Throws an error 43ms
   at line: 16 in <ScriptBlock>, <No file>
   16:         { Level1 } | Should Not Throw
   Expected: the expression not to throw an exception. Message was {Up}
       from line:10 char:5
       +     throw 'Up'
       +     ~~~~~~~~~~

Describing Testing
 [-] Error occurred in Describe block 31ms
   at line: 14 in <ScriptBlock>, <No file>
   RuntimeException: Up
   at Level3, <No file>: line 10
   at Level2, <No file>: line 6
   at Level1, <No file>: line 2
   at <ScriptBlock>, <No file>: line 14

[dlwyatt]

I played around a little bit with the code, and I don't think I like sticking the message in the middle of a split up (or duplicated) stack trace like that. (This can also happen for Should assertions, if the test happens to put them inside function calls for some reason.)

It seems like the only real problem here is that you want both the message and the stack trace information... if you set the message to something generic ("Pester test failed", or whatever), you could just match on the lines of the stack trace and call it a day. You'd even wind up highlighting every line of the trace that way. Would that work?

[rkeithhill]

How about if we skipped doing a problem matcher for the last example? It's more of a test error (as opposed to failure) anyway. The problem with the call stack is that I don't think folks want an error per stack frame of a single test. That'd be like Visual Studio's test explorer reporter an error for every stack frame in the stack. I wouldn't want that. I just want to know which test failed and ideally have something I can double click to navigate to that test.

As you mentioned earlier, how about another output option that isn't turned on by default but I could enable it with the VSCode task runner? The thing is, I would still want that output to be human readable as it will appear in the VSCode output window. But if the location (line # / [function], [filename]) is always on the second line (perhaps we punt on "runtimeException" errors) the PowerShell extension could provide a real nice Pester integration experience.

[dlwyatt]

Yeah, I suppose that's probably fine. The API bloat from adding an extra switch for this is a bit unfortunate, but there's probably not a "one size fits all" solution for the output anyway.

This might be a good time to introduce a practice similar to the -SessionOption parameter on New-PSSession, where we place lesser-used parameters into a separate command / object. (-Strict, -Quiet and -CodeCoverage might have belonged there as well; maybe we can deprecate these and move them in v4. That would leave the basic Invoke-Pester parameters as those related to filtering and automation-friendly output.)

[rkeithhill]

@dlwyatt Thanks!!

[dlwyatt]

BTW, I snuck in some more convenient syntax as well, if you prefer not to have to call New-PesterOption directly:

Invoke-Pester -PesterOption @{ IncludeVSCodeMarker = $true }

[rkeithhill]

I'm using that syntax. Thanks.