Learn how to make your Rails logs smarter with log_tags!

When you look at the logs of your application in development, they may appear clear and concise to you (probably not thou), but when you are looking at the production logs and there are many simultaneous requests, sometimes it is difficult to know exactly what like of the log is the next entry, or what are the logs related to a specific user.

Many times I have to answer questions like: ‘What user deleted that record’?

Or sometimes I just need to follow through a log file and try to make sense of it using the thread id, what is possible but not really pretty, so I started researching how to improve the logging of my rails applications, and found out that you can configure the “log_tags” property and add information to the logs, it is really easy as you can see in the sample bellow from the application.rb file:

config.log_tags = [
  :subdomain,
  :request_id
]

You can pass to the log_tags array the name of any method to be called on the “request” object, a Proc that will receive a “request” object, or anything that responds to a “to_s” call.

This is useful and helped me a lot debugging my multi-tenant applications (now at least I know which entry is for what sub domain).

But I still had a problem, I wanted to add “current_user” information to the logging, it would help me answer some common questions without creating a lot of useless objects in the database.

And after lots of research I found out that it is impossible to use the log_tags to add user information to the logs.

But I never loose hope, so one day I thought: “Why don’t I use an around_action in the ApplicationController?”

And that was the last part of my puzzle, with a really simple code, now I have request_id, subdomain and the user full name in my logs, the code is pretty simple as you can see:

  around_action :user_tagged_logging
 
 
  def user_tagged_logging
    logger.tagged(current_user.try(:full_name) || 'Anonymous') do
      yield
    end
  end

With these, my test logs are a lot more richer, even without the “subdomain” since that does not exists while running tests, for example, this is a small bit of my cucumber test log:

[472ca484-6712-4421-93eb-4d8429a96062] [Anonymous]   SQL (0.6ms)  INSERT INTO `sessions` (`user_id`, `active`, `created_at`, `updated_at`) VALUES (1, 1, '2018-07-20 20:34:33', '2018-07-20 20:34:33') [472ca484-6712-4421-93eb-4d8429a96062] [Anonymous]    (5.9ms)  COMMIT
[472ca484-6712-4421-93eb-4d8429a96062] [Anonymous] Redirected to http://127.0.0.1:55977/
[472ca484-6712-4421-93eb-4d8429a96062] Completed 302 Found in 506ms (ActiveRecord: 9.4ms)
[8df3a6da-1433-4070-8d24-32b0c2bd015f] Started GET "/" for 127.0.0.1 at 2018-07-20 20:34:33 +0000
[8df3a6da-1433-4070-8d24-32b0c2bd015f] Processing by StoryController#index as HTML
[8df3a6da-1433-4070-8d24-32b0c2bd015f]   Session Load (0.7ms)  SELECT  `sessions`.* FROM `sessions` WHERE `sessions`.`active` = 1 AND (updated_at > '2018-07-19 20:34:33.613141') AND `sessions`.`id` = 1 ORDER BY `sessions`.`id` ASC LIMIT 1
[8df3a6da-1433-4070-8d24-32b0c2bd015f]   User Load (1.4ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
[8df3a6da-1433-4070-8d24-32b0c2bd015f]   Role Load (0.7ms)  SELECT `roles`.* FROM `roles` INNER JOIN `role_users` ON `roles`.`id` = `role_users`.`role_id` WHERE `role_users`.`user_id` = 1
[8df3a6da-1433-4070-8d24-32b0c2bd015f] [Uru Writer]   Rendering story/index.html.erb within layouts/application
[8df3a6da-1433-4070-8d24-32b0c2bd015f] [Uru Writer]   Rendered story/index.html.erb within layouts/application (0.6ms)
[8df3a6da-1433-4070-8d24-32b0c2bd015f] Completed 200 OK in 416ms (Views: 387.5ms | ActiveRecord: 2.9ms | Solr: 0.0ms)

As you can see, the request_id and username are there, and of course, you can add anything that is more useful to your system, those are just sample information from a cucumber test 😛

And this is how I added the current user to the rails logs, when the app configuration didn’t worked (for a simple API reason, request does not have a session method…), I implemented a workaround in the application_controller.

Of course this could all be simpler if the rails “request” object had a pointer to the “session” instance like in the JavaEE world (yes, I’m also a Java programmer…)

So, did this quick tips helped you?

What other information you think would be helpful in the application logs?

Any questions about this implementation? leave a comment bellow!