pester / Pester

Pester is the ubiquitous test and mock framework for PowerShell.
https://pester.dev/
Other
3.11k stars 473 forks source link

Can't Verify Mocks Called Within BeforeAll Block #1622

Closed jsmythsci closed 4 years ago

jsmythsci commented 4 years ago

1. General summary of the issue

It seems that Mocks called within a BeginAll{} block cannot be verified in an adjacent child It{} block.

Based on what I have read it seems like it should work but maybe I am missing something.

Here is sample code to illustrate what I mean:

function Get-Foo() {}
Describe 'Example' {
    BeforeEach {
        Mock Get-Foo -Verifiable {}
    }

    Context 'BeforeAll' {
        BeforeAll {
            Get-Foo
        }
        It "Doesn't work?" {
            Assert-MockCalled Get-Foo -Times 1 -Exactly
        }
    }
    Context 'BeforeEach' {
        BeforeEach {
            Get-Foo
        }
        It 'Does work' {
            Assert-MockCalled Get-Foo -Times 1 -Exactly
        }
    }
    Describe 'It' {
        It 'Also works' {
            Get-Foo
            Assert-MockCalled Get-Foo -Times 1 -Exactly
        }
    }
}

2. Describe Your Environment

Pester version : 5.0.2 C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psd1 PowerShell version : 5.1.18362.752 OS version : Microsoft Windows NT 10.0.18363.0

3. Expected Behavior

The sample code should pass its test. Smallest sample that demonstrates the issue:

function Get-Foo() {}
Describe 'BeforeAll' {
    BeforeAll {
        Mock Get-Foo -Verifiable {}
        Get-Foo
    }
    It "Doesn't work?" {
        Assert-MockCalled Get-Foo -Times 1 -Exactly
    }
}

4.Current Behavior

The sample code returns the following error:

Starting discovery in 1 files.
Discovery finished in 270ms.
[-] BeforeAll.Doesn't work? 289ms (194ms|95ms)
 Expected Get-Foo to be called 1 times exactly but was called 0 times
 at Should -Invoke @__params__p, C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psm1:11655

Tests completed in 1.75s
Tests Passed: 0, Failed: 1, Skipped: 0 NotRun: 0

5. Possible Solution

6. Context

I am new to Pester and very new to v5. I ran across this while refactoring some tests that worked fine in v3.

I suspect that it is something that I just don't understand rather than an actual bug but I figured I would raise it since I can't find anything that seems to explain why it should work this way.

asears commented 4 years ago

Still working through the idiosyncracies of v5 myself and would also like some clarity on scoping in Pester 5. Have seen some odd behaviour when mocking things that Pester uses internally. (Set-TraceLevel for example)

I think the main issue is function Get-Foo() needs to be wrapped in Before block.

Mocks are scoped based on their placement Mocks are no longer effective in the whole Describe / Context in which they were placed. Instead they will defualt to the block in which they were placed.

Here's a working example, including new Should-Invoke syntax. I added the function code within BeforeAll, also works in BeforeEach.

