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:
1 2 3
You could tag the Rails logger:
1 2 3 4 5
And you’d see something like this:
1 2 3
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:
1 2 3 4 5 6 7
That way, you can easily see how and when your app is talking to that API.
Background jobs also work well with tagged logging:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
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:
1 2 3 4 5
1 2 3
Finally, if you add a line to your
development.rb), you can have Rails automatically tag your messages:
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
You can also pass a Proc that takes a
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.