One thing about writing about Rails for as long as I have is, sometimes I search online to see how to do something, and a post I wrote about it shows up in the first few results! Yet another reason to blog what you learn–you might forget it someday.
Testing log messages is one of those things I don’t do on a regular basis, and always have to root around to find the answer. Which codebase was it again? Which test? And on top of that, there are two (that I know of) ways to do this!
In this article, I’d like to share two approaches to this, along with a little exploration on how the two solutions differ. For the sake of simplicity, I’ll use an RSpec system spec–though in reality, I seldom test log messages unless there’s no other interface to test. In practice, this may be more useful for testing code used in a background job, for example, than in a web interface or API response.
Let’s say I’ve got a controller that, among other things, outputs to the Rails application log:
Naively, let’s just add a line indicating that the application logger
receive the intended log message,
and see what happens.
Hmm, that doesn’t work. The test fails with:
We need to stub out the Rails logger’s
info method, using RSpec’s
allow method. This lets us then use
expect to watch for specific
messages being passed to
Wait, that still doesn’t work:
I’ll admit it, this behavior stumped me for a long time. I stumbled upon a solution one day, while still relatively new to RSpec and desperately trying anything. Totally by accident, I put the expectation before triggering the case under test:
Wait, why does that work? It’s by design, as shown in the passing examples in RSpec’s documentation on expecting messages. From an English grammar standpoint, this makes sense: You expect something before it happens, not after. But it runs counter to the Arrange, Act, Assert pattern by expecting the specific log message before actually performing an action to test. (You may also know this pattern as Given, When, Then.) In a complex test, this nuance might be easy to miss.
We’re writing Ruby, though, and in Ruby, we like to have more than one
way to do things. Let’s test the same behavior using a spy. A spy
tests the same behavior, but with a slightly different syntax that lets
expect, or assert, after acting.
Here’s what it’d look like:
This passes just fine, and follows the Assemble, Act, Assert the pattern. It lets us arrange the example in such a way that assembly, action, and assertion are distinct steps within the test.
Like I said already, this is Ruby, so we can have more than one right way.
Consider the first approach when the test is closer to a traditional isolated unit test:
Consider a spy when the scenario is more complex:
I typically prefer using a spy for both cases, since my brain thinks in Given, When, Then, anyway. But you may prefer something else, and that’s totally cool. Just be aware that you may see either approach (or both!) when reading source code someday.
If you liked my series on practical advice for adding reliable tests to your Rails apps, check out the expanded ebook version. Lots of additional, exclusive content and a complete sample Rails application.
Ruby on Rails news and tips, and other ideas and surprises from Aaron at Everyday Rails. Delivered to your inbox on no particular set schedule.