Debugging Rails application with Logs

In a production application, logs are the source of truth for how and when specific events occurred. What request did the web server receive? Who sent it? How did the application respond? How much time did it take?

Logs have all the information that one needs to be able to effectively debug a particular issue and realize what happened at that point in time. And especially so, if you are a puts debugger.

This makes it important that one should be able to filter logs by

  • a user
  • a session
  • a request
  • a remote IP

Rails Log File

Let’s take a sample rails application which has scaffolded blog with a name and description.

If you start the server in a production environment, and visit the same url /blogs/new , you should see this in the log

INFO -- Started GET "/blogs/new" for ::1 at 2016-03-01 13:14:12 +0530
INFO -- : Processing by BlogsController#new as HTML
INFO -- : Rendered blogs/_form.html.erb (5.0ms)
INFO -- : Rendered blogs/new.html.erb within layouts/application (6.4ms)
INFO -- : Completed 200 OK in 26ms (Views: 11.6ms | ActiveRecord: 0.5ms)
INFO -- : Started GET "/assets/application-0362f38a3e53ca0933d0b7eb565b6c3a173fa099d52f1f29d13abdfaee97abc9.js" for ::1 at 2016-03-04 13:14:12 +0530
INFO -- : Started GET "/assets/application-0723cb9a2dd5a514d954f70e0fe0b89f6f9f1ae3a375c182f43b5f2b57e9c869.css" for ::1 at 2016-03-04 13:14:12 +0530

In a log file, filled with such requests – how would you filter requests by a specific user, session and  request-id ?

Log filter by Request Id

production.rb file in your Rails application has this piece of code

# production.rb
# Prepend all log lines with the following tags.
config.log_tags = [:uuid]

ActionDispatch::Request#uuid method – makes it easy to trace requests from end-to-end in the stack and identify individual requests in logs. On enabling this tag, the log file will look as

INFO -- : [da6a6790-8eeb-4db3-bb15-0fd168c09776] Started GET "/blogs/new" for ::1 at 2016-03-09 13:40:10 +0530
INFO -- : [da6a6790-8eeb-4db3-bb15-0fd168c09776] Processing by BlogsController#new as HTML
INFO -- : [da6a6790-8eeb-4db3-bb15-0fd168c09776] Rendered blogs/_form.html.erb (13.5ms)
INFO -- : [da6a6790-8eeb-4db3-bb15-0fd168c09776] Rendered blogs/new.html.erb within layouts/application (16.4ms)
INFO -- : [da6a6790-8eeb-4db3-bb15-0fd168c09776] Completed 200 OK in 41ms (Views: 25.6ms | ActiveRecord: 0.5ms)
INFO -- : [11c236e7-9faf-4f38-a129-ed79ebd4ae93] Started GET "/assets/application-0362f38a3e53ca0933d0b7eb565b6c3a173fa099d52f1f29d13abdfaee97abc9.js" for ::1 at 2016-03-09 13:40:10 +0530
INFO -- : [bf5adff0-e5a0-4f2f-a25f-22dec7e30c49] Started GET "/assets/application-0723cb9a2dd5a514d954f70e0fe0b89f6f9f1ae3a375c182f43b5f2b57e9c869.css" for ::1 at 2016-03-09 13:40:11 +0530

This shows that the Request for /blogs/new with specific da6a6790-8eeb-4db3-bb15-0fd168c09776, completed and then parallely assets were requested. Note: These were independent requests by the browser for assets.

Log filter by Session Id

Session Id, can be accessed through the cookie jar as req.cookie_jar["_session_id"]}"[0..20]

Since, log_tags can take lambda as an argument, we can write this as

# production.rb
config.log_tags = [:uuid, lambda {|req| "#{req.cookie_jar["_session_id"]}"[0..20]}]

Remember to replace _session_id by the value in your config/initializers/session_store.rb key. The log will look like this now,

