This is just a quick PHPUnit one, inspired by a trick my team lead suggested to me. I think it's quite handy and works around what seems to be a shortcoming of how PHPUnit mocks stuff. I'm sure there's strong opinions held on this sort of thing somewhere as to how I'm not supposed to want to do what my requirement has me needing to do here. I do so look forward to being told about it.
Anyway, I'm writing a script to repair some bung data we have. The details are irrelevant, but it's fairly "important" data (well: not to me... but to someone, apparently...), and I want to make sure we can track when things go wrong. And they will go wrong. Firstly I'm talking to an external third-party service, and it's foolhardy to trust those; secondly I'm relying on some of our own internal services which... ah... well yeah they were written in a different era by people with an unusual understanding of how to write managable, testable, and reliable code. And in the course of doing this work I turned-up a coupla bugs and had to fix those, so I don't back our own code to be stable here. I don't mean that judgementally: all code bases have better and not so good code in them. Anyway...
The upshot of this is the script logs a bunch of stuff - said script will be run by a cron job - and part of my testing is to verify the right things gets logged at the right time. A lot of it is fairly perfunctory "belt and braces" sort of logging, say "Records 1000-1999 processed OK", and I don't really care about that; but there's other stuff where the script deals with unexpected circumstances and I want to make sure that's done right.
For the purposes of this test I am mocking out all the dependencies so the script doesn't actually do anything, but the mocks return "workable" mocked data sufficient to walk through the stages of the script. And the logger is one of these dependencies, and is also mocked.
The test I was stuck on was one where an unhandled exception was thrown, and the script basically shuts itself down; having first logged what went wrong.
Here's a very pared-back version of the script:
public function myMethod($times){
try {
$this->logger->logMessage("Starting off");
for ($i=1; $i <= $times; $i++) {
$this->logger->logMessage("Starting processing iteration $i");
$this->helper->doThing();
$this->logger->logMessage("Finished processing iteration $i");
}
$this->logger->logMessage("Finishing off");
}
catch (\Exception $e) {
$this->logger->logMessage(sprintf("Something went wrong: %s", $e->getMessage()));
throw $e;
}
finally {
$this->logger->logMessage("All done");
}
}
Here I've just got the one doThing dependency call in the loop, but it makes the point. And around that, and before and after the the loop I log a line to track progress. And I log a line if there's an unhandled exception. As I said the real script is somewhat more complex than this, but this is an adequate analogy.
I have another test which tests the ongoing logging of a successful run with 0, 1, >1 records, but this test is to make sure the script a) reports the exception; b) still shuts down OK.
PHPUnit's approach to checking a specific argument was passed to a particular mock call is to use the at matcher method when setting an expectation. My first pass at the test used this matcher:
function testMyMethodUsingAt()
{
$exceptionMessage = "EXPECT_THIS";
$this->expectException(\RuntimeException::class);
$this->expectExceptionMessage($exceptionMessage);
$testIterations = 6;
$errorAt = $testIterations / 2;
$this->helper
->expects($this->at($errorAt))
->method("doThing")
->willThrowException(new \RuntimeException($exceptionMessage));
$this->logger
->expects($this->at(7))
->method("logMessage")
->with("Starting processing iteration 4");
$this->logger
->expects($this->at(8))
->method("logMessage")
->with("Something went wrong: $exceptionMessage");
$this->logger
->expects($this->at(9))
->method("logMessage")
->with("All done");
$this->sut->myMethod($testIterations);
}
Here I worked out the the call history for info would be nine entries long, and the entries I wanted to confirm the exception-tracking logic was correct was the 7th, 8th and 9th ones.
But this is problematic for a number of ways:
- it's not immediately clear what hat I pulled 7th, 8th and 9th from;
- it's fragile because it relies on there being precisely seven earlier log entries for it to work. EG: if we were to add another log line into the method, that would break this test, which is rubbish;
- semantically it's incorrect, as it's not the 7th, 8th and 9th entries I'm interested in; it's the last three. It'd be better to code it accordingly so the code was more readable to maintainers, later on.
- Lastly the at approach to things in PHPUnit is just a bit crap because the index is based on the mock object, not the mock method, despite almost all use-cases I've had for this sort of thing have been wanting to check sequential calls to the mocked method, not just to any method in the mocked object. So I try to steer clear of at at the best of times.
I was stumped.
Then me boss said "just use a callback in the will expectation, and build the log yerself". Initially I just looked at him like he was a loony (he's used to this), but then it dawned on me what he was suggesting. And it was easy, and not altogether awful, either:
function testMyMethodUsingCallLog()
{
$exceptionMessage = "EXPECT_THIS";
$this->expectException(\RuntimeException::class);
$this->expectExceptionMessage($exceptionMessage);
$testIterations = 6;
$errorAt = $testIterations / 2;
$this->helper
->expects($this->at($errorAt))
->method("doThing")
->willThrowException(new \RuntimeException($exceptionMessage));
$callLog = [];
$this->logger
->method("logMessage")
->will($this->returnCallback(function ($message) use (&$callLog) {
$callLog[] = $message;
}));
try {
$this->sut->myMethod($testIterations);
}
catch (\Exception $e) {
$this->assertSame("All done", array_pop($callLog));
$this->assertSame("Something went wrong: $exceptionMessage", array_pop($callLog));
$this->assertNotSame("Finishing off", array_pop($callLog));
throw $e;
}
}
The first key bit is capturing the call-log. This creates an array, and with each call to the mocked logging method, we capture what was logged. Note that these expectations don't enforce any rules here. They just capture what's going on.
Because this method call throws an exception, I have to try/catch it so that I can regain control once it's errored, and inspect the call log to see it's what I expect. My approach here is far more semantic: I check the last entry is the "Finishing off" one, the one before that is logging the correct exception, and - this is slightly different now - as a failsafe I check that the one before that is anything other than "All Done". Because if it was that value, it'd mean the logic flow did not branch at the right stage of things. Lastly I throw the exception I caught so PHPUnit's own exception-expectation-checking also validates that too.
One of the best things about this is that this test doesn't care about what goes on in the log prior to the stuff it's testing, it is able to focus on precisely what it cares about. This is much clearer code. An example of this would be to change this line in each test:
$testIterations = 6;
Change it to be any other number, and the first test breaks, whereas the second test keeps working. Win.
That's pretty cool.
I hasten to add I would probably not usually be focusing quite this closely on this sort of sequencing, but in this case we need to know things are working properly.
It's a shame PHPUnit doesn't just expose the call-log like this, as I can't be the first person who's been in this situation. But I guess the tools are there to DIY like I have here, so no harm done.
Righto.
--
Adam
