Debugging Tests: A look into assertCommandCalled

Have you ever written a test case, expecting it will pass, only to find out it doesn’t? Today, we’ll create a test for a Laravel Zero console command, and use its assertCommandCalled helper to assert one command calls another.

We’ll then see how easy it is to fall into the pits of despair trying to make an assertion pass, and how thankfully, we can follow a set of steps to get out of it.

The Scenario

Let’s say, we have a Laravel Zero application and it has a scan command. This command checks whether a “config_file” file exists in the base directory, and triggers another command to parse the file if so:

/* app/Commands/ScanCommand.php */

protected $signature = 'scan';

public function handle(): void
{
  if( file_exists('config_file') ){
    $this->call( ParseConfigCommand::class );
  }
}

The command triggered by the scan command has a signature of parse-config, and has the class name ParseConfigCommand. This command will simply provide a command line output indicating it has started, and parse the “config_file” found in the base directory:

/* app/Commands/ParseConfigCommand.php */
protected $signature = 'parse-config';

public function handle(): void
{
  $this->line( 'Starting parse of config_file' );
  $this->parse();
}

Creating the Test

The feature we’ll test out today is whether running the scan command ( given the right conditions ) triggers the parse-config command.

Laravel Zero provides us the helper, assertCommandCalled() in order to assert that a specific command was called. This is perfect for the feature we’re expecting to test. To start, first create a feature test in test/Feature/ScanCommandTest.php:

/* test/Feature/ScanCommandTest.php */ 
test( 'Scanner calls parse-config command when config_file is found in base directory.', function(){

    // 1. Arrange: prepare config_file in base directory
    file_put_contents( 'config_file', 'data' );

    // 2. Action: run intended command
    $this->artisan( 'scan' );

    // 3. Assert: parse-config was also called
    $this->assertCommandCalled( 'parse-config' );

    // 4. CleanUp
    unlink( 'config_file' );

});

There’s a bunch of things happening above, so let’s break it down:

Laravel Zero ships with Pest. And if we check the first line, we’ll see two parameters passed to Pest’s helper function test(). test receives a String description of what is being tested, and a closure containing the actual test expectations.

On to the actual test, notice 4 comments separating our test into 4 important sections:

1. The first section is Arrangement—this is where necessary preparations are made so that the action we run afterwards exhibit our intended behavior. In our case, we create a “config_file” file in our base directory so that when we run the scan command below, it triggers the parse-config command.

2. The second section is running the Action we want to test. This is calling the necessary methods, or in our case, triggering the artisan() method to mock-run a console command with the scan signature.

3. The third section is Asserting our expectation. In our case, we assert that running the scan command (given our preparation) should call the parse-config command.

4. The final section is clean up. This is the part where we remove any unnecessary, persisted files created thanks to our test, like the “config_file” created from section 1.

Now that we have the different parts of our test covered, let’s move on to running the test.

Running the Test

Thanks to the Arrangement section of our test, the proper file should’ve been created in the base directory before the scan command runs. Because of this, we should expect the scan command to pass its first “if condition”, and therefore call the parse-config command.

So, let’s run the test above with ./vendor/bin/pest, and check the result:

—it failed!

Debugging a Failed Assertion

Why did our assertion fail? If we look at the error message, it says: "Failed asserting that 'parse-config' was called...". Strange. The scan command clearly calls the parse-config command given the proper condition. How do we get to the bottom of this?

First, let’s test the action’s behavior manually. Prepare a “config_file” in the base directory, and run the scan command. Afterwards, check the command line output:

Starting parse of config_file

parse-config‘s line output was printed! This means it is indeed being called by the scan command.

Now, let’s see if it also gets called in a test environment. To do so, we’ll rely on a log entry to record and indicate it’s been called:

/*  app/Commands/ParseConfigCommand.php  */
+   Log::info( 'Running parse-config command!' );
    $this->parse();

Now if we run our test again with vendor/bin/pest and check our log file:

