T-10657 Support Rails 8.2 where log subscribers moved to ActiveSupport::EventReporter

.github/workflows/main.yml

@@ -40,6 +40,8 @@ jobs:
           - "rails-5.1"
           - "rails-5.0"
         exclude:
+          - gemfile: "rails-edge"
+            ruby-version: "3.2"
           - gemfile: "rails-edge"
             ruby-version: "3.1"
           - gemfile: "rails-edge"

lib/logtail-rails/action_controller/log_subscriber.rb

@@ -18,7 +18,7 @@ def integrate!
           return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:action_controller, LogtailLogSubscriber)
 
           Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:action_controller, ::ActionController::LogSubscriber)
-          LogtailLogSubscriber.attach_to(:action_controller)
+          Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:action_controller, LogtailLogSubscriber)
         end
       end
     end

lib/logtail-rails/action_controller/log_subscriber/logtail_log_subscriber.rb

@@ -9,21 +9,42 @@ class LogSubscriber < Integrator
         #
         # @private
         class LogtailLogSubscriber < ::ActionController::LogSubscriber
-          def start_processing(event)
-            return true if silence?
+          if ::ActionController::LogSubscriber < ::ActiveSupport::LogSubscriber
+            def start_processing(event)
+              return true if silence?
 
-            info do
-              payload = event.payload
-              params = payload[:params].except(*INTERNAL_PARAMS)
-              format = extract_format(payload)
-              format = format.to_s.upcase if format.is_a?(Symbol)
+              info do
+                payload = event.payload
+                params = payload[:params].except(*INTERNAL_PARAMS)
+                format = extract_format(payload)
+                format = format.to_s.upcase if format.is_a?(Symbol)
 
-              Events::ControllerCall.new(
-                controller: payload[:controller],
-                action: payload[:action],
-                format: format,
-                params: params
-              )
+                Events::ControllerCall.new(
+                  controller: payload[:controller],
+                  action: payload[:action],
+                  format: format,
+                  params: params
+                )
+              end
+            end
+          else
+            # Rails 8.2+ feeds this subscriber from Rails.event: the event is a hash whose
+            # payload already comes without the internal params and with the format upcased.
+            self.namespace = "action_controller"
+
+            def request_started(event)
+              return true if silence?
+
+              info do
+                payload = event[:payload]
+
+                Events::ControllerCall.new(
+                  controller: payload[:controller],
+                  action: payload[:action],
+                  format: payload[:format],
+                  params: payload[:params]
+                )
+              end
             end
           end
 

lib/logtail-rails/action_view/log_subscriber.rb

@@ -17,7 +17,7 @@ def integrate!
           return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:action_view, LogtailLogSubscriber)
 
           Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:action_view, ::ActionView::LogSubscriber)
-          LogtailLogSubscriber.attach_to(:action_view)
+          Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:action_view, LogtailLogSubscriber)
         end
       end
     end

lib/logtail-rails/action_view/log_subscriber/logtail_log_subscriber.rb

@@ -7,8 +7,12 @@ class LogSubscriber < Integrator
         # The intent of this subscriber is to, as transparently as possible, properly
         # track events that are being logged here.
         #
+        # Until Rails 8.1 it extends the default subscriber. Rails 8.2 turned that one into a
+        # subscriber of Rails.event, which receives the rendering events in debug mode only, so
+        # there this subscriber listens to the notifications on its own.
+        #
         # @private
-        class LogtailLogSubscriber < ::ActionView::LogSubscriber
+        class LogtailLogSubscriber < (::ActionView::LogSubscriber < ::ActiveSupport::LogSubscriber ? ::ActionView::LogSubscriber : ::ActiveSupport::LogSubscriber)
           def render_template(event)
             return true if silence?
 
@@ -67,15 +71,25 @@ def render_collection(event)
             end
           end
 
-          def self.attach_to(*)
-            super
+          if superclass == ::ActionView::LogSubscriber
+            def self.attach_to(*)
+              super
+
+              if ::Rails::VERSION::MAJOR > 7 || ::Rails::VERSION::MAJOR == 7 && ::Rails::VERSION::MINOR >= 1
+                # Clean extra listeners subscribed in parent's attach_to method
+                ::ActiveSupport::Notifications.notifier.listeners_for("render_template.action_view")
+                  .concat(::ActiveSupport::Notifications.notifier.listeners_for("render_layout.action_view")).flatten
+                  .filter { |listener| listener.delegate.class == ::ActionView::LogSubscriber::Start }
+                  .each { |listener| ActiveSupport::Notifications.unsubscribe(listener) }
+              end
+            end
+          else
+            # The default subscriber used to bring these log levels, the logger and the helpers below
+            subscribe_log_level :render_partial, :debug
+            subscribe_log_level :render_collection, :debug
 
