mirror of
https://github.com/rails/rails.git
synced 2022-11-09 12:12:34 -05:00
3876defd7c
This new ActiveRecord configuration option allows you to easily pinpoint what line of application code is triggering SQL queries in the development log by appending below each SQL statement log the line of Ruby code that triggered it. It’s useful with N+1 issues, and to locate stray queries. By default this new option ignores Rails and Ruby code in order to surface only callers from your application Ruby code or your gems. It is enabled on newly generated Rails 5.2 applications and can be enabled on existing Rails applications: ```ruby Rails.application.configure do # ... config.active_record.verbose_query_logs = true end ``` The `rails app:upgrade` task will also add it to `config/development.rb`. This feature purposely avoids coupling with ActiveSupport::BacktraceCleaner since ActiveRecord can be used without ActiveRecord. This decision can be reverted in the future to allow more configurable backtraces (the exclusion of gem callers for example).
236 lines
7.7 KiB
Ruby
236 lines
7.7 KiB
Ruby
# frozen_string_literal: true
|
|
|
|
require "cases/helper"
|
|
require "models/binary"
|
|
require "models/developer"
|
|
require "models/post"
|
|
require "active_support/log_subscriber/test_helper"
|
|
|
|
class LogSubscriberTest < ActiveRecord::TestCase
|
|
include ActiveSupport::LogSubscriber::TestHelper
|
|
include ActiveSupport::Logger::Severity
|
|
REGEXP_CLEAR = Regexp.escape(ActiveRecord::LogSubscriber::CLEAR)
|
|
REGEXP_BOLD = Regexp.escape(ActiveRecord::LogSubscriber::BOLD)
|
|
REGEXP_MAGENTA = Regexp.escape(ActiveRecord::LogSubscriber::MAGENTA)
|
|
REGEXP_CYAN = Regexp.escape(ActiveRecord::LogSubscriber::CYAN)
|
|
SQL_COLORINGS = {
|
|
SELECT: Regexp.escape(ActiveRecord::LogSubscriber::BLUE),
|
|
INSERT: Regexp.escape(ActiveRecord::LogSubscriber::GREEN),
|
|
UPDATE: Regexp.escape(ActiveRecord::LogSubscriber::YELLOW),
|
|
DELETE: Regexp.escape(ActiveRecord::LogSubscriber::RED),
|
|
LOCK: Regexp.escape(ActiveRecord::LogSubscriber::WHITE),
|
|
ROLLBACK: Regexp.escape(ActiveRecord::LogSubscriber::RED),
|
|
TRANSACTION: REGEXP_CYAN,
|
|
OTHER: REGEXP_MAGENTA
|
|
}
|
|
Event = Struct.new(:duration, :payload)
|
|
|
|
class TestDebugLogSubscriber < ActiveRecord::LogSubscriber
|
|
attr_reader :debugs
|
|
|
|
def initialize
|
|
@debugs = []
|
|
super
|
|
end
|
|
|
|
def debug(progname = nil, &block)
|
|
@debugs << progname
|
|
super
|
|
end
|
|
end
|
|
|
|
fixtures :posts
|
|
|
|
def setup
|
|
@old_logger = ActiveRecord::Base.logger
|
|
Developer.primary_key
|
|
super
|
|
ActiveRecord::LogSubscriber.attach_to(:active_record)
|
|
end
|
|
|
|
def teardown
|
|
super
|
|
ActiveRecord::LogSubscriber.log_subscribers.pop
|
|
ActiveRecord::Base.logger = @old_logger
|
|
end
|
|
|
|
def set_logger(logger)
|
|
ActiveRecord::Base.logger = logger
|
|
end
|
|
|
|
def test_schema_statements_are_ignored
|
|
logger = TestDebugLogSubscriber.new
|
|
assert_equal 0, logger.debugs.length
|
|
|
|
logger.sql(Event.new(0.9, sql: "hi mom!"))
|
|
assert_equal 1, logger.debugs.length
|
|
|
|
logger.sql(Event.new(0.9, sql: "hi mom!", name: "foo"))
|
|
assert_equal 2, logger.debugs.length
|
|
|
|
logger.sql(Event.new(0.9, sql: "hi mom!", name: "SCHEMA"))
|
|
assert_equal 2, logger.debugs.length
|
|
end
|
|
|
|
def test_sql_statements_are_not_squeezed
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.sql(Event.new(0.9, sql: "ruby rails"))
|
|
assert_match(/ruby rails/, logger.debugs.first)
|
|
end
|
|
|
|
def test_basic_query_logging
|
|
Developer.all.load
|
|
wait
|
|
assert_equal 1, @logger.logged(:debug).size
|
|
assert_match(/Developer Load/, @logger.logged(:debug).last)
|
|
assert_match(/SELECT .*?FROM .?developers.?/i, @logger.logged(:debug).last)
|
|
end
|
|
|
|
def test_basic_query_logging_coloration
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
SQL_COLORINGS.each do |verb, color_regex|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s))
|
|
assert_match(/#{REGEXP_BOLD}#{color_regex}#{verb}#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
end
|
|
end
|
|
|
|
def test_basic_payload_name_logging_coloration_generic_sql
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
SQL_COLORINGS.each do |verb, _|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0\.9ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s, name: "SQL"))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA}SQL \(0\.9ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
end
|
|
end
|
|
|
|
def test_basic_payload_name_logging_coloration_named_sql
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
SQL_COLORINGS.each do |verb, _|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s, name: "Model Load"))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}Model Load \(0\.9ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s, name: "Model Exists"))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}Model Exists \(0\.9ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
|
|
logger.sql(Event.new(0.9, sql: verb.to_s, name: "ANY SPECIFIC NAME"))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}ANY SPECIFIC NAME \(0\.9ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
end
|
|
end
|
|
|
|
def test_query_logging_coloration_with_nested_select
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
SQL_COLORINGS.slice(:SELECT, :INSERT, :UPDATE, :DELETE).each do |verb, color_regex|
|
|
logger.sql(Event.new(0.9, sql: "#{verb} WHERE ID IN SELECT"))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0\.9ms\)#{REGEXP_CLEAR} #{REGEXP_BOLD}#{color_regex}#{verb} WHERE ID IN SELECT#{REGEXP_CLEAR}/i, logger.debugs.last)
|
|
end
|
|
end
|
|
|
|
def test_query_logging_coloration_with_multi_line_nested_select
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
SQL_COLORINGS.slice(:SELECT, :INSERT, :UPDATE, :DELETE).each do |verb, color_regex|
|
|
sql = <<-EOS
|
|
#{verb}
|
|
WHERE ID IN (
|
|
SELECT ID FROM THINGS
|
|
)
|
|
EOS
|
|
logger.sql(Event.new(0.9, sql: sql))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0\.9ms\)#{REGEXP_CLEAR} #{REGEXP_BOLD}#{color_regex}.*#{verb}.*#{REGEXP_CLEAR}/mi, logger.debugs.last)
|
|
end
|
|
end
|
|
|
|
def test_query_logging_coloration_with_lock
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.colorize_logging = true
|
|
sql = <<-EOS
|
|
SELECT * FROM
|
|
(SELECT * FROM mytable FOR UPDATE) ss
|
|
WHERE col1 = 5;
|
|
EOS
|
|
logger.sql(Event.new(0.9, sql: sql))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0\.9ms\)#{REGEXP_CLEAR} #{REGEXP_BOLD}#{SQL_COLORINGS[:LOCK]}.*FOR UPDATE.*#{REGEXP_CLEAR}/mi, logger.debugs.last)
|
|
|
|
sql = <<-EOS
|
|
LOCK TABLE films IN SHARE MODE;
|
|
EOS
|
|
logger.sql(Event.new(0.9, sql: sql))
|
|
assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0\.9ms\)#{REGEXP_CLEAR} #{REGEXP_BOLD}#{SQL_COLORINGS[:LOCK]}.*LOCK TABLE.*#{REGEXP_CLEAR}/mi, logger.debugs.last)
|
|
end
|
|
|
|
def test_exists_query_logging
|
|
Developer.exists? 1
|
|
wait
|
|
assert_equal 1, @logger.logged(:debug).size
|
|
assert_match(/Developer Exists/, @logger.logged(:debug).last)
|
|
assert_match(/SELECT .*?FROM .?developers.?/i, @logger.logged(:debug).last)
|
|
end
|
|
|
|
def test_vebose_query_logs
|
|
ActiveRecord::Base.verbose_query_logs = true
|
|
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.sql(Event.new(0, sql: "hi mom!"))
|
|
assert_match(/↳/, @logger.logged(:debug).last)
|
|
ensure
|
|
ActiveRecord::Base.verbose_query_logs = false
|
|
end
|
|
|
|
def test_verbose_query_logs_disabled_by_default
|
|
logger = TestDebugLogSubscriber.new
|
|
logger.sql(Event.new(0, sql: "hi mom!"))
|
|
assert_no_match(/↳/, @logger.logged(:debug).last)
|
|
end
|
|
|
|
def test_cached_queries
|
|
ActiveRecord::Base.cache do
|
|
Developer.all.load
|
|
Developer.all.load
|
|
end
|
|
wait
|
|
assert_equal 2, @logger.logged(:debug).size
|
|
assert_match(/CACHE/, @logger.logged(:debug).last)
|
|
assert_match(/SELECT .*?FROM .?developers.?/i, @logger.logged(:debug).last)
|
|
end
|
|
|
|
def test_basic_query_doesnt_log_when_level_is_not_debug
|
|
@logger.level = INFO
|
|
Developer.all.load
|
|
wait
|
|
assert_equal 0, @logger.logged(:debug).size
|
|
end
|
|
|
|
def test_cached_queries_doesnt_log_when_level_is_not_debug
|
|
@logger.level = INFO
|
|
ActiveRecord::Base.cache do
|
|
Developer.all.load
|
|
Developer.all.load
|
|
end
|
|
wait
|
|
assert_equal 0, @logger.logged(:debug).size
|
|
end
|
|
|
|
def test_initializes_runtime
|
|
Thread.new { assert_equal 0, ActiveRecord::LogSubscriber.runtime }.join
|
|
end
|
|
|
|
if ActiveRecord::Base.connection.prepared_statements
|
|
def test_binary_data_is_not_logged
|
|
Binary.create(data: "some binary data")
|
|
wait
|
|
assert_match(/<16 bytes of binary data>/, @logger.logged(:debug).join)
|
|
end
|
|
|
|
def test_binary_data_hash
|
|
Binary.create(data: { a: 1 })
|
|
wait
|
|
assert_match(/<7 bytes of binary data>/, @logger.logged(:debug).join)
|
|
end
|
|
end
|
|
end
|