Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

ActiveRecord log which query went to which database

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.

like image 388
Wayne Conrad Avatar asked Mar 13 '17 16:03

Wayne Conrad


People also ask

What is ActiveRecord base transaction?

Rails provides the transaction method under the ActiveRecord::Base Class. Since every model inherits ActiveRecord::Base the transaction method is available to every model class. The transaction method called on a model class works exactly like ActiveRecord::Base.

Is ActiveRecord an ORM?

ActiveRecord is an ORM. It's a layer of Ruby code that runs between your database and your logic code.

What is ActiveRecord Ruby?

1 What is Active Record? Active Record is the M in MVC - the model - which is the layer of the system responsible for representing business data and logic. Active Record facilitates the creation and use of business objects whose data requires persistent storage to a database.


3 Answers

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
like image 133
idej Avatar answered Oct 20 '22 21:10

idej


@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.

like image 20
Michał Młoźniak Avatar answered Oct 20 '22 22:10

Michał Młoźniak


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:

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

like image 1
Dmitriy Budnik Avatar answered Oct 20 '22 22:10

Dmitriy Budnik