A Testing Tale of Woe and Confusion

image source: http://www.quotemaster.org/definition+of+insanity#&gid=1&pid=25

I have an application that I wrote in Laravel 5.1 a couple of years ago. It has a suite of tests at the unit and integrated level, and full Selenium based testing courtesy of the now defunct Laracasts\Integrated package that was an early precursor to much of the testing tools that are now part of Laravel 5.4.

This article is not about the details of the various testing packages and the constantly evolving world of test support in Laravel (as fascinating as that might be to look at). Instead it’s about trying to diagnose a test failure, and the various wrong turns I had to take before I got to root cause.

The test I had in place was fairly simple. I create a user and a couple of records (reviews) for that user. Then using the browser, I view a list of those records. There’s a link for each item that will mark the review as “reviewed”. The JavaScript UI throws up a confirm box when the link is clicked, and I test that if the confirm box is dismissed, no change is made to the record. And then if the confirm dialogue is confirmed, I check that the record is updated in the backend accordingly.

The meat of the test looks like this:

protected function doReviewLinkTest($test_review)
{
    $this->clickCss('#review-' . $test_review->id)
        ->seeInAlert($test_review->dataset_id, false)
        ->dismissAlert();
    $test_review = $test_review->fresh();
    $this->assertFalse($test_review->reviewed, 'Record should not be marked as reviewed when confirmation dismissed.');
    $this->clickCss('#review-' . $test_review->id)
        ->seeInAlert($test_review->dataset_id, true)
        ->wait(1000);
    $test_review = $test_review->fresh();
    $this->assertTrue($test_review->reviewed, 'Reviewed should be true when user confirms action.');
}

I was going back to the project after some time away from it, and ran the tests to make sure that everything was in a good state, and that’s when the wheels fell off my evening.

Selenium Checks

Selenium was no longer playing nicely with my version of Firefox. Which was fairly obvious as Firefox started and then failed to browse to my test website entirely. I tried updating to Selenium 3.4.0, but that seemed to be causing trouble with a couple of different interactions I had in place. I suspect Webdriver would need to be updated, but this was a rabbit hole I didn’t want to go down.

So in the end I reverted back to 2.5.1, and downgraded Firefox (I only really have Firefox installed for automated testing, so I was not too concerned about going back a few releases). And with the se/selenium-server-standalone package in composer, it was at least straight forward to switch Selenium around.

Test Failures

Finally I was able to run my frontend tests, revealing the failure of my Review tests. This functionality has been live for some time, so either no one was using it, or my tests were failing for a different reason. And here lies one of the important lessons from this evening.

Pay attention when you’re knackered and remember to take a step back when issues arise.

One of the quirks about my setup for running my front end tests is that I use php artisan serve —-env=testing to provide the testing webserver. I talked about this approach in an earlier post, but basically this allows me to use a separate sqlite database for running these tests, and doesn’t interfere with my development environment.

So I worked through the test manually on my development server, where everything worked as expected. There was clearly something wrong with my test, or with my test environment. But I couldn’t immediately think of any obvious difference between the two, so in a nod to Einstein, I ran the tests a few more times.

I examined the Selenium logs (which can make you go fairly cross-eyed at the best of times), but there was nothing awry that I could see. And the tests were still failing.

Front End Debugging

I started throwing in debug into the javascript code to see if I could pick things out that way, and soon discovered I was getting a Forbidden error from the Ajax request to mark the review as reviewed. Rather than trying to track the root cause of this in the backend code though, I got suspicious of how the request was being made:

$.ajax({
    'type': 'PUT',
    'url': path,
    'headers' : {
        'X-XSRF-TOKEN': $.cookie('XSRF-TOKEN')
    },

As I was using the PHP webserver, I wondered whether it supported the PUT request, or perhaps there was an issue with it accepting the X-XSRF-TOKEN header? I did a bit of googling, and it was inconclusive, but there were posts around of people complaining of issues around Ajax requests for the non-vanilla request types. So I followed the Laravel docs for how to spoof the request:

$.ajax({
    'type': 'POST',
    'url': path,
    'headers' : {
        'X-XSRF-TOKEN': $.cookie('XSRF-TOKEN')
    },
    'data' : { '_method': 'PUT'},

This didn’t help, so then I updated the data attributes on the link to include the csrf token, and did a further update:

token = $(this).data('token');
$.ajax({
    'type': 'POST',
    'url': path,
    'headers' : {
        'X-XSRF-TOKEN': $.cookie('XSRF-TOKEN')
    },
    'data' : { '_method': 'PUT', '_token': token},

But my requests were still Forbidden.

I was pretty much at the end of my tether at this point. For some reason the artisan webserver was logging all the raw resource requests for JavaScript files and images, but not the actual page requests. This was confusing as it meant I could never see the 403 response the Ajax request was claiming to receive (and I think one of the contributing factors in my wild goose chase of fiddling around with the request structure).

It’s possible that at this point I ignored Einstein a few more times, but unsurprisingly the tests continued to fail.

Backend Debug — where I should’ve started

So then I finally did what I should have done at the beginning, and dumped some logging into my application code to determine whether the controller was being reached, and if so where it was failing. And this was where I finally found the cause:

if ($review->user_id !== Auth::user()->id) {
    abort(403, 'You are not authorised for this action.');
}

As you can see, I am being a diligent coder here, and doing a type safe equality check between the review user id and the logged in user id. On my vagrant development server, and in production this has been working absolutely fine. However on my local machine this is not the case. For some reason the Auth::user()->id is a string, whilst the $review->user_id is an int. I found a github issue ascribing the problem to PHP versions. But it seems odd for this to be coming up when running recent versions of PHP 5.6 locally and on the dev server (5.6.27 and 5.6.11 respectively).

Initially, I thought I would just put the casting of the variables to int in the comparison, but that felt rather an odd place for it. But Laravel provides the ability to define exactly what datatype any given model attribute should be through the casts property. Digging through the code, I thought there was a good chance this would carry through to the user returned by Auth, so I added the following to my User model:

protected $casts = [
    'id' => 'int'
];

And voila, I suddenly had a passing test. Clearly I should have been checking my backend code a lot sooner, but hindsight is a wonderful thing. It did give me an opportunity to have a good dig around and get familiar with some old code, and I learnt a couple of handy tidbits along the way. So it wasn’t a complete waste of my evening!

Now I just need to clean up the logging mess I made in my code, run all my other tests to make sure that this small change doesn’t break anything else, and then I can finally make the change I intended to make at the beginning of my evening.

Maybe not right now though …