Describe 'Example' {
    BeforeAll {
        function Get-Foo() {}
        Mock Get-Foo -Verifiable {}
    }

    Context 'BeforeAll' {
        BeforeAll {
            function Get-Foo() {}
            Mock Get-Foo -Verifiable {}
        }
        It "Doesn't work?" {
            Get-Foo
            Should -Invoke Get-Foo -Times 1 -Exactly
        }
    }
    Context 'BeforeEach' {
        BeforeEach {
            Get-Foo
        }
        It 'Does work' {
            Should -Invoke Get-Foo -Times 1 -Exactly
        }
    }
    Describe 'It' {
        It 'Also works' {
            Get-Foo
            Should -Invoke Get-Foo -Times 1 -Exactly
        }
    }
}
diff --git b/my.tests.ps1 a/my.tests.ps1
index 2ec38a7..9ad915f 100644
--- b/my.tests.ps1
+++ a/my.tests.ps1
@@ -1,15 +1,17 @@
-function Get-Foo() {}
 Describe 'Example' {
-    BeforeEach {
+    BeforeAll {
+        function Get-Foo() {}
         Mock Get-Foo -Verifiable {}
     }

     Context 'BeforeAll' {
         BeforeAll {
-            Get-Foo
+            function Get-Foo() {}
+            Mock Get-Foo -Verifiable {}
         }
         It "Doesn't work?" {
-            Assert-MockCalled Get-Foo -Times 1 -Exactly
+            Get-Foo
+            Should -Invoke Get-Foo -Times 1 -Exactly
         }
     }
     Context 'BeforeEach' {
@@ -17,13 +19,13 @@ Describe 'Example' {
             Get-Foo
         }
         It 'Does work' {
-            Assert-MockCalled Get-Foo -Times 1 -Exactly
+            Should -Invoke Get-Foo -Times 1 -Exactly
         }
     }
     Describe 'It' {
         It 'Also works' {
             Get-Foo
-            Assert-MockCalled Get-Foo -Times 1 -Exactly
+            Should -Invoke Get-Foo -Times 1 -Exactly
         }
     }
 }

BeforeAll: Defines a series of steps to perform at the beginning of the current Context or Describe block. BeforeEach: Defines a series of steps to perform at the beginning of every It block within the current Context or Describe block. Context: Provides logical grouping of It blocks within a single Describe block. Describe: Creates a logical group of tests. Should: Should is a keyword what is used to define an assertion inside It block.

Should documentation is missing new -Invoke syntax. https://pester.dev/docs/commands/Should Probably need an issue for that.

v5 Discussion

From Converting tests to pester 5

Code inside a Describe- or Context-block should be inside a It-, Before-, or After-block. The exception to this is variables that contain test cases, those variables should be placed inside the Describe-block and before the It-block, but outside of the Before-blocks. they must be outside Before-blocks and It-blocks, but inside Describe- or Context-blocks.

From Community talk about Pester 5

Pester v4 Pester v5
In Pester v4 the BeforeEach is executed in a scope above It, so variables defined in BeforeEach are not writable from It and not changed in AfterEach, this makes sharing data between the test and the teardown difficult. For example when you created a file in the test and want to remove it, or close a connection to a database etc. In Pester v5 BeforeEach It and AfterEach all run in the same scope.
In Pester v4 the mock defined in the It block is defined on the containing Describe, so it leaks to the subsequest It blocks. This is a hurdle that everyone learning Pester faces. It also forces the test author to add unnecessary Context blocks when the mock should be "isolated" to one It block. In Pester v5 the Mock is defined on the block that contains it. So putting it within It will define this mock for that It and putting it into BeforeAll will define it for the Describe/Context that contains it.
Should is the way to do assertions, yet in Pester v4 there are two notably different assertions, Assert-MockCalled and Assert-VerifiableMock in Pester v5 these commands are deprecated and Should -Invoke and Should -InvokeVerifiable are newly available, and recommended to use.

We can leverage the new PesterPreference / Configuration Object to get some additional details on what is going on. I have a setup script which configures the object's common properties. Here's one I toggle to show the details on what Pester's doing with mocks.

$PesterPreference = [PesterConfiguration]::Default
$PesterPreference.Debug.WriteDebugMessages = $true
jsmythsci commented 4 years ago

@asears Thank you for the feedback. I agree that it seems to be a matter of scoping but I don't believe that it is related to where the "real" function is defined. Rather, it seems to be a matter of where the mocked function is invoked.

From what I can see, the reason your code sample works and mine does not is because of where Get-Foo is invoked for the first test. My code invokes Get-Foo in the BeforeAll{} block whereas your sample invokes it in the It{} block.

When I move the call to Get-Foo from the It{} block to the BeforeAll{} block in your sample I get the same results that I get with my original sample.

$ diff _a.ps1 _b.ps1 --unified
--- _a.ps1      2020-07-01 12:26:06.028298100 -0400
+++ _b.ps1      2020-07-01 13:34:14.675666500 -0400
@@ -8,9 +8,9 @@
         BeforeAll {
             function Get-Foo() {}
             Mock Get-Foo -Verifiable {}
+            Get-Foo
         }
         It "Doesn't work?" {
-            Get-Foo
             Should -Invoke Get-Foo -Times 1 -Exactly
         }
     }

Here's a mockup of the v3 code I was trying to migrate:

function Remove-Foo {
    foreach ($i in @('bar','baz')) {
        if (Test-Path $i) {
            Remove-Item $i
        }
    }
}

Describe 'Remove-Foo' {
    # Make sure we don't accidentally remove anything
    Mock Remove-Item {} -Verifiable

    $vars = @('bar','baz')

    Context 'Testing foo' {
        Mock Test-Path { $false } -Verifiable
        Remove-Foo

        It 'Calls Test-Path exactly twice' {
            Assert-MockCalled Test-Path -Times 2 -Exactly
        }

        foreach ($v in $vars) {
            It "Should check for $v" {
                Assert-MockCalled Test-Path -Times 1 -Exactly -ParameterFilter { $Path -eq $v}
            }
        }
    }

    Context 'Foo does not exist' {
        Mock Test-Path { $false }
        Remove-Foo

        It 'Does not call Remove-Item' {
            Assert-MockCalled Remove-Item -Times 0 -Exactly
        }
    }

    Context 'Foo exists' {
        Mock Test-Path { $true }
        Remove-Foo

        It 'Calls Remove-Item exactly twice' {
            Assert-MockCalled Remove-Item -Times 2 -Exactly
        }

        foreach ($v in $vars) {
            It "Should check for $v" {
                Assert-MockCalled Remove-Item -Times 1 -Exactly -ParameterFilter { $Path -eq $v}
            }
        }
    }
}

