diff options
| -rw-r--r-- | actioncable/CHANGELOG.md | 4 | ||||
| -rw-r--r-- | actioncable/lib/action_cable/channel/base.rb | 24 | ||||
| -rw-r--r-- | actioncable/lib/action_cable/channel/log_subscriber.rb | 40 | ||||
| -rw-r--r-- | actioncable/test/channel/base_test.rb | 75 | ||||
| -rw-r--r-- | actioncable/test/channel/log_subscriber_test.rb | 69 |
5 files changed, 204 insertions, 8 deletions
diff --git a/actioncable/CHANGELOG.md b/actioncable/CHANGELOG.md index fb9e498e49..db69766c40 100644 --- a/actioncable/CHANGELOG.md +++ b/actioncable/CHANGELOG.md @@ -1,3 +1,7 @@ +* 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. 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 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 |