Adam Cameron's Dev Blog: December 2019

G'day:
Yesterday we had a seemingly strange situation with a test one of my colleagues had written. It was behaving as if PHPUnit's exactly matcher was not working. The developer concerned was in the process of concluding that that is exactly what the problem is: PHPUnit. I suggested we pause and back-up a bit: given thousands of people uses PHPUnit and the exactly matcher every day (including ourselves) and have not reported this issue, whereas the code we are running it with was freshly written and not used by anyone yet... almost certainly the problem lay with our code.

Before I get on with what the problem was, this bears repeating:

If you are doing something new and it's going wrong, the problem will almost certainly not be related to any established third-party tools you are using. It'll be down to how you're using them.

I find it's a really helpful mindset when troubleshooting problems to just own the issue from the outset, rather than looking around for something else to blame. And if you've looked and looked and can't see the problem with your own code, this probably just means you haven't spotted the problem yet. Absence of evidence is not evidence of absence.

Anyway, the issue at hand. Here's a pared-down repro of the situation. The code is meaningless as I've removed all business context from it, but we have this:

class MyService
{
    private $dependency;

    function __construct(MyDependency $dependency){
        $this->dependency = $dependency;
    }

    function myMethod() {
        return $this->dependency->someMethod();
    }
}

And MyDependency is this:

class MyDependency
{
    function someMethod(){
        return "ORIGINAL VALUE";
    }
}

myMethod is new, so the dev had written a test for this:

class MyServiceTest extends TestCase
{

    /** @dataProvider provideTestCasesForMyMethodTests */
    public function testMyMethodViaDataProvider($dependency)
    {
        $dependency
            ->expects($this->once())
            ->method('someMethod')
            ->willReturn("MOCKED VALUE");

        $service = new MyService($dependency);

        $result = $service->myMethod();

        $this->assertEquals("MOCKED VALUE", $result);
    }

    public function provideTestCasesForMyMethodTests(){
        return [
            'it should call someMethod once' => [
                'dependency' => $this->createMock(MyDependency::class)
            ]
        ];
    }
}

I hasten to add that it's completely daft to have the data provider in this example. However in the real-world example there were valid test variations, and given the method being tested was a factory method, part of the test was to check that the relevant method had been called on the relevant object being returned by the factory method. The data provider was legit.

This test passes:

PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php
PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

. 1 / 1 (100%)

Time: 77 ms, Memory: 4.00 MB

OK (1 test, 1 assertion)
PS C:\src\php\general>

However when we were trouble shooting something, we ended up with this assertion:

$dependency
    ->expects($this->exactly(10))
    ->method('someMethod')
    ->willReturn("MOCKED VALUE");

And the test still passed:

Whut the?

When we were looking at this I asked my colleague to simplify their tests a bit. The IRL version was testing this case via a data provider and test that was testing a bunch of things in a method that had some complexity issues, and I wanted to pare the situation back to just one simple test, testing this one thing. We ended up with this test:

public function testMyMethodViaInlineMock()
{
    $dependency = $this->createMock(MyDependency::class);
    $dependency
        ->expects($this->once())
        ->method('someMethod')
        ->willReturn("MOCKED VALUE");

    $service = new MyService($dependency);

    $result = $service->myMethod();

    $this->assertEquals("MOCKED VALUE", $result);
}

The difference here being we are not using a data provider any more, the mocking of the dependency is in the test. And this passes:

PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

. 1 / 1 (100%)

Time: 61 ms, Memory: 4.00 MB

OK (1 test, 2 assertions)
PS C:\src\php\general>

Good, fine, but now we tested out the ->expects($this->exactly(10)) issue again:

PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

F 1 / 1 (100%)

Time: 102 ms, Memory: 4.00 MB

There was 1 failure:

1) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyMethodViaInlineMock
Expectation failed for method name is "someMethod" when invoked 10 time(s).
Method was expected to be called 10 times, actually called 1 times.

FAILURES!
Tests: 1, Assertions: 2, Failures: 1.
PS C:\src\php\general>

This is more like it. But... erm... why?

I'd had "unexpected" behaviour previously when referring to $this inside a data provider method, because the data provider method is not called on the same instance of the test class that the tests are run with (why? Buggered if I know, but it is), and had my suspicions that this could be contributing to it. This is when we just shrugged and left the test as it was - working now - and I undertook to investigate some more later. The code I've been sharing here is the start of my investigation. I was at this point none the wiser though.

