Add a tagged proxy logger to handle per connection tags

6 files changed, 59 insertions, 35 deletions

diff --git a/lib/action_cable/channel/base.rb b/lib/action_cable/channel/base.rb
index 37399c8101..fac988ba52 100644
--- a/lib/action_cable/channel/base.rb
+++ b/lib/action_cable/channel/base.rb
@@ -11,7 +11,7 @@ module ActionCable
       on_unsubscribe :disconnect
 
       attr_reader :params, :connection
-      delegate :log_info, :log_error, to: :connection
+      delegate :logger, to: :connection
 
       class_attribute :channel_name
 
@@ -41,7 +41,7 @@ module ActionCable
           if respond_to?(:receive)
             receive(data)
           else
-            log_error "#{self.class.name} received data (#{data}) but #{self.class.name}#receive callback is not defined"
+            logger.error "#{self.class.name} received data (#{data}) but #{self.class.name}#receive callback is not defined"
           end
         else
           unauthorized
@@ -67,7 +67,7 @@ module ActionCable
         end
 
         def unauthorized
-          log_error "Unauthorized access to #{self.class.name}"
+          logger.error "Unauthorized access to #{self.class.name}"
         end
 
         def connect
diff --git a/lib/action_cable/channel/redis.rb b/lib/action_cable/channel/redis.rb
index 197cf03c8e..cbc3512072 100644
--- a/lib/action_cable/channel/redis.rb
+++ b/lib/action_cable/channel/redis.rb
@@ -14,7 +14,7 @@ module ActionCable
         @_redis_channels ||= []
         @_redis_channels << [ redis_channel, callback ]
 
-        log_info "Subscribing to the redis channel: #{redis_channel}"
+        logger.info "Subscribing to the redis channel: #{redis_channel}"
         pubsub.subscribe(redis_channel, &callback)
       end
 
@@ -22,7 +22,7 @@ module ActionCable
         def unsubscribe_from_redis_channels
           if @_redis_channels
             @_redis_channels.each do |channel, callback|
-              log_info "Unsubscribing from the redis channel: #{channel}"
+              logger.info "Unsubscribing from the redis channel: #{channel}"
               pubsub.unsubscribe_proc(channel, callback)
             end
           end
@@ -30,7 +30,7 @@ module ActionCable
 
         def default_subscription_callback(channel)
           -> (message) do
-            log_info "Received a message over the redis channel: #{channel} (#{message})"
+            logger.info "Received a message over the redis channel: #{channel} (#{message})"
             broadcast ActiveSupport::JSON.decode(message)
           end
         end
diff --git a/lib/action_cable/connection.rb b/lib/action_cable/connection.rb
index 665a851b11..a9048926e4 100644
--- a/lib/action_cable/connection.rb
+++ b/lib/action_cable/connection.rb
@@ -3,5 +3,6 @@ module ActionCable
     autoload :Base, 'action_cable/connection/base'
     autoload :InternalChannel, 'action_cable/connection/internal_channel'
     autoload :Identifier, 'action_cable/connection/identifier'
+    autoload :TaggedLoggerProxy, 'action_cable/connection/tagged_logger_proxy'
   end
 end
diff --git a/lib/action_cable/connection/base.rb b/lib/action_cable/connection/base.rb
index 2ab62092af..e8126f3d75 100644
--- a/lib/action_cable/connection/base.rb
+++ b/lib/action_cable/connection/base.rb
@@ -12,8 +12,7 @@ module ActionCable
         self.identifiers += identifiers
       end
 
-      attr_reader :env, :server
-      attr_accessor :log_tags
+      attr_reader :env, :server, :logger
       delegate :worker_pool, :pubsub, to: :server
 
       def initialize(server, env)
@@ -24,11 +23,13 @@ module ActionCable
         @accept_messages = false
         @pending_messages = []
         @subscriptions = {}
-        @log_tags = [ 'ActionCable' ]
+
+        @logger = TaggedLoggerProxy.new(server.logger, tags: [ 'ActionCable' ])
+        @logger.add_tags(*logger_tags)
       end
 
       def process
-        log_info started_request_message
+        logger.info started_request_message
 
         if websocket?
           @websocket = Faye::WebSocket.new(@env)
@@ -52,7 +53,7 @@ module ActionCable
           end
 
           @websocket.on(:close) do |event|
-            log_info finished_request_message
+            logger.info finished_request_message
 
             worker_pool.async.invoke(self, :on_connection_closed)
             EventMachine.cancel_timer(@ping_timer) if @ping_timer
@@ -86,7 +87,7 @@ module ActionCable
       end
 
       def broadcast(data)
