Last updated at Tue, 31 Oct 2017 19:03:00 GMT
This article was written by Jack Kinsella, a Logentries customer based in Berlin. Jack owns Oxbridge Notes and co-founded Bolivian Express. Below Jack has shared an excerpt from his writings on A Comprehensive Guide to Debugging Rails.
Seasoned Rails pros will have interpreting logs down second nature, but I’ll outline the important realizations I had as a beginner for the sake of the version of me out there who is new to Rails development. Whenever you visit a page/fill a form/do an Ajax request in Rails, the server logs out a boatload of useful data. When should you refer to these logs? When you notice something you don’t expect to happen or see an error that you don’t know how to even start debugging. In these cases begin by systematically comparing what you see output in the logs with what you expect to see. Let’s look at the workflow for interpreting the Rails log.
Manage your log tab with Linux: Usually there is way too much information on your log screen. Start your debugging sessions by clearing the output in your terminal tab with Command+K. Alternatively, if the bug you want to identify has already occurred and for this reason you don’t want to clear the screen, then use the terminal’s Command+F feature to search all its contents (sometimes 1000s of screens worth of data) for something that identifies your bug. Finally I like to pipe log output into a grep command to filter the information I want. For example when debugging Rendered information I might access my logs with tail -f log/development.log | grep Rendered, thereby only displaying lines containing the string “Rendered”. Note that this configuration of tail and grep is a real-time filter, and will update the screen with any new Rendered lines added to the logs as you interact with your Rails application.
Tailed live Heroku logs: Heroku doesn’t store your logs, it being a read-only file system, but luckily you can view live requests as they hit our website with heroku logs -t. Pro-tip: leave this open in a terminal for some time (e.g. 20 minutes), then use the search function of your terminal app (Command + F) to search for the keywords which would indicate your bug. Unlike your development mode log, your production log is by default set to “info”, meaning that you won’t get information about caching or SQL commands run. When you want this additional information, increase the log level to debug with heroku config:add LOG_LEVEL=”debug”. (This assumes you have set up your production.rb environment file to respond to ENV[“LOG_LEVEL”]) As soon as you’ve finished debugging switch the log level back to the default with heroku config:add LOG_LEVEL=”info” otherwise our logs will fill up rapidly and become expensive to archive in the third party software we employ.
Archived logs: As mentioned above, our production server sits on Heroku, which, as a read-only filesystem, doesn’t save our web-app logs for future reference. Therefore we use Logentries, a cloud-based log management and analytics service to capture and store our logs. You can access the web-app interface for Logentries through the Heroku dashboard, and choose time-ranges within which to search by keyword for application errors, HTTP statuses, specific parameters, or logged information you manually output from your application.
Heroku Scheduler Logs: View all the processes that Heroku has currently running for your application with Heroku ps. While a scheduled task is running you’ll see a process named something like scheduler.X, with X representing an integer number, say 1 in this case. You can inspect the logs of this scheduled process with $ heroku logs –ps scheduler.1.
S3 Access Logs: Like many Heroku applications we store binary data on S3. Requests for this data sometimes completely skip our website, and this is done by intentionally as a performance optimization of our own design. This means we lose potential debugging information. To remedy this we have enabled the optional AWS S3 logging feature in the relevant Oxbridge Notes buckets (through the AWS S3 web console) and thereby created logs within a bucket oxbridgenotes-logging. Information about interpreting these logs is found in this article, and advice on using Ruby to read them in a usable manner is found here.
Alerts based on logs: Through our production log archiving software, Logentries, we can set alerts to be sent via email/Campfire/other services when the logs contain an entry matching a certain regular expression and optionally when that same entry matches a given number of times, e.g. once, ten times, one hundred times. This allows us to inform ourselves about errors that would not be reported by our Rails based exception notification, that is, errors that happen outside of the Rails application. In particular these are errors at the level of Heroku platform, such as request time-outs, failure of our Rails app to boot at all, or failures of supporting services such as Memcachier, which are provisioned through the Heroku platform.
