Merge pull request #23723 from mwear/action_cable_notifications

Add ActiveSupport::Notification to Channel::Base#perform_action

2 files changed, 56 insertions, 8 deletions

diff --git a/actioncable/lib/action_cable/channel/base.rb b/actioncable/lib/action_cable/channel/base.rb
index 714d9887d4..a0319eb522 100644
--- a/actioncable/lib/action_cable/channel/base.rb
+++ b/actioncable/lib/action_cable/channel/base.rb
@@ -1,3 +1,4 @@
+require 'action_cable/channel/log_subscriber'
 require 'set'
 
 module ActionCable
@@ -160,7 +161,10 @@ module ActionCable
         action = extract_action(data)
 
         if processable_action?(action)
-          dispatch_action(action, data)
+          payload = { channel_class: self.class.name, action: action, data: data }
+          ActiveSupport::Notifications.instrument("perform_action.action_cable", payload) do
+            dispatch_action(action, data)
+          end
         else
           logger.error "Unable to process #{action_signature(action, data)}"
         end
@@ -191,8 +195,10 @@ module ActionCable
         # Transmit a hash of data to the subscriber. The hash will automatically be wrapped in a JSON envelope with
         # the proper channel identifier marked as the recipient.
         def transmit(data, via: nil)
-          logger.info "#{self.class.name} transmitting #{data.inspect.truncate(300)}".tap { |m| m << " (via #{via})" if via }
-          connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, message: data)
+          payload = { channel_class: self.class.name, data: data, via: via }
+          ActiveSupport::Notifications.instrument("transmit.action_cable", payload) do
+            connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, message: data)
+          end
         end
 
         def defer_subscription_confirmation!
@@ -264,9 +270,10 @@ module ActionCable
 
         def transmit_subscription_confirmation
           unless subscription_confirmation_sent?
-            logger.info "#{self.class.name} is transmitting the subscription confirmation"
-            connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:confirmation])
-            @subscription_confirmation_sent = true
+            ActiveSupport::Notifications.instrument("transmit_subscription_confirmation.action_cable", channel_class: self.class.name) do
+              connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:confirmation])
+              @subscription_confirmation_sent = true
+            end
           end
         end
 
@@ -276,8 +283,9 @@ module ActionCable
         end
 
         def transmit_subscription_rejection
-          logger.info "#{self.class.name} is transmitting the subscription rejection"
-          connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:rejection])
+          ActiveSupport::Notifications.instrument("transmit_subscription_rejection.action_cable", channel_class: self.class.name) do
+            connection.transmit ActiveSupport::JSON.encode(identifier: @identifier, type: ActionCable::INTERNAL[:message_types][:rejection])
+          end
         end
     end
   end
diff --git a/actioncable/lib/action_cable/channel/log_subscriber.rb b/actioncable/lib/action_cable/channel/log_subscriber.rb
new file mode 100644
index 0000000000..d58b017e0e
--- /dev/null
+++ b/actioncable/lib/action_cable/channel/log_subscriber.rb
@@ -0,0 +1,40 @@
+require 'active_support/log_subscriber'
+
+module ActionCable
+  module Channel
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def perform_action(event)
+        info do
+          channel_class = event.payload[:channel_class]
+          action = event.payload[:action]
+          "Completed #{channel_class}##{action} in #{event.duration.round}ms"
+        end
+      end
+
+      def transmit(event)
+        info do
+          channel_class = event.payload[:channel_class]
+          data = event.payload[:data]
+          via = event.payload[:via]
+          "#{channel_class} transmitting #{data.inspect.truncate(300)}".tap { |m| m << " (via #{via})" if via }
+        end
+      end
+
+      def transmit_subscription_confirmation(event)
+        info do
+          channel_class = event.payload[:channel_class]
+          "#{channel_class} is transmitting the subscription confirmation"
+        end
+      end
+
+      def transmit_subscription_rejection(event)
+        info do
+          channel_class = event.payload[:channel_class]
+          "#{channel_class} is transmitting the subscription rejection"
+        end
+      end
+    end
+  end
+end
+
+ActionCable::Channel::LogSubscriber.attach_to :action_cable