Note that Remove-Foo is only called once in each Context{}. It is this flow that I was trying to replicate by calling the function in the BeforeAll{} block but, as the samples demonstrate, this doesn't seem to work.

My tests have shown that the mocked function is getting called as expected when invoked from the BeforeAll{} block, it just can't be verified in an associated It{} block. This will report success for the BeforeAll{} and failure for the It{}:

Describe 'foo' {
    BeforeAll {
        [int]$callCount = 1
        Mock Write-Host -Verifiable {}
        Write-Host ''
        Assert-MockCalled Write-Host -Times $callCount -Exactly
    }

    It 'bar' {
        Assert-MockCalled Write-Host -Times $callCount -Exactly
    }
}

Output:

Starting discovery in 1 files.
Discovery finished in 39ms.
[-] foo.bar 27ms (25ms|3ms)
 Expected Write-Host to be called 1 times exactly but was called 0 times
 at Should -Invoke @__params__p, C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psm1:11655

Tests completed in 447ms
Tests Passed: 0, Failed: 1, Skipped: 0 NotRun: 0

This shows that It 'bar' {} is executing. It also shows that it inherits the $callCount variable from the BeforeAll{} block, as expected.

Changing $callCount to 2 also has the expected effect: the BeforeAll{} block fails and It 'bar' {} never runs.

Output:

Starting discovery in 1 files.
Discovery finished in 25ms.
[-] Describe foo failed
 Expected Write-Host to be called 2 times exactly but was called 1 times
 at Should -Invoke @__params__p, C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psm1:11655

Tests completed in 270ms
Tests Passed: 0, Failed: 1, Skipped: 0 NotRun: 0
BeforeAll \ AfterAll failed: 1
  - foo

From all of this I can infer:

  1. It{} inherits Mocks from BeforeAll{}.
  2. It{} inherits variables from BeforeAll{}.
  3. It{} does not inherit whatever mechanism Pester uses to track calls to Mocks from BeforeAll{}.

The last point seems counter-intuitive to me so what I would like to understand is whether these 3 "facts" are actually true. I think the logic I used to come to the conclusion is sound but it wouldn't be the first time I made I mistake.

Secondly, assuming the list is accurate, is it intended and/or expected behaviour or is it a bug?

asears commented 4 years ago

I tested a few different things your sample above and had some strange scoping issues too. Very confusing!

Non working debug session. It seems to lose / reset the count when It is entered.

Discovery: Starting test discovery in 1 test containers. 

Starting discovery in 1 files.
Discovery: Discovering tests in my.tests.ps1 
Discovery: Found 1 tests in 9 ms 
Discovery: Processing discovery result objects, to set root, parents, filters etc. 
Filter: (foo) Block will be included in the run, because there were no include filters, and will let its children to determine whether or not it should run. 
Filter: (foo.bar) Test will be included in the run, because there were no include filters so all tests are included unless they match exclude rule. 
Discovery finished in 80ms.
Discovery: Test discovery finished. 
Mock: Setting up default mock for Write-Host. 
Mock: We are in a block, one time setup or similar. Returning mock table from test block. 
Mock: Resolving command Write-Host. 
Mock: Searching for command Write-Host in the caller scope. 
Mock: Found the command Write-Host in the caller scope. 
Mock: Mock does not have a hook yet, creating a new one. 
Mock: Defined new hook with bootstrap function PesterMock_9676dab5-0b84-4525-a803-8b9d0824159b and aliases Write-Host, Microsoft.PowerShell.Utility\Write-Host. 
Mock: Adding a new default behavior to Write-Host. 
Mock: Mock for Write-Host was invoked from block Process, resolving call history and behaviors. 
Mock: Getting all defined mock behaviors in this and parent scopes for command Write-Host. 
Mock: Finding all behaviors in this block and parent blocks. 
Mock: Found behaviors for 'Write-Host' in 'foo'. 
Mock: Found 1 behaviors for 'Write-Host': 
    Body: {  }
    Filter: $null
    Verifiable: True
Mock: We are in a block, one time setup or similar. Returning mock table from test block. 
Mock: Finding a mock behavior.
Mock: {  } is a default behavior and will be used for the mock call.
Mock: Executing mock behavior for mock Write-Host.
Mock: Behavior for Write-Host was executed.
Mock: Resolving command Write-Host.
Mock: Searching for command Write-Host in the caller scope.
Mock: Found the command Write-Host in the caller scope and it resolved to PesterMock_9676dab5-0b84-4525-a803-8b9d0824159b.
Mock: Running mock filter {  $True  } with context: Object = .
Mock: Mock filter passed.
Mock: Resolving command Write-Host.
Mock: Searching for command Write-Host in the caller scope.
Mock: Found the command Write-Host in the caller scope and it resolved to PesterMock_9676dab5-0b84-4525-a803-8b9d0824159b.
[-] foo.bar 16ms (13ms|3ms)
 Expected Write-Host to be called 1 times exactly but was called 0 times
 at Should -Invoke @__params__p, C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psm1:11655

