By Aaron Sumner,
August 10, 2020.
File under: rspec.
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
(Rails.logger) should expect to 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 info:
Wait, that still doesn’t work:
Option 1: Expect, then act
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.
Option 2: Spy on the log
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
us 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.
Which way is the right way?
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:
The code being exercised lacks a lot of external dependencies
(including Rails)
The test can be structured so that all assertions are kept
together–or better yet, the log assertion is the only thing being
checked
Consider a spy when the scenario is more complex:
The code relies heavily on Rails, Active Record, or anything else
that’s not easily abstracted away
The test asserts outcomes in addition to the log message
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.
What do you think?
Follow along on on
Mastodon,
Facebook, or
Bluesky
to let me know
what you think and catch my latest posts. Better yet,
subscribe to my newsletter for
updates from Everyday Rails, book picks, and other thoughts and ideas that
didn't quite fit here.
Test with confidence!
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.