From 09a1321d5b57111edc273f68f428e4ee5471ed5c Mon Sep 17 00:00:00 2001 From: Matthew Wear Date: Tue, 16 Feb 2016 11:06:35 -0800 Subject: Add AS::Notifications and LogSubscriber to ActionCable::Channel This commit adds ActiveSupport::Notifications instrumentation hooks and a LogSuscriber to ActionCable::Channel::Base. --- actioncable/CHANGELOG.md | 4 ++ actioncable/lib/action_cable/channel/base.rb | 24 ++++--- .../lib/action_cable/channel/log_subscriber.rb | 40 ++++++++++++ actioncable/test/channel/base_test.rb | 75 ++++++++++++++++++++++ actioncable/test/channel/log_subscriber_test.rb | 69 ++++++++++++++++++++ 5 files changed, 204 insertions(+), 8 deletions(-) create mode 100644 actioncable/lib/action_cable/channel/log_subscriber.rb create mode 100644 actioncable/test/channel/log_subscriber_test.rb (limited to 'actioncable') 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 -- cgit v1.2.3 From edbfd10876f938bd04b9034b1e4c4329cd4f2d2b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafael=20Mendon=C3=A7a=20Fran=C3=A7a?= Date: Wed, 30 Mar 2016 00:03:11 -0300 Subject: Keep logging in the ActionCable::Channel::Base To move Action Cable logging to a LoggingSubscriber we need to pass the log tags in the notification payload since Action Cable logging use the Channel instance to tag the logs. --- actioncable/lib/action_cable/channel/base.rb | 7 ++- .../lib/action_cable/channel/log_subscriber.rb | 40 ------------- actioncable/test/channel/log_subscriber_test.rb | 69 ---------------------- 3 files changed, 6 insertions(+), 110 deletions(-) delete mode 100644 actioncable/lib/action_cable/channel/log_subscriber.rb delete mode 100644 actioncable/test/channel/log_subscriber_test.rb (limited to 'actioncable') diff --git a/actioncable/lib/action_cable/channel/base.rb b/actioncable/lib/action_cable/channel/base.rb index a0319eb522..464d0581dd 100644 --- a/actioncable/lib/action_cable/channel/base.rb +++ b/actioncable/lib/action_cable/channel/base.rb @@ -1,4 +1,3 @@ -require 'action_cable/channel/log_subscriber' require 'set' module ActionCable @@ -195,6 +194,8 @@ 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 } + 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) @@ -270,6 +271,8 @@ module ActionCable def transmit_subscription_confirmation unless subscription_confirmation_sent? + logger.info "#{self.class.name} is transmitting the subscription confirmation" + 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 @@ -283,6 +286,8 @@ module ActionCable end def transmit_subscription_rejection + logger.info "#{self.class.name} is transmitting the subscription 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 diff --git a/actioncable/lib/action_cable/channel/log_subscriber.rb b/actioncable/lib/action_cable/channel/log_subscriber.rb deleted file mode 100644 index d58b017e0e..0000000000 --- a/actioncable/lib/action_cable/channel/log_subscriber.rb +++ /dev/null @@ -1,40 +0,0 @@ -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/log_subscriber_test.rb b/actioncable/test/channel/log_subscriber_test.rb deleted file mode 100644 index 18acdc9fbd..0000000000 --- a/actioncable/test/channel/log_subscriber_test.rb +++ /dev/null @@ -1,69 +0,0 @@ -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 -- cgit v1.2.3