Mock: Removing function PesterMock_9676dab5-0b84-4525-a803-8b9d0824159b and aliases Write-Host, Microsoft.PowerShell.Utility\Write-Host for Write-Host.
Tests completed in 158ms
Tests Passed: 0, Failed: 1, Skipped: 0 NotRun: 0

A "working" script

Describe 'foo' {
    BeforeAll {
        [int]$callCount = 1
        Mock Write-Host -Verifiable {}
        Write-Host ''
        Assert-MockCalled Write-Host -Times $callCount -Exactly
    }

    It 'bar' {
        Write-Host 'heyho'
        Assert-MockCalled Write-Host -Times $callCount -Exactly
    }
}
jsmythsci commented 4 years ago

I think we are saying the same thing, though it still leaves the question of whether it is a bug or intended behaviour.

I expanded the test case a little further and here, I think, things get even weirder:

Describe 'foo' {
    BeforeAll {
        [int]$callCount = 1
        Mock Write-Host -Verifiable {}
        Write-Host ''
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'throws' {
        Mock Write-Host -Verifiable { throw 'ERROR!' }

        {Write-Host '' } | Should -Throw
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'changes counts' {
        $callCount = 2
        Write-Host 'How now'
        Write-Host 'brown cow?'
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'is unaffected by changes in previous It{} blocks' {
        Write-Host ''
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    AfterAll {
        Should -Invoke Write-Host -Times $callCount -Exactly
    }
}

Based on our previous tests I would expect this to work but, again, it does not:

Starting discovery in 1 files.
Discovery finished in 31ms.
[-] Describe foo failed
 Expected Write-Host to be called 1 times exactly but was called 5 times
 at Should -Invoke @__params__p, C:\Program Files\WindowsPowerShell\Modules\Pester\5.0.2\Pester.psm1:11655

Tests completed in 567ms
Tests Passed: 3, Failed: 0, Skipped: 0 NotRun: 0
BeforeAll \ AfterAll failed: 1
  - foo

The report explicitly states that the tests (It{} block) passed and only the BeforeAll \ AfterAll failed. We know the BeforeAll{} is passing because if it was not then the child test would not run so it must be the AfterAll{} block that is failing.

What I believe we can infer from this is that:

  1. Child scopes (It{}) inherit variables ($expectCount) from parent scopes (BeforeAll{}).
  2. Modifying variables in child scopes does not affect variables in parent scopes.
  3. Child scopes inherit Mocks (Mock Write-Host -Verifiable {}) defined in parent scopes.
  4. Modifying/overwriting Mocks in child scopes does not affect Mocks defined in parent scopes.
  5. Child scopes do not inherit call history of Mocks from parent scopes.
  6. Calling Mocks in child scopes does affect call history in parent scopes. 6.1. This holds true even if the child scope redefines the Mock.

The first 4 points make sense to me but the last 2 seem counter-intuitive. And point 6.1 seems especially wrong, in my opinion.

I am new to all of this, though, so there may be a good reason for it that I just am not aware of.

EDIT: Update validations to use recommended syntax. Slightly reword list of inferred facts to hopefully make it clearer.

jsmythsci commented 4 years ago

I took a closer look at the v5 ReadMe and confirmed that this is expected behaviour.

Here is a fixed version of the expanded example in my previous comment:

Describe 'foo' {
    BeforeAll {
        [int]$callCount = 1
        Mock Write-Host -Verifiable {}
        Write-Host ''
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'counts the parent' {
        Should -Invoke Write-Host -Times $callCount -Exactly -Scope Describe
    }

    It 'throws' {
        Mock Write-Host -Verifiable { throw 'ERROR!' }

        { Write-Host '' } | Should -Throw
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'changes counts' {
        $callCount = 2
        Write-Host 'How now'
        Write-Host 'brown cow?'
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    It 'is unaffected by changes in previous It{} blocks' {
        { Write-Host '' } | Should -Not -Throw
        Should -Invoke Write-Host -Times $callCount -Exactly
    }

    AfterAll {
        # Shouldn't this be 4?
        #   1 - BeforeAll
        #   0 - It 'throws' (Mock is redefined)
        #   2 - It 'changes counts'
        #   1 - It 'is unaffected by changes in previous It{} blocks'
        Should -Invoke Write-Host -Times 5 -Exactly
    }
}

I still don't understand why the call to the child Mock in It 'throws'{} is counted in the Describe{} scope but I think that discussion belongs in a different issue.