activerecord sessionstore silent no more

#ActiveRecord::SessionStore::Session Silent No More
Brad Pauly — January 19, 2013

Have you ever wondered why SQL statements for sessions aren’t logged when you are using :active_recored_store? Me too. This morning, with a hot cup of coffe by my side, I decided to dig in and find out. It turns out to be straight forward and you can easily turn it off.

Take a look at activerecord/lib/active_record/session_store.rb in Rails and you’ll find the key methods: get_session, set_session, and destroy_session. Notice that the methods that make database calls are in a block within Base.silence. The silence method (found in ActiveSupport::Benchmarkable, which ActiveRecord::Base extends) temporarily changes the log level to ::Logger::ERROR so that the SQL is not logged and then changes it back to whatever it was previously.

If you’d like to see what’s going on in there, you can override this functionality in an initializer. Put the following code in config/initializers/unsilence_session_log.rb and restart your application.

module ActiveSupport
  module Benchmarkable
    def silence
      yield
    end
  end
end

Now you should see some extra info in your logs. Something like this:

Started GET "/" for 127.0.0.1 at 2013-01-19 13:28:11 -0800
  ActiveRecord::SessionStore::Session Load (0.3ms)  SELECT `sessions`.* FROM `sessions` WHERE `sessions`.`session_id` = 'fabc7c4db04d13d59a6966e0ab0ef37d' LIMIT 1
Processing by FooController#index as HTML
  Rendered foo/index.html.erb within layouts/application (0.3ms)
Completed 200 OK in 19ms (Views: 18.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  BEGIN
   (0.3ms)  UPDATE `sessions` SET `data` = 'BAh7CEkiEnJldHVybl90b191cmwGOgZFRkkiIWh0dHA6Ly9sb2NhbGhvc3Q6\nM
 ...
 Qx\nRmc9BjsARg==\n', `updated_at` = '2013-01-19 21:28:11' WHERE `sessions`.`id` = 285
   (0.6ms)  COMMIT

The session data is trimmed for slightly better readability. I had fun digging around the Rails source code, I hope you enjoyed reading!

Want new posts sent to your email?