-            if ::Rails::VERSION::MAJOR > 7 || ::Rails::VERSION::MAJOR == 7 && ::Rails::VERSION::MINOR >= 1
-              # Clean extra listeners subscribed in parent's attach_to method
-              ::ActiveSupport::Notifications.notifier.listeners_for("render_template.action_view")
-                .concat(::ActiveSupport::Notifications.notifier.listeners_for("render_layout.action_view")).flatten
-                .filter { |listener| listener.delegate.class == ::ActionView::LogSubscriber::Start }
-                .each { |listener| ActiveSupport::Notifications.unsubscribe(listener) }
+            def logger
+              ::ActionView::Base.logger
             end
           end
 
@@ -90,6 +104,35 @@ def log_rendering_start(*args)
           def silence?
             ActionView.silence?
           end
+
+          unless superclass == ::ActionView::LogSubscriber
+            def from_rails_root(string)
+              string = string.sub(rails_root, "")
+              string.sub!(/^app\/views\//, "")
+              string
+            end
+
+            def rails_root
+              @rails_root ||= "#{::Rails.root}/"
+            end
+
+            def render_count(payload)
+              if payload[:cache_hits]
+                "[#{payload[:cache_hits]} / #{payload[:count]} cache hits]"
+              else
+                "[#{payload[:count]} times]"
+              end
+            end
+
+            def cache_message(payload)
+              case payload[:cache_hit]
+              when :hit
+                "[cache hit]"
+              when :miss
+                "[cache miss]"
+              end
+            end
+          end
         end
       end
     end

lib/logtail-rails/active_record/log_subscriber.rb

@@ -12,7 +12,7 @@ def integrate!
           return true if Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribed?(:active_record, LogtailLogSubscriber)
 
           Logtail::Integrations::Rails::ActiveSupportLogSubscriber.unsubscribe!(:active_record, ::ActiveRecord::LogSubscriber)
-          LogtailLogSubscriber.attach_to(:active_record)
+          Logtail::Integrations::Rails::ActiveSupportLogSubscriber.subscribe!(:active_record, LogtailLogSubscriber)
         end
       end
     end

lib/logtail-rails/active_record/log_subscriber/logtail_log_subscriber.rb

@@ -13,35 +13,88 @@ class LogSubscriber < Integrator
         # track events that are being logged here. This LogSubscriber will never change
         # default behavior / log messages.
         #
+        # Until Rails 8.1 it extends the default subscriber. Rails 8.2 turned that one into a
+        # subscriber of Rails.event, which receives the SQL events in debug mode only, so there
+        # this subscriber listens to the notifications on its own.
+        #
         # @private
-        class LogtailLogSubscriber < ::ActiveRecord::LogSubscriber
-          def sql(event)
-            return true if silence?
+        class LogtailLogSubscriber < (::ActiveRecord::LogSubscriber < ::ActiveSupport::LogSubscriber ? ::ActiveRecord::LogSubscriber : ::ActiveSupport::LogSubscriber)
+          if superclass == ::ActiveRecord::LogSubscriber
+            def sql(event)
+              return true if silence?
 
-            r = super(event)
+              r = super(event)
 
-            if @message
-              payload = event.payload
+              if @message
+                payload = event.payload
 
-              sql_event = Events::SQLQuery.new(
-                sql: payload[:sql],
-                duration_ms: event.duration,
-                message: @message,
-              )
+                sql_event = Events::SQLQuery.new(
+                  sql: payload[:sql],
+                  duration_ms: event.duration,
+                  message: @message,
+                )
 
-              logger.debug sql_event
+                logger.debug sql_event
 
-              @message = nil
+                @message = nil
+              end
+
+              r
             end
 
-            r
-          end
+            private
+            def debug(message)
+              @message = message
+            end
+          else
+            require "active_record/structured_event_subscriber"
 
-          private
-          def debug(message)
-            @message = message
+            # Rails 8.2 split ActiveRecord::LogSubscriber#sql in two: a subscriber that turns the
+            # notification into an event for Rails.event, rendering and filtering the binds, and
+            # a log subscriber that formats the event. Both are used here as they are, without
+            # Rails.event between them.
+            class Translation < ::ActiveRecord::StructuredEventSubscriber
+              attr_reader :payload
+
+              def emit_debug_event(name, payload = nil, caller_depth: 1, **kwargs)
+                @payload = payload || kwargs
+              end
+            end
+
+            class Formatting < ::ActiveRecord::LogSubscriber
+              attr_reader :message
+
+              private
+              def debug(message)
+                @message = message
+              end
+            end
+
+            def sql(event)
+              return true if silence?
+
+              translation = Translation.new
+              translation.sql(event)
+              # Schema and explain queries are not reported
+              return unless translation.payload
+
+              formatting = Formatting.new
+              formatting.sql({ name: "active_record.sql", payload: translation.payload })
+
+              logger.debug Events::SQLQuery.new(
+                sql: event.payload[:sql],
+                duration_ms: event.duration,
+                message: formatting.message,
+              )
+            end
+            subscribe_log_level :sql, :debug
+
+            def logger
+              ::ActiveRecord::Base.logger
+            end
           end
 
+          private
           def silence?
             ActiveRecord.silence?
           end

lib/logtail-rails/active_support_log_subscriber.rb

@@ -6,6 +6,12 @@ module ActiveSupportLogSubscriber
         extend self
 
         def find(component, type)
+          if event_reporter_subscriber?(type)
+            return ::ActiveSupport.event_reporter.subscribers.map { |entry| entry[:subscriber] }.find do |subscriber|
+              subscriber.class == type
+            end
+          end
+
           ::ActiveSupport::LogSubscriber.log_subscribers.find do |subscriber|
             subscriber.class == type
           end
@@ -15,9 +21,25 @@ def subscribed?(component, type)
           !find(component, type).nil?
         end
 
+        def subscribe!(component, type)
+          if event_reporter_subscriber?(type)
+            # Like attach_to below, only deliver the events for the methods the subscriber defines itself
+            events = type.public_instance_methods(false).map { |method| "#{component}.#{method}" }
+            ::ActiveSupport.event_reporter.subscribe(type.new) { |event| events.include?(event[:name]) }
+            return
+          end
+
+          type.attach_to(component)
+        end
+
         # I don't know why this has to be so complicated, but it is. This code was taken from
         # lograge :/
         def unsubscribe!(component, type)
+          if event_reporter_subscriber?(type)
+            ::ActiveSupport.event_reporter.unsubscribe(type)
+            return
+          end
+
           if defined?(type.detach_from)
             type.detach_from(component)
             return
@@ -38,6 +60,12 @@ def unsubscribe!(component, type)
             end
           end
         end
+
+        # Rails 8.2+ feeds the framework log subscribers from Rails.event instead of
+        # ActiveSupport::Notifications.
+        def event_reporter_subscriber?(type)
+          defined?(::ActiveSupport::EventReporter::LogSubscriber) && type < ::ActiveSupport::EventReporter::LogSubscriber
+        end
       end
     end
   end

lib/logtail-rails/event_log_subscriber.rb

@@ -22,6 +22,7 @@ def initialize(logger)
         # Rails 8.1 event emission method - called when events are emitted
         def emit(event)
           return unless self.class.enabled
+          return if framework_event?(event)
 
           # Log the event with all its data to Rails.logger
           # Create a structured log entry with the event data
@@ -42,6 +43,17 @@ def emit(event)
 
         private
 
+        # Rails 8.2+ routes the framework's own instrumentation (controller calls, SQL queries,
+        # template renders, ...) through Rails.event as well. The Rails log subscribers, and ours
+        # replacing them, already log those, so only the application's own events are forwarded.
+        def framework_event?(event)
+          return false unless defined?(::ActiveSupport::EventReporter::LogSubscriber)
+
+          ::ActiveSupport::EventReporter::LogSubscriber.descendants.any? do |log_subscriber|
+            event[:name].start_with?("#{log_subscriber.namespace}.")
+          end
+        end
+
         def build_log_message(event)
           payload = event[:payload] || {}
           payload_str = payload.map { |key, value| "#{key}=#{value}" }.join(" ")

spec/logtail-rails/action_view/log_subscriber_spec.rb

@@ -54,6 +54,26 @@ def method_for_action(action_name)
           expect(lines[2].strip).to match(/Rendered spec\/support\/rails\/templates\/template.html \(\d+\.\d+ms\)/)
           expect(lines[2]).to include("\"template_rendered\":{\"name\":\"spec/support/rails/templates/template.html\"")
         end
+
+        if Rails.respond_to?(:event)
+          # What config.log_level = :info does when the app boots. Rails 8.2 reports the rendering
+          # events to Rails.event in debug mode only.
+          context "with the debug mode of Rails.event turned off" do
+            around(:each) do |example|
+              debug_mode = Rails.event.debug_mode?
+              Rails.event.debug_mode = false
+              example.run
+              Rails.event.debug_mode = debug_mode
+            end
+
+            it "should log a template render event once" do
+              dispatch_rails_request("/action_view_log_subscriber")
+              lines = clean_lines(io.string.split("\n"))
+              expect(lines[2].strip).to match(/Rendered spec\/support\/rails\/templates\/template.html \(\d+\.\d+ms\)/)
+              expect(lines[2]).to include("\"template_rendered\":{\"name\":\"spec/support/rails/templates/template.html\"")
+            end
+          end
+        end
       end
     end
   end