Test fails while it should pass

[DarkLite1]

General summary of the issue

Hard to explain, but it took us a complete breakdown of a very complicated script to see what was happening. Please see the test code below.

Describe your environment

Pester version : 5.1.1 C:\Program Files\WindowsPowerShell\Modules\Pester\5.1.1\Pester.psm1
PowerShell version : 5.1.14393.3866
OS version : Microsoft Windows NT 10.0.14393.0

Steps to reproduce

The code below should pass for all tests but it reports the following errors:

[-] should pass because argument SamAccountName is only called once 425ms (421ms|4ms)
Expected Get-Stuff to be called 1 times exactly but was called 2 times
[-] should pass because argument DistinguishedName is only called once 412ms (410ms|2ms)
Expected Get-Stuff to be called 1 times exactly but was called 2 times

It seems like the parameter used in the function called $SamAccountName cannot be used as variable names in other places in the script outside of the function or it will break the check on how many times the function/mock is called.

Describe 'test' {
    BeforeAll {
        Function Get-Stuff {
            Param (
                [String]$SamAccountName,
                [String]$DistinguishedName
            )
        }
        Mock Get-Stuff
    }
    it 'should pass because argument SamAccountName is only called once' {
        Get-Stuff -SamAccountName  'a'
        Get-Stuff -DistinguishedName  'b'
        
        Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter { 
            $SamAccountName
        }
    }
    it 'should pass because argument DistinguishedName is only called once' {
        Get-Stuff -SamAccountName  'a'
        Get-Stuff -DistinguishedName  'b'
        
        Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter { 
            $DistinguishedName
        }
    }
    it 'should pass because argument SamAccountName is only called once' {
        Get-Stuff -SamAccountName  'a'
        Get-Stuff -DistinguishedName  'b'
        
        foreach (
            $samAccountName in (0..5) # rename the variable and it works
        ) {
            # do something
        }

        Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter { 
            $SamAccountName
        }
    }
    it 'should pass because argument DistinguishedName is only called once' {
        Get-Stuff -SamAccountName  'a'
        Get-Stuff -DistinguishedName  'b'
        
        foreach (
            $DistinguishedName in (0..2) # rename the variable and it works
        ) {
            # do something
        }

        Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter { 
            $DistinguishedName
        }
    }
}

Expected Behavior

Expected all tests to pass.

Current Behavior

First test fails.

[nohwnd]

@DarkLite1 for me only the last two fail. Is what you described as current behavior: "First test fails." incorrect?

[nohwnd]

It fails for you because only BoundParameters are set as variables in the ParameterFilter. You are using variable with the same name as the parameter which is set to 5 after the foreach loop. Foreach does not create a new scope, so the variable remains in scope.

This variable is inherited into the ParameterFilter because you want to be able to use variables from the test in the parameter filter:

    it 'should pass because argument SamAccountName is only called once' {
        Get-Stuff -SamAccountName  'a'
        Get-Stuff -DistinguishedName  'b'
        
        $san = 'a'
        Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter { 
            $SamAccountName -eq $san
        }
    }

So in your example, you have two calls of Get-Stuff.
When should invoke runs the filter for Get-Stuff -SamAccountName 'a' then $SamAccountName is in bound parameters, and is a. a is truthy, so the filter will pass.
When should invoke runs the filter for Get-Stuff -DistinguishedName 'a' then $SamAccountName is not in bound parameters, and is 5. 5, which is truthy, so the filter will pass.

You get 2 matching, but you asked to have exactly 1.

    Describe 'test' {
        BeforeAll {
            Function Get-Stuff {
                Param (
                    [String]$SamAccountName,
                    [String]$DistinguishedName
                )
            }
            Mock Get-Stuff
        }

        it 'should pass because argument SamAccountName is only called once' {
            Get-Stuff -SamAccountName  'a'
            Get-Stuff -DistinguishedName  'b'
            
            foreach (
                $samAccountName in (0..5) # rename the variable and it works
            ) {
                # do something
            }
    
            Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
                Write-Host "`$SamAccountName is $($SamAccountName), will pass filter? $([bool]$SamAccountName)" -ForegroundColor Cyan
                $SamAccountName
            }
        }
    }

