Capture Ruby Logger output for testing

Question

I have a ruby class like this:

require 'logger'
class T
  def do_something
    log = Logger.new(STDERR)
    log.info("Here is an info message")
  end
end

And a test script line this:

#!/usr/bin/env ruby

gem "minitest"
require 'minitest/autorun'

require_relative 't'

class TestMailProcessorClasses < Minitest::Test
  def test_it
    me = T.new

    out, err = capture_io do
      me.do_something
    end

    puts "Out is '#{out}'"
    puts "err is '#{err}'"
  end
end

When I run this test, both out and err are empty strings. I see the message printed on stderr (on the terminal). Is there a way to make Logger and capture_io to play nicely together?

I'm in a straight Ruby environment, not Ruby on Rails.

Answer 1

The magic is to use capture_subprocess_io

 out, err = capture_subprocess_io do
     do_stuff
 end

Answer 2

MiniTest's #capture_io temporarily switches $stdout and $stderr for StringIO objects to capture output written to $stdout or $stderr. But Logger has its own reference to the original standard error stream, which it will write to happily. I think you can consider this a bug or at least a limitation of MiniTest's #capture_io.

In your case, you're creating the Logger inside the block to #capture_io with the argument STDERR. STDERR still points to the original standard error stream, which is why it doesn't work as expected.

Changing STDERR to $stderr (which at that points does point to a StringIO object) works around this problem, but only if the Logger is actually created in the #capture_io block, since outside that block it points to the original standard error stream.

class T
  def do_something
    log = Logger.new($stderr)
    log.info("Here is an info message")
  end
end

Answer 3

Documentation of capture_subprocess_io

Basically Leonard's example fleshed out and commented with working code and pointing to the docs.

---

Captures $stdout and $stderr into strings, using Tempfile to ensure that subprocess IO is captured as well.

out, err = capture_subprocess_io do
  system "echo Some info"                 # echos to standard out
  system "echo You did a bad thing 1>&2"  # echos to standard error
end

assert_match %r%info%, out
assert_match %r%bad%, err

NOTE: This method is approximately 10x slower than #capture_io so only use it when you need to test the output of a subprocess.

See Documentation

Answer 4

This is an old question, but one way we do this is to mock out the logger with an expects. Something like

logger.expects(:info).with("Here is an info message")

This allows us to assert the code under test without changing how logger works out of the box.

As an example of capture_io, we have a logger implementation to allow us to pass in hashes and output them to json. When we test that implementation we use capture_io. This is possible because we initialize the logger implementation in our subject line with $stdout.

subject { CustomLogging.new(ActiveSupport::Logger.new($stdout)) }

in the test

it 'processes a string message' do
  msg = "stuff"
  out, err = capture_io do
    subject.info(msg)
  end
  out.must_equal "#{msg}\n"
end

Answer 5

You need to provide a different StringIO object while initializing Logger.new to capture the output, rather than the usual: STDERR which actually points to the console.

I modified the above two files a bit and made into a single file so that you can copy and test easily:

require 'logger'
require 'minitest'

class T
  def do_something(io = nil)
    io ||= STDERR
    log = Logger.new io
    log.info("Here is an info message")
  end
end

class TestT < Minitest::Test

  def test_something
    t = T.new
    string_io = StringIO.new
    t.do_something string_io
    puts "Out: #{string_io.string}"
  end

end

Minitest.autorun

Explanation:

1. Method do_something will function normally in all other code when used without the argument.
2. When a StringIO method is provided, it uses that instead of the typical STDERR thus enabling to capture output like into a file or in this case for testing.