ActiveRecord log which query went to which database

Question

In an ActiveRecord application with multiple connections to different databases, nothing in the log indicates which query went to which database. These queries to separate databases:

Base1.connection.select_value("select * from foo")
Base2.connection.select_value("select * from foo")

Emit these log entries:

D, [2017-03-13T09:27:11.844395 #22112] DEBUG -- :    (0.6ms)  select * from foo
D, [2017-03-13T09:27:11.844539 #22112] DEBUG -- :    (0.1ms)  select * from foo

How can I cause the ActiveRecord database log to indicate which database a query was being done against?

Standalone example

begin
  require "bundler/inline"
rescue LoadError => e
  $stderr.puts "Bundler version 1.10 or later is required."
  raise e
end

gemfile(true) do
  source "https://rubygems.org"
  # Activate the gem you are reporting the issue against.
  gem "activerecord", "4.2.8"
  gem "sqlite3"
end

require "active_record"
require "logger"

class Base1 < ActiveRecord::Base
  self.abstract_class = true
end

class Base2 < ActiveRecord::Base
  self.abstract_class = true
end

Base1.establish_connection(adapter: "sqlite3", database: ":memory:")
Base2.establish_connection(adapter: "sqlite3", database: ":memory:")

ActiveRecord::Base.logger = Logger.new(STDOUT)

Base1.connection.execute("create table foo(i int)")
Base2.connection.execute("create table foo(i int)")
Base1.connection.execute("insert into foo(i) values (1)")
Base2.connection.execute("insert into foo(i) values (2)")
raise unless Base1.connection.select_value("select * from foo") == 1
raise unless Base2.connection.select_value("select * from foo") == 2

The output:

D, [2017-03-13T09:27:11.842939 #22112] DEBUG -- :    (0.2ms)  create table foo(i int)
D, [2017-03-13T09:27:11.843478 #22112] DEBUG -- :    (0.2ms)  create table foo(i int)
D, [2017-03-13T09:27:11.843612 #22112] DEBUG -- :    (0.1ms)  insert into foo(i) values (1)
D, [2017-03-13T09:27:11.843720 #22112] DEBUG -- :    (0.0ms)  insert into foo(i) values (2)
D, [2017-03-13T09:27:11.844395 #22112] DEBUG -- :    (0.6ms)  select * from foo
D, [2017-03-13T09:27:11.844539 #22112] DEBUG -- :    (0.1ms)  select * from foo

I tried creating a separate logger for each connection

I tried giving each connection its own logger, so that I could change each log's formatting:

Base1.logger = Logger.new(STDOUT)
Base2.logger = Logger.new(STDOUT)

But, unfortunately, there appears to be only one logger in ActiveRecord, as shown by this line which does not raise an exception:

raise unless Base1.logger.object_id == Base2.logger.object_id

Versions

• ruby-2.3.3
• activerecord 4.2.8
• In this example, sqlite3 1.13.3 (1)
• In production, mysql2 0.4.5 (1) and activerecord-sqlserver-adapter 4.2.15 (1)

(1) This problem is not specific to any particular database adapter. I've listed adapter versions for completeness.

Answer 1

As I know you can't do it with ActiveRecord natively. But you can override log method in AbstractAdapter if you really need it:

class ActiveRecord::ConnectionAdapters::AbstractAdapter
  alias :original_log :log
  def log(sql, name = "SQL", binds = [], statement_name = nil)
    #add info that you want to display to name
    name = "#{name} #{@connection.hash}" 
    original_log(sql, name, binds, statement_name) { yield }
  end
end

The output:

D, [2017-03-15T20:55:59.200533 #73440] DEBUG -- :    -4111614587995646180 (0.5ms)  create table foo(i int)
D, [2017-03-15T20:55:59.201178 #73440] DEBUG -- :    -4097137311320758185 (0.1ms)  create table foo(i int)
D, [2017-03-15T20:55:59.201298 #73440] DEBUG -- :    -4111614587995646180 (0.0ms)  insert into foo(i) values (1)
D, [2017-03-15T20:55:59.201426 #73440] DEBUG -- :    -4097137311320758185 (0.1ms)  insert into foo(i) values (2)
D, [2017-03-15T20:55:59.202229 #73440] DEBUG -- :    -4111614587995646180 (0.7ms)  select * from foo
D, [2017-03-15T20:55:59.202360 #73440] DEBUG -- :    -4097137311320758185 (0.0ms)  select * from foo

Being more human-friendly

The above code logs the connection hash, and that's enough to tell one connection from another. If you want to log something more human-friendly than that, you'll need to get a little tricky.

What we can do is to decorate the abstract adapter with a method to return a human-friendly connection name. During your program's initialization, add a #log_name method to each connection adapter:

Base1.connection.define_singleton_method(:log_name) { "one" }
Base2.connection.define_singleton_method(:log_name) { "two" }

The monkey-patch can now use the #log_name method:

class ActiveRecord::ConnectionAdapters::AbstractAdapter
  alias :original_log :log
  def log(sql, name = "SQL", binds = [], statement_name = nil)
    connection_name = respond_to?(:log_name) ? log_name : nil
    name = [connection_name, name].compact.join(" ")
    original_log(sql, name, binds, statement_name) { yield }
  end
end

The output:

D, [2017-03-21T10:10:53.330021 #22147] DEBUG -- :   one (0.3ms)  create table foo(i int)
D, [2017-03-21T10:10:53.330380 #22147] DEBUG -- :   two (0.2ms)  create table foo(i int)
D, [2017-03-21T10:10:53.330464 #22147] DEBUG -- :   one (0.0ms)  insert into foo(i) values (1)
D, [2017-03-21T10:10:53.330536 #22147] DEBUG -- :   two (0.0ms)  insert into foo(i) values (2)
D, [2017-03-21T10:10:53.331002 #22147] DEBUG -- :   one (0.4ms)  select * from foo
D, [2017-03-21T10:10:53.331104 #22147] DEBUG -- :   two (0.0ms)  select * from foo

Answer 2

@idej answer is good, but I want to also add another approach. If it happens that you also use ActiveSupport, you can subscribe to sql.active_record event.

ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)

  puts event.inspect
end

In event.payload you have access to some useful attributes like sql, connection_id, binds etc. The problem is that you need to log those attributes yourself and message for any sql query will appear two times in the logs. But you don't have to modify any class.

You can find more details in the docs.

Answer 3

You have to (monkey)patch ActiveRecord::ConnectionAdapters::AbstractAdapter you may do it in new initializer:

# config/initializers/adapter_monkeypatch.rb
class ActiveRecord::ConnectionAdapters::AbstractAdapter
  alias :original_log :log
  def log(sql, *args, &block)
    prefix = self.class.to_s.demodulize

    original_log("#{prefix}: #{sql}", *args, &block)
  end
end

As you are using different databases you could just use class_name of adapter as prefix:

But it's easy to change prefix to something more relevant to your requirements.