Convert log subscriber in Active Record to consume structured events

Author: gmcgibbon

activerecord/lib/active_record/base.rb

@@ -6,6 +6,7 @@
 require "active_support/time"
 require "active_support/core_ext/class/subclasses"
 require "active_record/log_subscriber"
+require "active_record/structured_event_subscriber"
 require "active_record/relation/delegation"
 require "active_record/attributes"
 require "active_record/type_caster"

activerecord/lib/active_record/log_subscriber.rb

@@ -1,51 +1,42 @@
 # frozen_string_literal: true
 
 module ActiveRecord
-  class LogSubscriber < ActiveSupport::LogSubscriber # :nodoc:
+  class LogSubscriber < ActiveSupport::EventReporter::LogSubscriber # :nodoc:
     IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"]
 
+    self.namespace = "active_record"
+
     class_attribute :backtrace_cleaner, default: ActiveSupport::BacktraceCleaner.new
 
     def strict_loading_violation(event)
       debug do
-        owner = event.payload[:owner]
-        reflection = event.payload[:reflection]
-        color(reflection.strict_loading_violation_message(owner), RED)
+        owner = event[:payload][:owner]
+        klass = event[:payload][:class]
+        name = event[:payload][:name]
+        message = +"`#{owner}` is marked for strict_loading."
+        message << " The #{klass ? "#{klass} association" : "polymorphic association"}"
+        message << " named `:#{name}` cannot be lazily loaded."
+
+        color(message, RED)
       end
     end
-    subscribe_log_level :strict_loading_violation, :debug
+    event_log_level :strict_loading_violation, :debug
 
     def sql(event)
-      payload = event.payload
+      payload = event[:payload]
 
       return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])
 
       name = if payload[:async]
-        "ASYNC #{payload[:name]} (#{payload[:lock_wait].round(1)}ms) (db time #{event.duration.round(1)}ms)"
+        "ASYNC #{payload[:name]} (#{payload[:lock_wait].round(1)}ms) (db time #{payload[:duration_ms].round(1)}ms)"
       else
-        "#{payload[:name]} (#{event.duration.round(1)}ms)"
+        "#{payload[:name]} (#{payload[:duration_ms].round(1)}ms)"
       end
       name  = "CACHE #{name}" if payload[:cached]
       sql   = payload[:sql]
-      binds = nil
+      binds = payload[:binds]
 
       if payload[:binds]&.any?
-        casted_params = type_casted_binds(payload[:type_casted_binds])
-
-        binds = []
-        payload[:binds].each_with_index do |attr, i|
-          attribute_name = if attr.respond_to?(:name)
-            attr.name
-          elsif attr.respond_to?(:[]) && attr[i].respond_to?(:name)
-            attr[i].name
-          else
-            nil
-          end
-
-          filtered_params = filter(attribute_name, casted_params[i])
-
-          binds << render_bind(attr, filtered_params)
-        end
         binds = binds.inspect
         binds.prepend("  ")
       end
@@ -55,7 +46,11 @@ def sql(event)
 
       debug "  #{name}  #{sql}#{binds}"
     end
-    subscribe_log_level :sql, :debug
+    event_log_level :sql, :debug
+
+    def self.default_logger
+      ActiveRecord::Base.logger
+    end
 
     private
       def type_casted_binds(casted_binds)
@@ -106,10 +101,6 @@ def sql_color(sql)
         end
       end
 
-      def logger
-        ActiveRecord::Base.logger
-      end
-
       def debug(progname = nil, &block)
         return unless super
 
@@ -136,4 +127,6 @@ def filter(name, value)
   end
 end
 
-ActiveRecord::LogSubscriber.attach_to :active_record
+ActiveSupport.event_reporter.subscribe(
+  ActiveRecord::LogSubscriber.new, &ActiveRecord::LogSubscriber.subscription_filter
+)

activerecord/test/cases/adapters/abstract_mysql_adapter/table_options_test.rb

@@ -81,6 +81,12 @@ class DefaultEngineOptionTest < ActiveRecord::AbstractMysqlTestCase
   include SchemaDumpingHelper
   self.use_transactional_tests = false
 
+  def run(*)
+    with_debug_event_reporting do
+      super
+    end
+  end
+
   def setup
     @logger_was  = ActiveRecord::Base.logger
     @log         = StringIO.new
@@ -90,7 +96,7 @@ def setup
   end
 
   def teardown