[2023-07-03 12:13:27] development.INFO: Running parse-config command! 

We’ll have our confirmation that parse-config is getting called, even in test!

Neat! We’ve now verified that our action works both manually and in a test environment. This let’s us know that we don’t need to change anything in the code we’re testing.

Even with this confirmation, our assertion still fails however. Now that we’re done with inspecting what’s being tested, let’s move over and inspect how it is being tested.

Making assertCommandCalled() pass

This is how we assert that our parse-config command is called:

/* test/Feature/ScanCommandTest.php */
$this->assertCommandCalled( 'parse-config' );

And this is a longer version of our error message from the failed assertion above:

Failed asserting that 'parse-config' was called with the given arguments: ... at `vendor/laravel-zero/framework/src/Testing/TestCase.php:57`

If we open the file indicated in the error, at around line 57, we’ll find Laravel Zero’s beautiful declaration of the assertCommandCalled() method:

/* vendor/laravel-zero/framework/src/Testing/TestCase.php */

protected function assertCommandCalled(string $command, array $arguments = []): void
{
  $argumentsAsString = (new ArgumentFormatter)->format($arguments);
  $recorder = app(CommandRecorderRepository::class);

  static::assertTrue(
    $recorder->exists($command, $arguments),
    'Failed asserting that \''.$command.'\' was called with the given arguments: '. $argumentsAsString
  );
}

From our test’s perspective, we give assertCommandCalled() a $command argument of “parse-config”. The method would then feed this value to its $recorder object’s exists() method to see whether the command exists or not.

The $recorder object is an instance of the CommandRecorderRepository class. And if we check what this class is all about, we’ll see that it holds a record of all the commands called in its private property $storage!

This is neat! We finally have a good lead on what’s happening: we can check the commands triggered through the $recorder attribute, and once and for all get to the bottom of our debug journey.

Go ahead, add a quick dd( $recorder ); before the assertion line, and we’ll see:

^ LaravelZero\Framework\Providers\CommandRecorder\CommandRecorderRepository^ {#908
  -storage: Illuminate\Support\Collection^ {#971
    #items: array:2 [
      0 => array:3 [
        "command" => "scan"
        "arguments" => []
        "mode" => "default"
      ]
      1 => array:3 [
        "command" => "App\Commands\ParseConfigCommand"
        "arguments" => []
        "mode" => "default"
      ]
    ]
    #escapeWhenCastingToString: false
  }
}

See? Indeed the parse-config command is getting called. But, the recorded value is the class name, instead of its signature!

If we go back to the declaration of our scan command’s handle method, we do pass a class instance, instead of its signature. Let’s go back to our test case, and add our fix:

/* test/Feature/ScanCommandTest.php */

$this->assertCommandCalled( 'App\Commands\ParseConfigCommand' );

This should now give us a well deserve pass:

PASS  Tests\Feature\ScanCommandTest
✓ Scanner calls parse-config command when config_file is found in base directory.               0.04s  

Tests:    1 passed (1 assertions)
Duration: 0.07s

Debugging Tests

A lot has happened above! Here’s a summary of the steps we took in debugging our failed assertion:

1. First, we made arrangements and run our actions manually. Doing so let’s us see first-hand whether the behavior we intend to see actually happens.
2. Since the behavior occurs manually, we verify it on our test environment. We re-run the test we created, but rely on a log entry that would indicate to us whether our intended behavior actually occurred behind the scenes.
3. After double checking our behavior works manually and in the test environment, next up we focus on trying to see how exactly the assertion is being done by checking the method that’s involved with the assertion.
4. With the assertion method available for inspection, we finally data dumped what values the assertion method was actually receiving.
5. Finally, thanks to seeing the values, we were able to verify what argument to pass to the assertCommandCalled() method for it to pass our intended assertion.

There’s no sure fire way to debug tests. But, it’s helpful to have a checklist to verify if it’s the code being tested ( steps 1-2 ) or the test itself ( steps 3-5 ) that needs to be adjusted, in order for our test to finally pass.