From bec65fa261b9803c19edbbe9dc89836e1edf78c7 Mon Sep 17 00:00:00 2001
From: Peter Boling <peter.boling@gmail.com>
Date: Fri, 17 Jul 2015 13:23:59 -0700
Subject: Improve sql logging coloration in `ActiveRecord::LogSubscriber`.
- Improves coloring for statements like:
# Become WHITE
SELECT * FROM (
SELECT * FROM mytable FOR UPDATE
) ss WHERE col1 = 5;
LOCK TABLE table_name IN ACCESS EXCLUSIVE MODE;
# Becomes RED
ROLLBACK
- Reinstates the coloration of the `payload[:name]`.
Instead of simple alternating colors, adds meaning:
- `MAGENTA` for `"SQL"` or `blank?` payload names
- `CYAN` for Model Load/Exists
- Introduces specs for sql coloration.
- Introduces specs for payload name coloration.
GH#20885
---
activerecord/CHANGELOG.md | 24 ++++++
activerecord/lib/active_record/log_subscriber.rb | 28 +++++--
activerecord/test/cases/log_subscriber_test.rb | 98 ++++++++++++++++++++++++
3 files changed, 143 insertions(+), 7 deletions(-)
(limited to 'activerecord')
diff --git a/activerecord/CHANGELOG.md b/activerecord/CHANGELOG.md
index 237b07f653..e130ebc632 100644
--- a/activerecord/CHANGELOG.md
+++ b/activerecord/CHANGELOG.md
@@ -1,3 +1,27 @@
+* Improve sql logging coloration in `ActiveRecord::LogSubscriber`.
+ GH#20885
+
+ Improves coloring for statements like:
+
+ # Become WHITE
+ SELECT * FROM (
+ SELECT * FROM mytable FOR UPDATE
+ ) ss WHERE col1 = 5;
+ LOCK TABLE table_name IN ACCESS EXCLUSIVE MODE;
+
+ # Becomes RED
+ ROLLBACK
+
+ Reinstates the coloration of the `payload[:name]`.
+ Instead of simple alternating colors, adds meaning:
+ - `MAGENTA` for `"SQL"` or `blank?` payload names
+ - `CYAN` for Model Load/Exists
+
+ Introduces specs for sql coloration.
+ Introduces specs for payload name coloration.
+
+ *Peter Boling*
+
* Deprecate force association reload by passing a truthy argument to
association method.
diff --git a/activerecord/lib/active_record/log_subscriber.rb b/activerecord/lib/active_record/log_subscriber.rb
index 4d597a0ab1..9e3f1bfb9e 100644
--- a/activerecord/lib/active_record/log_subscriber.rb
+++ b/activerecord/lib/active_record/log_subscriber.rb
@@ -47,7 +47,11 @@ module ActiveRecord
binds = " " + payload[:binds].map { |attr| render_bind(attr) }.inspect
end
- name = color(name, nil, true)
+ if payload[:name].blank? || payload[:name] == "SQL" # SQL vs Model Load/Exists
+ name = color(name, MAGENTA, true)
+ else
+ name = color(name, CYAN, true)
+ end
sql = color(sql, sql_color(sql), true)
debug " #{name} #{sql}#{binds}"
@@ -55,12 +59,22 @@ module ActiveRecord
def sql_color(sql)
case sql
- when /\s*\Ainsert/i then GREEN
- when /\s*\Aselect/i then BLUE
- when /\s*\Aupdate/i then YELLOW
- when /\s*\Adelete/i then RED
- when /transaction\s*\Z/i then CYAN
- else MAGENTA
+ when /\A\s*rollback/mi then
+ RED
+ when /\s*.*?select .*for update/mi, /\A\s*lock/mi then
+ WHITE
+ when /\A\s*select/i then
+ BLUE
+ when /\A\s*insert/i then
+ GREEN
+ when /\A\s*update/i then
+ YELLOW
+ when /\A\s*delete/i then
+ RED
+ when /transaction\s*\Z/i then
+ CYAN
+ else
+ MAGENTA
end
end
diff --git a/activerecord/test/cases/log_subscriber_test.rb b/activerecord/test/cases/log_subscriber_test.rb
index 4192d12ff4..3846ba8e7f 100644
--- a/activerecord/test/cases/log_subscriber_test.rb
+++ b/activerecord/test/cases/log_subscriber_test.rb
@@ -7,6 +7,20 @@ 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
+ }
class TestDebugLogSubscriber < ActiveRecord::LogSubscriber
attr_reader :debugs
@@ -71,6 +85,90 @@ class LogSubscriberTest < ActiveRecord::TestCase
assert_match(/SELECT .*?FROM .?developers.?/i, @logger.logged(:debug).last)
end
+ def test_basic_query_logging_coloration
+ event = Struct.new(:duration, :payload)
+ logger = TestDebugLogSubscriber.new
+ logger.colorize_logging = true
+ SQL_COLORINGS.each do |verb, color_regex|
+ logger.sql(event.new(0, 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
+ event = Struct.new(:duration, :payload)
+ logger = TestDebugLogSubscriber.new
+ logger.colorize_logging = true
+ SQL_COLORINGS.each do |verb, _|
+ logger.sql(event.new(0, sql: verb.to_s))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0.0ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
+
+ logger.sql(event.new(0, {sql: verb.to_s, name: "SQL"}))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA}SQL \(0.0ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
+ end
+ end
+
+ def test_basic_payload_name_logging_coloration_named_sql
+ event = Struct.new(:duration, :payload)
+ logger = TestDebugLogSubscriber.new
+ logger.colorize_logging = true
+ SQL_COLORINGS.each do |verb, _|
+ logger.sql(event.new(0, {sql: verb.to_s, name: "Model Load"}))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}Model Load \(0.0ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
+
+ logger.sql(event.new(0, {sql: verb.to_s, name: "Model Exists"}))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}Model Exists \(0.0ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
+
+ logger.sql(event.new(0, {sql: verb.to_s, name: "ANY SPECIFIC NAME"}))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_CYAN}ANY SPECIFIC NAME \(0.0ms\)#{REGEXP_CLEAR}/i, logger.debugs.last)
+ end
+ end
+
+ def test_query_logging_coloration_with_nested_select
+ event = Struct.new(:duration, :payload)
+ logger = TestDebugLogSubscriber.new
+ logger.colorize_logging = true
+ SQL_COLORINGS.slice(:SELECT, :INSERT, :UPDATE, :DELETE).each do |verb, color_regex|
+ logger.sql(event.new(0, sql: "#{verb} WHERE ID IN SELECT"))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0.0ms\)#{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
+ event = Struct.new(:duration, :payload)
+ 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, sql: sql))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0.0ms\)#{REGEXP_CLEAR} #{REGEXP_BOLD}#{color_regex}.*#{verb}.*#{REGEXP_CLEAR}/mi, logger.debugs.last)
+ end
+ end
+
+ def test_query_logging_coloration_with_lock
+ event = Struct.new(:duration, :payload)
+ 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, sql: sql))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0.0ms\)#{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, sql: sql))
+ assert_match(/#{REGEXP_BOLD}#{REGEXP_MAGENTA} \(0.0ms\)#{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
--
cgit v1.2.3