Keeping Your Logs From Becoming an Unreadable Mess

When you run into a strange, seemingly unsolvable bug, improving your logging can be the best step you can take. Great logging is the easiest way to detect and fix entire classes of bugs. When you log enough information, you can see how your data changes during a request. You can track the calls you make to other services, and investigate the response. In fact, when debuggers failed, logging helped me fix the toughest bug I’ve ever run into.

But log too much, and your log files will quickly turn into a jumble of unreadable, unhelpful messages. How can you slice just the information you care about out of that pile of data? Can you print messages in a way that’s easy to filter later?

Marking your log messages

Rails includes TaggedLogging, which can help you quickly categorize related log messages. When you tag a logger, you’ll get a marker at the beginning of your message. So instead of:

Finding people...
  Person Load (0.3ms)  SELECT "people".* FROM "people"
Found 0 people!

You could tag the Rails logger:

logger.tagged("People") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

And you’d see something like this:

[People] Finding people...
[People]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[People] Found 0 people!

Now, log messages that care about different things can look different.

Some tagged logger examples

As you log more often, and log more complicated things, you’ll naturally notice areas where those tags will make your messages clearer. But there are a few places I’ve found tagged logging particularly helpful. I’ll usually tag those right away.

You can log requests you make to other APIs:

logger.tagged("GitHub API") do
  uri = URI("https://api.github.com/repos/rails/rails/tags")

  logger.info { "Fetching #{uri}" }
  tags = JSON.parse(Net::HTTP.get(uri))
  logger.info { "First tag: #{tags.first["name"]}" }
end

[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags
[GitHub API] First tag: v4.2.4.rc1

That way, you can easily see how and when your app is talking to that API.

(This works particularly well with Faraday middleware, or if you only communicate with a server through a Gateway).

Background jobs also work well with tagged logging:

require "active_support/tagged_logging"

Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger)

module LoggedJob
  def around_perform_log_job(*args)
    logger.tagged(name) do
      logger.info { "Performing #{name} with #{args.inspect}" }
      yield
    end
  end
end

class MyJob
  extend LoggedJob

  def self.perform(*args)
    ...
  end
end

Now, any job that extends LoggedJob will have all of its log messages tagged with the class name of the job.

And if you have a logged-in user, you could tag messages with their user ID:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

[user-123] Finding people...
[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[user-123] Found 0 people!

Finally, if you add a line to your config/environments/production.rb (or development.rb), you can have Rails automatically tag your messages:

config.log_tags = [ :subdomain, :uuid ]

log_tags lists the tags you want to appear at the beginning of every Rails log entry. Each symbol refers to a method on ActionDispatch::Request, so :uuid means request.uuid.

You can also pass a Proc that takes a request object:

config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]

But I don’t see that very often.

These default tags are nice: uuid can tie together all the log entries that happen in one request, and if you’re keeping sessions on the server, the session ID is also helpful. With those tags, and enough messages, you can trace some really complicated paths through your app. And usually, that’s what it takes to figure out how a nasty bug happened.

How much do you use the Rails logger in your apps? Have you tried tagged logging? If you haven’t, try finding a place for it. Tagging actions taken by your users is a good start. It’ll help you out the next time you have to debug a crazy multi-step bug.

If you want to learn more about logging and other debugging techniques, I’ve dedicated an entire chapter of Practicing Rails to finding and fixing the errors you’ll run into as you create your apps. Grab the first chapter for free here.