Merge pull request #23723 from mwear/action_cable_notifications

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

actioncable/CHANGELOG.md

+*  Add ActiveSupport::Notifications and ActiveSupport::LogSubscriber to ActionCable::Channel
+
+   *Matthew Wear*
+
 *   Allow channel identifiers with no backslahes/escaping to be accepted
     by the subscription storer.
 

actioncable/lib/action_cable/channel/base.rb

+require 'action_cable/channel/log_subscriber'
 require 'set'
 
 module ActionCable
@@ -160,7 +161,10 @@ def perform_action(data)
         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 @@ def unsubscribed
         # 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 @@ def action_signature(action, data)
 
         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 @@ def reject_subscription
         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

actioncable/lib/action_cable/channel/log_subscriber.rb

+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

actioncable/test/channel/base_test.rb

@@ -166,6 +166,81 @@ def rm_rf
     end
   end
 
+  test "notification for perform_action" do
+    begin
+      events = []
+      ActiveSupport::Notifications.subscribe "perform_action.action_cable" do |*args|
+        events << ActiveSupport::Notifications::Event.new(*args)
+      end
+
+      data = {'action' => :speak, 'content' => 'hello'}
+      @channel.perform_action data
+
+      assert_equal 1, events.length
+      assert_equal 'perform_action.action_cable', events[0].name
+      assert_equal 'ActionCable::Channel::BaseTest::ChatChannel', events[0].payload[:channel_class]
+      assert_equal :speak, events[0].payload[:action]
+      assert_equal data, events[0].payload[:data]
+    ensure
+      ActiveSupport::Notifications.unsubscribe "perform_action.action_cable"
+    end
+  end
+
+  test "notification for transmit" do
+    begin
+      events = []
+      ActiveSupport::Notifications.subscribe 'transmit.action_cable' do |*args|
+        events << ActiveSupport::Notifications::Event.new(*args)
+      end
+
+      @channel.perform_action 'action' => :get_latest
+      expected_data = {data: 'latest'}
+
+      assert_equal 1, events.length
+      assert_equal 'transmit.action_cable', events[0].name
+      assert_equal 'ActionCable::Channel::BaseTest::ChatChannel', events[0].payload[:channel_class]
+      assert_equal expected_data, events[0].payload[:data]
+      assert_nil events[0].payload[:via]
+    ensure
+      ActiveSupport::Notifications.unsubscribe 'transmit.action_cable'
+    end
+  end
+
+  test "notification for transmit_subscription_confirmation" do
+    begin
+      events = []
+      ActiveSupport::Notifications.subscribe 'transmit_subscription_confirmation.action_cable' do |*args|
+        events << ActiveSupport::Notifications::Event.new(*args)
+      end
+
+      @channel.stubs(:subscription_confirmation_sent?).returns(false)
+      @channel.send(:transmit_subscription_confirmation)
+
+      assert_equal 1, events.length
+      assert_equal 'transmit_subscription_confirmation.action_cable', events[0].name
+      assert_equal 'ActionCable::Channel::BaseTest::ChatChannel', events[0].payload[:channel_class]
+    ensure
+      ActiveSupport::Notifications.unsubscribe 'transmit_subscription_confirmation.action_cable'
+    end
+  end
+
+  test "notification for transmit_subscription_rejection" do
+    begin
+      events = []
+      ActiveSupport::Notifications.subscribe 'transmit_subscription_rejection.action_cable' do |*args|
+        events << ActiveSupport::Notifications::Event.new(*args)
+      end
+
+      @channel.send(:transmit_subscription_rejection)
+
+      assert_equal 1, events.length
+      assert_equal 'transmit_subscription_rejection.action_cable', events[0].name
+      assert_equal 'ActionCable::Channel::BaseTest::ChatChannel', events[0].payload[:channel_class]
+    ensure
+      ActiveSupport::Notifications.unsubscribe 'transmit_subscription_rejection.action_cable'
+    end
+  end
+
   private
     def assert_logged(message)
       old_logger = @connection.logger

actioncable/test/channel/log_subscriber_test.rb

+require 'test_helper'
+require 'stubs/test_connection'
+require 'active_support/log_subscriber/test_helper'
+require 'action_cable/channel/log_subscriber'
+
+class ActionCable::Channel::LogSubscriberTest < ActiveSupport::TestCase
+  include ActiveSupport::LogSubscriber::TestHelper
+
+  class ChatChannel < ActionCable::Channel::Base
+    attr_reader :last_action
+
+    def speak(data)
+      @last_action = [ :speak, data ]
+    end
+
+    def get_latest
+      transmit data: 'latest'
+    end
+  end
+
+  def setup
+    super
+    @connection = TestConnection.new
+    @channel = ChatChannel.new @connection, "{id: 1}", { id: 1 }
+    ActionCable::Channel::LogSubscriber.attach_to :action_cable
+  end
+
+  def test_perform_action
+    data = {'action' => :speak, 'content' => 'hello'}
+    @channel.perform_action(data)
+    wait
+
+    assert_equal(1, logs.size)
+    assert_match(/Completed #{channel_class}#speak in \d+ms/, logs.first)
+  end
+
+  def test_transmit
+    @channel.perform_action('action' => :get_latest)
+    wait
+
+    assert_equal(2, logs.size)
+    assert_match(/^#{channel_class} transmitting/, logs.first)
+  end
+
+  def test_transmit_subscription_confirmation
+    @channel.stubs(:subscription_confirmation_sent?).returns(false)
+    @channel.send(:transmit_subscription_confirmation)
+    wait
+
+    assert_equal(1, logs.size)
+    assert_equal("#{channel_class} is transmitting the subscription confirmation", logs.first)
+  end
+
+  def test_transmit_subscription_rejection
+    @channel.send(:transmit_subscription_rejection)
+    wait
+
+    assert_equal(1, logs.size)
+    assert_equal("#{channel_class} is transmitting the subscription rejection", logs.first)
+  end
+
+  def channel_class
+    "ActionCable::Channel::LogSubscriberTest::ChatChannel"
+  end
+
+  def logs
+    @logs ||= @logger.logged(:info)
+  end
+end