Inconsistent behavior mocking external command between output verbosity 'Detailed' and 'Diagnostic'

lxs65 commented 6 months ago

Checklist

[X] Issue has a meaningful title
[X] I have searched the existing issues. See all issues
[X] I have tested using the latest version of Pester. See Installation and update guide.

What is the issue?

When mocking the dotnet CLI command (possibly other native commands as well) and testing with Should -Invoke makes the test succeed (as expected) with output verbosity set to 'Detailed' but that very same test fails with a RuntimeException when opting for the 'Diagnostic' output verbosity (or have Debug.WriteDebugMessagesFrom include 'Mock').

Expected Behavior

It is expected the test succeeds without throwing when applying 'Diagnostic' output verbosity, just like it succeeds when using 'Detailed' output verbosity.

Steps To Reproduce

Using the following "helper" cmdlet:

function Invoke-Dotnet {
    # from: https://stackoverflow.com/questions/68747649/how-do-i-execute-dotnet-build-from-within-a-powershell-script
    [CmdletBinding()]
    Param (
        [Parameter(Mandatory = $true)]
        [System.String]
        $Command,

        [Parameter(Mandatory = $true)]
        [System.String]
        $Arguments
    )

    $DotnetArgs = @()
    $DotnetArgs += $Command
    $DotnetArgs += ($Arguments -split "\s+")

    & dotnet $DotnetArgs

    if ($LASTEXITCODE -ne 0) {
        throw "There was an issue running the specified dotnet command."
    }
}

And testing this using:

$PesterPreference = New-PesterConfiguration
$PesterPreference.Output.Verbosity = 'Detailed'
$PesterPreference.Output.StackTraceVerbosity = 'Full'

BeforeAll {
    . "$PSScriptRoot\Invoke-DotNet.ps1"
}

Describe "Invoke-DotNet" {
    It "Results in LASTEXITCODE 0 on success" {
        # Arrange
        Mock dotnet -ParameterFilter { $args[0] -eq 'build' } { 
            $global:LASTEXITCODE = 0 
        }

        $Command = "build"
        $Arguments = "someFakeSolution.sln --configuration Release"
        $Arguments += " --no-restore"
        $Arguments += " --verbosity diag"

        # Act
        Invoke-DotNet -Command $Command -Arguments $Arguments

        # Assert
        $global:LASTEXITCODE | Should -Be 0
        Should -Invoke dotnet -Times 1 -Exactly -Scope It -ParameterFilter {
            $args[0] -eq 'build'
            $args[1] -eq 'someFakeSolution.sln'
            $args[4] -eq '--no-restore'
        }
    }
}

This test as provided succeeds. Changing the output verbosity in $PesterPreference to 'Diagnostic' will result in:

Mock: Executing mock behavior for mock dotnet.exe. 
Mock: Behavior for dotnet.exe was executed. 
Mock: Resolving command dotnet. 
Mock: Searching for command dotnet in the script scope. 
Mock: Found the command dotnet in the script scope and it resolved to PesterMock_script_dotnet.exe_09acd774-3b1d-4517-856c-0216ccf0f665. 
Mock: Removing function PesterMock_script_dotnet.exe_09acd774-3b1d-4517-856c-0216ccf0f665 and aliases dotnet.exe, dotnet for dotnet.exe. 
Mock: Removed function PesterMock_script_dotnet.exe_09acd774-3b1d-4517-856c-0216ccf0f665 from script session state. 
Mock: Removed alias dotnet.exe from script session state. 
Mock: Removed alias dotnet from script session state. 
  [-] Results in LASTEXITCODE 0 on success 45ms (43ms|2ms)
   RuntimeException: You cannot call a method on a null-valued expression.
   at Should-InvokeInternal, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:11067
   at Should-Invoke, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:15388
   at Invoke-Assertion, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:8098
   at Should<End>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:8048
   at <ScriptBlock>, C:\gitrepos\Playground-pester\TestDotnet\Invoke-DotNet.Tests.ps1:46
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2012
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1973
   at Invoke-ScriptBlock, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2145
   at Invoke-TestItem, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1198
   at Invoke-Block, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:834
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:892
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2012
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1973
   at Invoke-ScriptBlock, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2148
   at Invoke-Block, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:939
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:892
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2012
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1973
   at Invoke-ScriptBlock, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2148
   at Invoke-Block, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:939
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1676
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.ps1:3
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:3203
   at Invoke-InNewScriptScope, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:3210
   at Run-Test, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:1679
   at Invoke-Test, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:2500
   at Invoke-Pester<End>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:5046
   at <ScriptBlock>, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:9858
   at Invoke-Interactively, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:9865
   at Describe, C:\Users\SEGA403417\OneDrive - Exact Group B.V\Documents\PowerShell\Modules\Pester\5.5.0\Pester.psm1:9843
   at <ScriptBlock>, C:\gitrepos\Playground-pester\TestDotnet\Invoke-DotNet.Tests.ps1:9
   at <ScriptBlock>, <No file>:1

P.S. My real code-under-test does not actually use the "helper" cmdlet for invoking the dotnet CLI. It is just there to as simple as possible show the issue.

P.S. (2) It does not make a difference if I change

Should -Invoke dotnet -Times 1 -Exactly -Scope It -ParameterFilter {....

into

Should -Invoke "dotnet" -Times 1 -Exactly -Scope It -ParameterFilter {....

or

Should -Invoke -CommandName "dotnet" -Times 1 -Exactly -Scope It -ParameterFilter {....

into

Should -Invoke "dotnet" -Times 1 -Exactly -ParameterFilter {....

etc...

Describe your environment

Pester version : 5.5.0 PowerShell version: 7.4.2 OS version: Microsoft Windows NT 10.0.22631.0

Possible Solution?

No response

fflaten commented 6 months ago

Thanks for the report. Can repro and confirm, affecting all native applications when using parameterfilter. Will be fixed in 5.6.0 /cc @nohwnd

nohwnd commented 6 months ago

did you find the problem? Are we trying to log a value that is not there when writing the diagnostic log?

fflaten commented 6 months ago

Yeah. Native commands don't have CommandMetadata which I completely forgot when writing the "you might have inherited a variable in parameterfilter causing a false positive" logging. See PR :)

pester / Pester