On a whim I tried another test variation, to see if there was any change in behaviour across the threshold of the count (so checking "off by one" situations). Here I have a new method that calls the same dependency method five times:

function myOtherMethod(){
     $this->dependency->someOtherMethod();
     $this->dependency->someOtherMethod();
     $this->dependency->someOtherMethod();
     $this->dependency->someOtherMethod();
    return  $this->dependency->someOtherMethod();
}

And a test for it that just checks what happens when we expect it to be called 3-7 times:


/** @dataProvider provideTestCasesForMyOtherMethodTests */
public function testMyOtherMethodCallsDependencyMethodEnoughTimes($dependency, $expectedCount) {
    $dependency
        ->expects($this->exactly($expectedCount))
        ->method('someOtherMethod')
        ->willReturn("MOCKED VALUE");

    $service = new MyService($dependency);

    $result = $service->myOtherMethod();

    $this->assertEquals("MOCKED VALUE", $result);
}

public function provideTestCasesForMyOtherMethodTests(){
    return [
        'it expects myOtherMethod to be called 3 times' => [
            'dependency' => $this->createMock(MyDependency::class),
            'expectedCount' => 3
        ],
        'it expects myOtherMethod to be called 4 times' => [
            'dependency' => $this->createMock(MyDependency::class),
            'expectedCount' => 4
        ],
        'it expects myOtherMethod to be called 5 times' => [
            'dependency' => $this->createMock(MyDependency::class),
            'expectedCount' => 5
        ],
        'it expects myOtherMethod to be called 6 times' => [
            'dependency' => $this->createMock(MyDependency::class),
            'expectedCount' => 6
        ],
        'it expects myOtherMethod to be called 7 times' => [
            'dependency' => $this->createMock(MyDependency::class),
            'expectedCount' => 7
        ]
    ];
}

All things being equal, I was expecting no failures here, given what we'd seen before. But... erm...

OK so this is a bit perplexing. When the expected call count is less than the actual call count we get it failing correcty. But when it's more... no failure. Now I'm flummoxed. For good measure I also have a test not creating the dependency in the data provider, but instead inline in the test:

/** @dataProvider provideTestCasesForMyOtherMethodTests */
public function testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest($_, $expectedCount) {
    $dependency = $this->createMock(MyDependency::class);
    $dependency
        ->expects($this->exactly($expectedCount))
        ->method('someOtherMethod')
        ->willReturn("MOCKED VALUE");

    $service = new MyService($dependency);

    $result = $service->myOtherMethod();

    $this->assertEquals("MOCKED VALUE", $result);
}

And this one behaves correctly:

PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php --filter=testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

FF.FF 5 / 5 (100%)

Time: 67 ms, Memory: 4.00 MB

There were 4 failures:

1) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest with data set "it expects myOtherMethod to be called 3 times" (Mock_MyDependency_2707ab91 Object (...), 3)
me\adamcameron\general\phpunit\expectsWithDataProviderIssue\MyDependency::someOtherMethod() was not expected to be called more than 3 times.

C:\src\php\general\src\phpunit\expectsWithDataProviderIssue\MyService.php:21
C:\src\php\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php:99

2) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest with data set "it expects myOtherMethod to be called 4 times" (Mock_MyDependency_2707ab91 Object (...), 4)
me\adamcameron\general\phpunit\expectsWithDataProviderIssue\MyDependency::someOtherMethod() was not expected to be called more than 4 times.

C:\src\php\general\src\phpunit\expectsWithDataProviderIssue\MyService.php:22
C:\src\php\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php:99

3) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest with data set "it expects myOtherMethod to be called 6 times" (Mock_MyDependency_2707ab91 Object (...), 6)
Expectation failed for method name is "someOtherMethod" when invoked 6 time(s).
Method was expected to be called 6 times, actually called 5 times.

4) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyOtherMethodCallsDependencyMethodEnoughTimesWithDependencyCreatedInTest with data set "it expects myOtherMethod to be called 7 times" (Mock_MyDependency_2707ab91 Object (...), 7)
Expectation failed for method name is "someOtherMethod" when invoked 7 time(s).
Method was expected to be called 7 times, actually called 5 times.

FAILURES!
Tests: 5, Assertions: 6, Failures: 4.
PS C:\src\php\general>

