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

4 files changed, 144 insertions, 8 deletions

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
diff --git a/activesupport/lib/active_support/log_subscriber.rb b/activesupport/lib/active_support/log_subscriber.rb
index e95dc5a866..e782cd2d4b 100644
--- a/activesupport/lib/active_support/log_subscriber.rb
+++ b/activesupport/lib/active_support/log_subscriber.rb
@@ -95,7 +95,7 @@ module ActiveSupport
       METHOD
     end
 
-    # Set color by using a string or one of the defined constants. If a third
+    # Set color by using a symbol or one of the defined constants. If a third
     # option is set to +true+, it also adds bold to the string. This is based
     # on the Highline implementation and will automatically append CLEAR to the
     # end of the returned String.