-        log_info "Sending data: #{data}"
+        logger.info "Sending data: #{data}"
         @websocket.send data
       end
 
@@ -99,19 +100,11 @@ module ActionCable
       end
 
       def handle_exception
-        log_error "Closing connection"
+        logger.error "Closing connection"
 
         @websocket.close
       end
 
-      def log_info(message)
-        log :info, message
-      end
-
-      def log_error(message)
-        log :error, message
-      end
-
       protected
         def initialize_connection
           server.add_connection(self)
@@ -142,13 +135,13 @@ module ActionCable
           subscription_klass = server.registered_channels.detect { |channel_klass| channel_klass.find_name == id_options[:channel] }
 
           if subscription_klass
-            log_info "Subscribing to channel: #{id_key}"
+            logger.info "Subscribing to channel: #{id_key}"
             @subscriptions[id_key] = subscription_klass.new(self, id_key, id_options)
           else
-            log_error "Subscription class not found (#{data.inspect})"
+            logger.error "Subscription class not found (#{data.inspect})"
           end
         rescue Exception => e
-          log_error "Could not subscribe to channel (#{data.inspect})"
+          logger.error "Could not subscribe to channel (#{data.inspect})"
           log_exception(e)
         end
 
@@ -159,18 +152,18 @@ module ActionCable
             log_exception "Unable to process message because no subscription was found (#{message.inspect})"
           end
         rescue Exception => e
-          log_error "Could not process message (#{message.inspect})"
+          logger.error "Could not process message (#{message.inspect})"
           log_exception(e)
         end
 
         def unsubscribe_channel(data)
-          log_info "Unsubscribing from channel: #{data['identifier']}"
+          logger.info "Unsubscribing from channel: #{data['identifier']}"
           @subscriptions[data['identifier']].unsubscribe
           @subscriptions.delete(data['identifier'])
         end
 
         def invalid_request
-          log_info "#{finished_request_message}"
+          logger.info "#{finished_request_message}"
           [404, {'Content-Type' => 'text/plain'}, ['Page not found']]
         end
 
@@ -204,12 +197,12 @@ module ActionCable
         end
 
         def log_exception(e)
-          log_error "There was an exception - #{e.class}(#{e.message})"
-          log_error e.backtrace.join("\n")
+          logger.error "There was an exception - #{e.class}(#{e.message})"
+          logger.error e.backtrace.join("\n")
         end
 
-        def log(type, message)
-          server.logger.tagged(*log_tags) { server.logger.send type, message }
+        def logger_tags
+          []
         end
     end
   end
diff --git a/lib/action_cable/connection/internal_channel.rb b/lib/action_cable/connection/internal_channel.rb
index 5338fc879e..a7d99f4b14 100644
--- a/lib/action_cable/connection/internal_channel.rb
+++ b/lib/action_cable/connection/internal_channel.rb
@@ -10,7 +10,7 @@ module ActionCable
           @_internal_redis_subscriptions << [ internal_redis_channel, callback ]
 
           pubsub.subscribe(internal_redis_channel, &callback)
-          log_info "Registered connection (#{connection_identifier})"
+          logger.info "Registered connection (#{connection_identifier})"
         end
       end
 
@@ -26,12 +26,12 @@ module ActionCable
 
           case message['type']
           when 'disconnect'
-            log_info "Removing connection (#{connection_identifier})"
+            logger.info "Removing connection (#{connection_identifier})"
             @websocket.close
           end
         rescue Exception => e
-          log_error "There was an exception - #{e.class}(#{e.message})"
-          log_error e.backtrace.join("\n")
+          logger.error "There was an exception - #{e.class}(#{e.message})"
+          logger.error e.backtrace.join("\n")
 
           handle_exception
         end
diff --git a/lib/action_cable/connection/tagged_logger_proxy.rb b/lib/action_cable/connection/tagged_logger_proxy.rb
new file mode 100644
index 0000000000..04ea331bde
--- /dev/null
+++ b/lib/action_cable/connection/tagged_logger_proxy.rb
@@ -0,0 +1,30 @@
+module ActionCable
+  module Connection
+    class TaggedLoggerProxy
+
+      def initialize(logger, tags:)
+        @logger = logger
+        @tags = tags.flatten
+      end
+
+      def info(message)
+        log :info, message
+      end
+
+      def error(message)
+        log :error, message
+      end
+
+      def add_tags(*tags)
+        @tags += tags.flatten
+        @tags = @tags.uniq
+      end
+
+      protected
+        def log(type, message)
+          @logger.tagged(*@tags) { @logger.send type, message }
+        end
+
+    end
+  end
+end