1
0
Fork 0
mirror of https://github.com/rails/rails.git synced 2022-11-09 12:12:34 -05:00
rails--rails/activerecord/test/cases/log_subscriber_test.rb
Abhay Nikam 85b5cd344b Disable colorize logging of SQL and reduce unnecessary invokation of sql_color matching
When the `colorize_logging` is disabled,
logs do not colorize the SQL queries.
But the `sql_color` method is always
invoked which due to regex matching results
in slow queries.

This PR fixes #38685 and removes
unnecessary invokation of `sql_color`
method when `colorize_logging` is disabled
2020-03-11 11:06:08 +05:30

261 lines
8.5 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
ActiveRecord::Base.connection.materialize_transactions
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_logging_sql_coloration_disabled
logger = TestDebugLogSubscriber.new
logger.colorize_logging = false
SQL_COLORINGS.each do |verb, color_regex|
logger.sql(Event.new(0.9, sql: verb.to_s))
assert_no_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_equal 2, @logger.logged(:debug).size
assert_match(//, @logger.logged(:debug).last)
ensure
ActiveRecord::Base.verbose_query_logs = false
end
def test_verbose_query_with_ignored_callstack
ActiveRecord::Base.verbose_query_logs = true
logger = TestDebugLogSubscriber.new
def logger.extract_query_source_location(*); nil; end
logger.sql(Event.new(0, sql: "hi mom!"))
assert_equal 1, @logger.logged(:debug).size
assert_no_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