Describing test
$SamAccountName is a, will pass filter? True
$SamAccountName is 5, will pass filter? True
  [-] should pass because argument SamAccountName is only called once 39ms (36ms|3ms)
   Expected Get-Stuff to be called 1 times exactly but was called 2 times
   at Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {, C:\Users\jajares\Desktop\t.ps1:28
   at <ScriptBlock>, C:\Users\jajares\Desktop\t.ps1:28
Tests completed in 156ms
Tests Passed: 0, Failed: 1, Skipped: 0 NotRun: 0

I don't think this is a bug.

[nohwnd]

Btw running this with the Diagnostic output will help diagnosing this as well:

Mock: Running mock filter { 
                Write-Host "`$SamAccountName is $($SamAccountName), will pass filter? $([bool]$SamAccountName)" -ForegroundColor Cyan
                $SamAccountName
             } with context: SamAccountName = a. <---
$SamAccountName is a, will pass filter? True
Mock: Mock filter passed. <---
Mock: Running mock filter { 
                Write-Host "`$SamAccountName is $($SamAccountName), will pass filter? $([bool]$SamAccountName)" -ForegroundColor Cyan
                $SamAccountName
             } with context: DistinguishedName = b. <---
$SamAccountName is 5, will pass filter? True
Mock: Mock filter passed. <---

[DarkLite1]

Thank you for getting back to me. I now fully understand where we went wrong. So thanks for the clarification and the very clear example that showed my stupidity of staring too long to my code lol. You are correct, it can be that we want to access variables within the -ParameterFilter clause of the Should CmdLet.

Looking at this from another perspective it seemed really strange because Get-Stuff only was called once with argument -SamAccountName. So this works as expected:

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $SamAccountName = $false

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $SamAccountName
    }
}

This does not as you just explained to me, we unintentionally added the variable to the scope which makes the test fail: In real life this was intentional because we have a test script file that we want to test where we really use a foreach loop with the variable named $samAccountName, which broke the test.

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $SamAccountName = $true

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $SamAccountName
    }
}

Just an idea, but it would be great if there was a parameter hashtable created by Pester containing only the parameters used in the mock. This would allow the user to really address a Parameter of the mock in the -ParameterFilter clause and not be confused by other variables set elsewhere (in the script, in the it clause, ....).

t's just a thought but something like this might clear up all possible confusion. A small example to clarify the idea:

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $samAccountName = 'a'

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $mockParameter.SamAccountName -eq $samAccountName
    }
}

PS: Thanks for the Diagnostic tip, didn't really know about that :)

[nohwnd]

Just an idea, but it would be great if there was a parameter hashtable created by Pester containing only the parameters used in the mock.

That sounds interesting. But $mockParameter would have to include all variables that are inherited to the current scope from all parents, so that hashtable would be big, and I would have to build it everytime a parameter filter is about to be invoked. This seems slow. It also brings more problems to the table. What if your variable is not in the table for some reason, maybe there is a typo or something.

It think a more reasonable solution to this is to add a logging which will check if the parameter variable we are about to define already exists and log that. This will only impact Diagnostic runs, and should show you that "Parameter $SamAccountName defined variable with value "a", but the value already existed in the current scope and had value "5", are your test variables conflicting with parameter names?". This covers the case when the variable conflicts with a parameter name that was provided.

What this does not cover is when variable does not conflict with the parameter name. (in your Get-Stuff -DistinguishedName 'b' case). This I would propose to solve by echoing the raw output of the Parameter filter into log before checking it's truthiness. "Parameter filter output is '5' which is truthy. Filter passed."

[DarkLite1]

Thank you for getting back to me. Really appreciate that you're open to suggestions.

Just an idea, but it would be great if there was a parameter hashtable created by Pester containing only the parameters used in the mock.

That sounds interesting. But $mockParameter would have to include all variables that are inherited to the current scope from all parents, so that hashtable would be big, and I would have to build it everytime a parameter filter is about to be invoked.

Why would it be needed to include all variables from the parent scopes in $mockParameter? Would it not be sufficient to make a copy of $PSBoundParameters when the mock is created? Or am I oversimplifying things here? The only goal would be to address a parameter in the function and be certain that you are addressing that parameter and not a variable from another scope.

UPDATE: I'm wrong, this will not work.... You are correct, it seems like you have to rebuild the -ParameterFilter every time for this to work. The issue is that using the log function of Pester will not warn you for mistakes like this. It took me two days to figure out I was using a variable with the same name as a function parameter ten miles deeper in the script that blew up the test. That's why it would be nice to have something build-in that doesn't require logging.

