Add AS::Notifications and LogSubscriber to ActionCable::Channel

This commit adds ActiveSupport::Notifications instrumentation hooks
and a LogSuscriber to ActionCable::Channel::Base.

2 files changed, 144 insertions, 0 deletions

diff --git a/actioncable/test/channel/base_test.rb b/actioncable/test/channel/base_test.rb
index d41bf3064b..bed54eb6b3 100644
--- a/actioncable/test/channel/base_test.rb
+++ b/actioncable/test/channel/base_test.rb
@@ -166,6 +166,81 @@ class ActionCable::Channel::BaseTest < ActiveSupport::TestCase
     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
diff --git a/actioncable/test/channel/log_subscriber_test.rb b/actioncable/test/channel/log_subscriber_test.rb
new file mode 100644
index 0000000000..18acdc9fbd
--- /dev/null
+++ b/actioncable/test/channel/log_subscriber_test.rb
@@ -0,0 +1,69 @@
+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