This article was originally published by Justin Weiss on his personal site, and with his permission, we are sharing it here for Codeship readers.
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.