I started diving back through the PHPUnit code, and found the point where my two test variations began to demonstrate different behaviour. I edited InvocationHandler::verify to spit out some telemetry:

public function verify(): void
{
    printf(PHP_EOL . "InvocationHandler::verify called with %d matchers" . PHP_EOL, count($this->matchers));

    foreach ($this->matchers as $matcher) {
        $matcher->verify();
    }

And here's what I get running the two tests:

PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php --filter=testMyMethodViaDataProvider PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

. 1 / 1 (100%)
InvocationHandler::verify called with 0 matchers

Time: 60 ms, Memory: 4.00 MB

OK (1 test, 1 assertion)
PS C:\src\php\general> vendor\bin\phpunit .\test\phpunit\expectsWithDataProviderIssue\MyServiceTest.php --filter=testMyMethodViaInlineMock PHPUnit 8.5.0 by Sebastian Bergmann and contributors.

F 1 / 1 (100%)
InvocationHandler::verify called with 1 matchers

Time: 62 ms, Memory: 4.00 MB

There was 1 failure:

1) me\adamcameron\general\test\phpunit\expectsWithDataProviderIssue\MyServiceTest::testMyMethodViaInlineMock
Expectation failed for method name is "someMethod" when invoked 10 time(s).
Method was expected to be called 10 times, actually called 1 times.

FAILURES!
Tests: 1, Assertions: 2, Failures: 1.
PS C:\src\php\general>

Well. So when we run our tests using the mock created in the test code... we get our matcher "loaded" (for lack of a better term); when we run our test using the mock created in the data provider: it's nowhere to be seen. Interesting.

Looking further up the call stack, we find that this verify method is called from TestCase::verifyMockObects:

private function verifyMockObjects(): void
{
    foreach ($this->mockObjects as $mockObject) {
        if ($mockObject->__phpunit_hasMatchers()) {
            $this->numAssertions++;
        }

        $mockObject->__phpunit_verify(
            $this->shouldInvocationMockerBeReset($mockObject)
        );
    }

(I dunno what's going on with the method name there, but I did verify the call stack... PHPUnit is doing some special magic there).

verifyMockObjects in turn is called from runBare in the same class, and that is run from TestResult::run.

The key thing here is verifyMockObjects being run in the context of the TestCase object, and it looks at $this->mockObjects. Where does $this->mockObjects come from? When we create the mock:

public function getMock(): MockObject
{
    $object = $this->generator->getMock(
        $this->type,
        !$this->emptyMethodsArray ? $this->methods : null,
        $this->constructorArgs,
        $this->mockClassName,
        $this->originalConstructor,
        $this->originalClone,
        $this->autoload,
        $this->cloneArguments,
        $this->callOriginalMethods,
        $this->proxyTarget,
        $this->allowMockingUnknownTypes,
        $this->returnValueGeneration
    );

    $this->testCase->registerMockObject($object);

    return $object;
}

// ...

public function registerMockObject(MockObject $mockObject): void
{
    $this->mockObjects[] = $mockObject;
}

(remember that our createMock call is just a wrapper for a getMockBuilder()...->getMock() call).

So what's the bottom line here? Well my initial wariness about creating the mock in the data provider method has legs... when a mock is created it's registered in the TestCase object it's created within... and the one that the data provider method is running in is not the same TestCase as the one the test is run in. So... none of the mock's constraints are checked when the test is run. That's mostly it.

But what's the story with how that last test still failed on the variants with only 3/5 and 4/5 calls made? That check is done when the mocked method is actually called. So given this:

function myMethod() {
    return $this->dependency->someMethod();
}

When the mocked someMethod is called, a check is made then as to whether it's been called too many times for the expectation. So that's one within the mock itself at the time it's executed, hence it still "works". It's just the check that the exact number of call times was hit that is done at test level, not mock level if that makes sense.

This all just goes to show that one should just use data provider methods for providing data values for test variations, not to treat them like some sort of looping mechanism that the test is just a callback for. That's not the intent, and when one tries to be tricky... one is quickly found out to not be as clever as one hopes... ;-)

That's an awful lot of carry on for what ended up to be an easy / simple explanation. I'm mostly writing this up in case anyone else gets the same issue, and also to show how I went about troubleshooting and investigating it. I'll be putting this in front of my team shortly...

Righto.

--
Adam

Adam Cameron's Dev Blog

Friday 20 December 2019

PHPUnit: trying to be clever with data providers and failing