CODEWITHSUNDEEP
ruby-on-railsloggingrspec
Brad Rice
Brad Rice

Reputation: 1344

RSpec test if a custom Rails log is written to

I'm trying to test a method that logs multiple messages based on conditionals to a log that is not the default Rails logger. I formatted the logger in config/environment.rb:

# Format the logger
class Logger
  def format_message(level, time, progname, msg)
    "#{time.to_s(:db)} #{level} -- #{msg}\n"
  end
end

and created a new logger in the ImportRecording class in the lib/ directory. A method of that class includes the following:

# some code omitted...
days.each do |day|
  if not hash[day].include? "copied"
    @log.error "#{day} needs to be copied!"
  end
  if not hash[day].include? "compressed"
    @log.error "#{day} needs to be compressed!"
  end
  if not hash[day].include? "imported"
    @log.debug "#{day} needs to be imported"
    `rake RAILS_ENV=#{Rails.env} recordings:import[#{day}]` unless Rails.env == "test"
  end
end
# finishing up logging omitted...

I wrote a tiny macro to help with testing this method:

def stub_todo
  { "20130220" => ["copied"],
    "20130219" => ["copied", "compressed"],
    "20130218" => ["copied", "compressed", "imported"] }
end

and here's my test:

describe ".execute_todo" do
  it "carries out the appropriate commands, based on the todo hash" do
    ImportRecording.execute_todo stub_todo
    ImportRecording.log.should_receive(:debug).with("20130219 needs to be imported")
    ImportRecording.log.should_receive(:error).with("20130220 needs to be compressed!")
    ImportRecording.log.should_receive(:debug).with("20130220 needs to be imported")
  end
end

I stare at the import log as I run these tests and watch the lines get added (there's a delay, because the log is large by now), but the tests still fail. I wonder if the formatting of the log is messing this up, but I am passing the aforementioned strings to the methods :debug and :error to the log. Any help?

EDIT 3/14/13:

In the hopes that someone may be able to help me out here, I changed by test to look as follows:

it "carries out the appropriate commands, based on the todo hash" do
  ImportRecording.stub!(:execute_todo).with(stub_todo).and_return(false)
  ImportRecording.log.should_receive(:debug).with("20130219 needs to be imported")
  ImportRecording.log.should_receive(:error).with("20130220 needs to be compressed!")
  ImportRecording.log.should_receive(:debug).with("20130220 needs to be imported")
end

and this is the error I'm getting from RSpec:

Failure/Error: ImportRecording.log.should_receive(:debug).with("20130219 needs to be imported")
  (#<Logger:0x007fb04fa83ed0>).debug("20130219 needs to be imported")
    expected: 1 time
    received: 0 times

Upvotes: 2

Views: 1993

Answers (2)

Brad Rice
Brad Rice

Reputation: 1344

I found the problem. Somehow, these expectations are supposed to be declared before the method that should actually cause them. The code should read

it "carries out the appropriate commands, based on the todo hash" do
  ImportRecording.log.should_receive(:debug).with("20130219 needs to be imported")
  ImportRecording.log.should_receive(:error).with("20130220 needs to be compressed!")
  ImportRecording.log.should_receive(:debug).with("20130220 needs to be imported")
  ImportRecording.execute_todo stub_todo
end

The tests now pass. I also had to add in more lines to the test to account for every line that was written to the log because of the method call. So for future researchers, state your expectations and then call the method.

Upvotes: 3

zetetic
zetetic

Reputation: 47548

I stare at the import log as I run these tests and watch the lines get added

If you set message expectations on the logger calls, you should not see the lines added to the log. Like stubs, message expectations replace the implementation of the original method. This suggests that your logger setup is mis-configured somehow.

Upvotes: 0

Related Questions