[nohwnd]

It's hard for me to distinguish a mistake from intent when I don't understand the motivation. That's why I suggest better logging, so when you see that something is wrong (because you know the intent and can identify a mistake), you have better tools to see what might be wrong.

[DarkLite1]

Yeah, I understand. That's why it's a great idea to use a hashtable for the parameters that are mocked. It might be slower but it will guarantee that people are addressing the parameter and not another variable somewhere else.

When using something like $mockParameter.SamAccountName in the code below, the intent is very clear.

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $samAccountName = 'a'

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $mockParameter.SamAccountName -eq $samAccountName
    }
}

In that case there is no diagnostic logging required to see the variables or the values they hold. The hashtable is just holding the $PSBoundParameters of the mock.

[Glober777]

@DarkLite1, that would be a serious braking change, affecting mocks that do not depend on variables in the parent scope.

Wouldn't it be more intuitive, if it was implemented the other way around, where you'd have to specify required variables from the parent scope more explicitly, i.e. with the help of a using scope modifier (consistently to how those are used in Start-Job and Invoke-Command cmdlets)? For example:

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $samAccountName = 'a'

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $SamAccountName -eq $using:samAccountName
    }
}

[nohwnd]

Will implement the logging as proposed. I will look into the psboudn parameters later. But the $using won't work imho, because we are running the the same scope, not in other scope.

[DarkLite1]

Thank you @nohwnd for improving the logging. Also thank you @Glober777 for thinking out of the box one this one. Shame it doesn't work with using.

Can we maybe keep this one open until we have a way to really address the arguments of a function in the -ParameterFilter clause? I still believe this would be helpful for many people as in 99.9 % of all cases the -ParameterFilter clause is used to check the arguments passed to the function.

[fflaten]

$PesterBoundParameters was made available in 5.2.0 (PR #1916). That means you can now be even more explicit in your filters when you need check if the mock was called using specific parameters. $PesterBoundParameters will hopefully never be confused with a local variable in It-block. A variable in the It-block named the same as a mock parameter would however still be overwritten inside the filter like your $samAccountName-scenario. Changing that would be a breaking change.

Lets say we update the mocking docs to advise using $PesterBoundParameters.<MockParameterName> in parameterfilters and a warning about using conflicting names with known parameters for any "expectedvalue"-variables in the It-block etc. Would we then consider this closed? 🙂

Sample using $PesterBoundParameters:

It 'should pass because argument SamAccountName is only called once' {
    Get-Stuff -SamAccountName  'a'
    Get-Stuff -DistinguishedName  'b'
    
    $expectedSamAccountName = 'a'

    Should -Invoke Get-Stuff -Times 1 -Exactly -ParameterFilter {
        $PesterBoundParameters.SamAccountName -eq $expectedSamAccountName 
    }
}

[DarkLite1]

@fflaten if we advice in the docs to use $PesterBoundParameters for accessing an argument passed to a mocked function I would definitely be ok closing this one. I feel no one is really aware of this issue/functionality and it would clear up a lot of confusion about what the variable holds/what variable one is actually addressing/what one is trying to asses.

Adding a warning message for using the same variable name in the -ParameterFilter clause that is conflicting with the mocked parameter name would be of great help too.

IMHO it would be best practice to always use $PesterBoundParameters whenever you can. It makes it really clear on what one is trying to achieve.

Thank you for implementing this guys, really appreciate it.

[fflaten]

I feel no one is really aware of this issue/functionality and it would clear up a lot of confusion about what the variable holds/what variable one is actually addressing/what one is trying to asses.

It is very new so not unexpected :-)

IMHO it would be best practice to always use $PesterBoundParameters whenever you can. It makes it really clear on what one is trying to achieve.

I'll submit a docs PR to mention this in a tip admonitions (green block).

Adding a warning message for using the same variable name in the -ParameterFilter clause that is conflicting with the mocked parameter name would be of great help too.

I like the idea as a diagnostic-output warning. What do you think @nohwnd ?

[nohwnd]

I like it, it was my idea :D #1873 (comment) It does not work at the moment though, because when running the filter we are already in the function, so we already have that parameter defined.

[fflaten]

Haha, my bad 😅
We'll keep this open until we got that working then.