Just another 陰陽 site

Joachim’s blog: Debugging and Logging AJAX requests tests in Docksal


The hardest thing I find with tests is understanding errors. Every time I think I’ve got debugging output sorted, I find a new layer where it doesn’t work, I’ve got nothing, and I’m in the dark with something that’s crashing and I don’t know why.

The first layer is simple: errors in your test code itself. For example, make a typo in your tests/src/Functional/MyTest.php and PHPUnit crashes and you see the error in the terminal.

But when it’s site code that’s crashing, you’re dealing with a system that is being driven by code, and therefore, you can’t see it. And that’s a major obstacle to figuring out a problem.

The HTML output that Drupal’s Functional and Functional Javascript tests produce is a huge help: every time your test code makes a request to the test site, an HTML file is written to the test files directory. If your site crashes when your test makes a request, you’ll see the error and the backtrace there.

However, there’s no such output when in a Functional Javascript test you cause an AJAX request. And while you can create a screenshot of what the page looks like after the request, our another HTML file of the page (see for instructions how; the issue is about how to make that automatic but I have no idea how that might be possible), you can’t see the actual error, because AJAX requests that fail just sit there doing nothing. There’s nothing useful to see in the browser.

So we need to see logs. When a real site has an AJAX crash, with a human being-controlled web browser making the request, you can go and look in the logs. With a test site, the log table is zapped when the test is completed.

Fortunately, Drupal 8’s pluggable logging means there are other ways of getting hold of them, more permanent ways.

I first tried log_stdout module. This outputs log errors to STDOUT. If you’re running on Docksal, as I am, you have an extra layer to get though to see that. You can monitor the cli container with fin logs -f cli, and with that module add a | ag WATCHDOG to filter.

However, I wasn’t seeing backtrace in this output, and I gave up figuring out why.

So I tried filelog module instead, which as the name implies, writes log to a simple text file. This needs a little bit more work, as by default it writes to ‘public://logs’. This means that each run of the test gets its own log file, which is perhaps what you want, but for my own uses I wanted a single log file I could tail -f in a terminal window and have continual monitoring.

A quick bit of config setting in the test’s setUp() does the trick:

  ->set('location', '/var/www/docroot/sites/simpletest/logs')

And I think that’s me at last sorted.