-    ActiveRecord::Base.logger       = @logger_was
+    ActiveRecord::Base.logger = @logger_was
     ActiveRecord::Migration.verbose = @verbose_was
     ActiveRecord::Base.lease_connection.drop_table "mysql_table_options", if_exists: true
     ActiveRecord::Base.connection_pool.schema_migration.delete_all_versions rescue nil

activerecord/test/cases/bind_parameter_test.rb

@@ -5,6 +5,7 @@
 require "models/reply"
 require "models/author"
 require "models/post"
+require "active_support/log_subscriber/test_helper"
 
 if ActiveRecord::Base.lease_connection.prepared_statements
   module ActiveRecord
@@ -23,6 +24,12 @@ def call(*args)
         end
       end
 
+      def run(*)
+        with_debug_event_reporting do
+          super
+        end
+      end
+
       def setup
         super
         @connection = ActiveRecord::Base.lease_connection
@@ -289,21 +296,12 @@ def assert_logs_binds(binds)
             123,
             payload)
 
-          logger = Class.new(ActiveRecord::LogSubscriber) {
-            attr_reader :debugs
-
-            def initialize
-              super
-              @debugs = []
-            end
-
-            def debug(str)
-              @debugs << str
-            end
-          }.new
-
-          logger.sql(event)
-          assert_match %r(\[\["id", 10\]\]\z), logger.debugs.first
+          old_logger = ActiveRecord::LogSubscriber.logger
+          ActiveRecord::LogSubscriber.logger = logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
+          StructuredEventSubscriber.new.sql(event)
+          assert_match %r(\[\["id", 10\]\]\z), logger.logged(:debug).last
+        ensure
+          ActiveRecord::LogSubscriber.logger = old_logger
         end
 
         def assert_logs_unnamed_binds(binds)
@@ -321,21 +319,12 @@ def assert_logs_unnamed_binds(binds)
             123,
             payload)
 
-          logger = Class.new(ActiveRecord::LogSubscriber) {
-            attr_reader :debugs
-
-            def initialize
-              super
-              @debugs = []
-            end
-
-            def debug(str)
-              @debugs << str
-            end
-          }.new
-
-          logger.sql(event)
-          assert_match %r(\[\[nil, "abcd"\]\]\z), logger.debugs.first
+          old_logger = ActiveRecord::LogSubscriber.logger
+          ActiveRecord::LogSubscriber.logger = logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
+          StructuredEventSubscriber.new.sql(event)
+          assert_match %r(\[\[nil, "abcd"\]\]\z), logger.logged(:debug).last
+        ensure
+          ActiveRecord::LogSubscriber.logger = old_logger
         end
 
         def assert_filtered_log_binds(binds)
@@ -353,21 +342,12 @@ def assert_filtered_log_binds(binds)
             123,
             payload)
 
-          logger = Class.new(ActiveRecord::LogSubscriber) {
-            attr_reader :debugs
-
-            def initialize
-              super
-              @debugs = []
-            end
-
-            def debug(str)
-              @debugs << str
-            end
-          }.new
-
-          logger.sql(event)
-          assert_match %r/#{Regexp.escape '[["auth_token", "[FILTERED]"]]'}/, logger.debugs.first
+          old_logger = ActiveRecord::LogSubscriber.logger
+          ActiveRecord::LogSubscriber.logger = logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
+          StructuredEventSubscriber.new.sql(event)
+          assert_match %r/#{Regexp.escape '[["auth_token", "[FILTERED]"]]'}/, logger.logged(:debug).last
+        ensure
+          ActiveRecord::LogSubscriber.logger = old_logger
         end
     end
   end

activerecord/test/cases/insert_all_test.rb

@@ -18,6 +18,12 @@ class ReadonlyNameBook < Book
 class InsertAllTest < ActiveRecord::TestCase
   fixtures :books
 
+  def run(*)
+    with_debug_event_reporting do
+      super
+    end
+  end
+
   def setup
     Arel::Table.engine = nil # should not rely on the global Arel::Table.engine
     @original_db_warnings_action = :ignore
@@ -1034,12 +1040,12 @@ def test_upsert_without_unpersisted_records_has_no_deprecation
   private
     def capture_log_output
       output = StringIO.new
-      old_logger, ActiveRecord::Base.logger = ActiveRecord::Base.logger, ActiveSupport::Logger.new(output)
+      old_logger, ActiveRecord::LogSubscriber.logger = ActiveRecord::LogSubscriber.logger, ActiveSupport::Logger.new(output)
 
       begin
         yield output
       ensure
-        ActiveRecord::Base.logger = old_logger
+        ActiveRecord::LogSubscriber.logger = old_logger
       end
     end