INFO -- : [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [TzY5YTBJUHpkOHRsMjBrQ] Started GET "/blogs/new" for 127.0.0.1 at 2016-03-09 13:52:47 +0530
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [TzY5YTBJUHpkOHRsMjBrQ] Processing by BlogsController#new as HTML
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [TzY5YTBJUHpkOHRsMjBrQ] Rendered blogs/_form.html.erb (5.3ms)
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [TzY5YTBJUHpkOHRsMjBrQ] Rendered blogs/new.html.erb within layouts/application (6.8ms)
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [TzY5YTBJUHpkOHRsMjBrQ] Completed 200 OK in 30ms (Views: 13.6ms | ActiveRecord: 0.5ms)

Log filter by Remote IP

Simply adding the tag :remote_ip does the trick

# production.rb
config.log_tags = [:uuid, :remote_ip, lambda {|req| "#{req.cookie_jar["_session_id"]}"[0..20]}]
INFO -- : [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [127.0.0.1] [TzY5YTBJUHpkOHRsMjBrQ] Started GET "/blogs/new" for 127.0.0.1 at 2016-03-09 13:52:47 +0530
..[1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [127.0.0.1] [TzY5YTBJUHpkOHRsMjBrQ] Processing by BlogsController#new as HTML
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [127.0.0.1] [TzY5YTBJUHpkOHRsMjBrQ] Rendered blogs/_form.html.erb (5.3ms)
.. [1ad1390c-b0f0-48f1-a1e2-303bc01a5c66] [127.0.0.1] [TzY5YTBJUHpkOHRsMjBrQ] Rendered blogs/new.html.erb within layouts/application (6.8ms)
..

Log filter by User Id

config.log_tags = [
:uuid, ->(req){
    session_data = req.cookie_jar.signed[ "_session_id" ]
    warden_data = session_data["warden.user.provider_user.key"]
    if warden_data
      '#' + warden_data[1][0].to_s
    else
      "Anonymous"
    end
  }
]
# When using Devise

What all can I log?

When figuring out what can you log, it’s important to look at the request object and see what it carries. It can be easily done as

config.log_tags = [
  lambda { |req|
    req.inspect
  }
]

This should dump the entire action dispatch request details along with the @env. Now, you can look through it and figure out, what needs to be show in logs.

Building Rails API

Rails API was recently merged into Rails via PR #19832. This means, all features of rails-api will be bundled with the next Rails 5 release.

The advantage of a API only Rails project, has always been

1. being able to use a subset of Rails features, for building API’s and

2. a trimmed middleware stack

Now that, Rails API has been merged into Rails, how can we achieve these same benefits?

Let’s try it out by building a Rails API only application. Rails API with Rails is on master right now and not released. So,

Continue reading

Rails : Render templates outside controllers

Wanted to render templates outside controllers in a rake task or in a job ? You could do that.. but had problems with the asset pipeline ?

Before Rails 5, you had a couple of approaches you could depend upon based on the usage of ActionController::Base render and AbstractController::Base.

Let’s take an example and try this out

# books_controller.rb

class BooksController < ApplicationController
   def show
     @book = Book.find(params[:id])
   end
end

and a corresponding view

# books/show.html.erb

<p id="notice"><%= notice %></p>
<p>
 <strong>Name:</strong>
 <%= @book.name %>
</p>
<p>
 <strong>Description:</strong>
 <%= @book.description %>
</p>
<%= link_to 'Edit', edit_book_path(@book) %> |
<%= link_to 'Back', books_path %>

A rake task that attempts to use this template  Continue reading

What’s new in RAILS 5 ?

Rails 5 was announced by dhh, this April at RailsConf 2015 in Atlanta.

Well, what’s special about Rails 5?

The Rails Core Team has always made major releases happen on an every two years basis. So it fits in well, to release Rails 5 in December 2015.

To some it might feel like a point release in the 4.x line in terms of features / upgrades, but the fact that Rails 5 drops support for MRI < 2.2.1, is itself a major change. Alongwith some backwards incompatible changes like halting callback chains.

New in Rails 5?

Continue reading