Are you Spying on me? A quick overview of Spies in RSpec

When executing code, you expect things to happen. You expect objects to receive messages. You also expect objects to receive one, or more, messages a certain number of times (in most cases).

Lately, I’ve been writing more and more code that logs and/or warns stuff in certain conditions. In the project I’m currently working on, it is fundamental that we log information because it contains several large and small components, interconnected with each other. These logs allows us to quickly figure out not only what’s wrong, but also where in the code the bug occurred, as well as the state of the application at that point.

Because of this, it is important for my team to test that our logger infrastructure is functioning as it should, warning and informing stuff that we deem critical.

This raises the question: how do you test that your logger has received n messages while executing code in specific execution environments?

Generally, in RSpec (which is the test framework we use), message expectations on doubles (doubles are objects “faking” the real implementation of your classes) are tested before you invoke your code under test. In this case, if you want to test a logger, it would be much more useful to test that the logger has receivedsome message(s) by the end of your tests.

Let me demonstrate this with a bit of code. Let’s say that you have the following class:

Now, if we want to test that the logger received the message Im doing stuff! , all you have to write in your spec is this:

If have trouble understanding why we’re using double('logger') , go ahead and read my blog post where I walk you through on how to make your classes easier to test!

Pretty simple right?

Ok, but what happens when we make the logger print yet another message, perhaps an error, in a specific condition?

With this code, we will log an additional error with the message thats too much times! if we call the method do_stuff with an argument greater than 10 .

If our test remains the same, no tests break. However, if we change the test to:

When we run our specs, this fails!

Failure/Error: logger.log_error “thats too much times!” if n_times > 10
 #<Double “logger”> received unexpected message :log_error with (“thats too much times!”)

Wait, this doesn’t make sense! Why would this test fail? We’re only testing that the class receive the info log, which it did, so why would this fail just because it received another message?

Well, this happens because message expectations on doubles fail when the double receives messages that we don’t explicitly expect it to have received.

This is not practical for what we want to achieve. This means that if we want to test that a logger received only a specific message while executing a piece of code, we would need to know all the previous messages that it could have received as well, before reaching that point in the code. Note that we had to put the expectation before invoking the tested code.

It would be nice if we could test a logger in a given-when-thenapproach, that is, given some exact scenario, I expect the logger to have receiveda specific message, without caring too much about any other messages that it may or may not have received.

This is where rspec spies help us! Spies are a special kind of double that allows you to create message expectations after the fact has happened. It provides a very useful method called have_receivedwhich is exactly what we need for this situation. Let’s make the previous test pass by replacing the double on the logger from a regular double to a spy double:

Note that now we place the expectations after invoking the tested code. The important thing here is that this test would pass even if the expectation on the error log was not explicitly present in the test.

We only say that we expect the error log to be there, and we don’t care that the info log message was received: that’s not what we want to test!

The method have_received accepts the usual message constraints as the other message expectations:

Note that the following expectation would fail (as expected)

Failure/Error: expect(logger_spy).to have_received(:log_error).with(/too much times/i).exactly(:twice)
 
 (Double “logger”).log_error(/too much times/i)
 expected: 2 times with arguments: (/too much times/i)
 received: 1 time with arguments: (/too much times/i)

1 example, 1 failure

So, remember: when writing unit tests, if you don’t care about which messages are received but only that a specific subset of messages were received, consider using a spy instead of a regular double!

That’s it! Let me know in the comments if you have more cool use cases for spies on rspec!

Nowadays I work at Runtime Revolution. Working here has been, and continues to be, a great learning experience. I’ve matured professionally as a developer, focusing on building and maintaining large scale Ruby on Rails applications.