Search code examples
ruby-on-railstransactionsnotifications

ActiveSupport::Notifications transaction_id

I have been browsing the Rails repository at Github to find the definition of transaction_id, but is unsuccessful.

What kind of transaction is it? It looks like the same transaction_id is used for a group of events.

ActiveSupport::Notifications.subscribe do |name, start, finish, transaction_id , payload|
  Rails.logger.debug(["notification:", name, start, finish, transaction_id , payload].join(" "))
end

Result:

Started GET "/" for 127.0.0.1 at 2012-10-16 15:51:40 +0200

notification: sql.active_record 2012-10-16 15:51:40 +0200 2012-10-16 15:51:40 +0200 9eb707034598e4cc7c32 {:sql=>"SHOW client_min_messages", :name=>"SCHEMA", :connection_id=>46235640, :binds=>[]}

notification: sql.active_record 2012-10-16 15:51:40 +0200 2012-10-16 15:51:40 +0200 9eb707034598e4cc7c32 {:sql=>"SET client_min_messages TO 'panic'", :name=>"SCHEMA", :connection_id=>46235640, :binds=>[]}

notification: sql.active_record 2012-10-16 15:51:40 +0200 2012-10-16 15:51:40 +0200 9eb707034598e4cc7c32 {:sql=>"SET standard_conforming_strings = on", :name=>"SCHEMA", :connection_id=>46235640, :binds=>[]}

notification: sql.active_record 2012-10-16 15:51:40 +0200 2012-10-16 15:51:40 +0200 9eb707034598e4cc7c32 {:sql=>"SET client_min_messages TO 'notice'", :name=>"SCHEMA", :connection_id=>46235640, :binds=>[]}

notification: sql.active_record 2012-10-16 15:51:40 +0200 2012-10-16 15:51:40 +0200 9eb707034598e4cc7c32 {:sql=>"SET time zone 'UTC'", :name=>"SCHEMA", :connection_id=>46235640, :binds=>[]}

...

notification: process_action.action_controller 2012-10-16 15:51:40 +0200 2012-10-16 15:51:41 +0200 9eb707034598e4cc7c32 {:controller=>"PagesController", :action=>"index", :params=>{"controller"=>"pages", "action"=>"index"}, :format=>:html, :method=>"GET", :path=>"/", :status=>200, :view_runtime=>339.344333, :db_runtime=>31.421587}

The same transaction_id: 9eb707034598e4cc7c32

Solution

  • I just dove deep into this, hoping that there was some way to get the request from within a LogSubscriber. No such luck.

    Activesupport::Notifications::Instrumenter has a unique id, initialized as a SecureRandom.hex(10) when it is initialized. Any evernt created by this instrumenter gets that 10 digit hex id.

    In ActiveSupport::Notifications, the instrumenter is picked out of Thread.current, and created if none exists - therefore all notifications sent within the scope of a single thread will have the same transaction_d, unifying them all together (which is nice), but the initial value of that transaction_id is simply a 10 digit random hex. (defined in Activesupport::Notifications::Instrumenter#unique_id)