Tag log entries with the request id

5 files changed, 45 insertions, 34 deletions

diff --git a/lib/action_cable/channel/base.rb b/lib/action_cable/channel/base.rb
index 8ee99649f4..37399c8101 100644
--- a/lib/action_cable/channel/base.rb
+++ b/lib/action_cable/channel/base.rb
@@ -11,6 +11,7 @@ module ActionCable
       on_unsubscribe :disconnect
 
       attr_reader :params, :connection
+      delegate :log_info, :log_error, to: :connection
 
       class_attribute :channel_name
 
@@ -40,7 +41,7 @@ module ActionCable
           if respond_to?(:receive)
             receive(data)
           else
-            logger.error "[ActionCable] #{self.class.name} received data (#{data}) but #{self.class.name}#receive callback is not defined"
+            log_error "#{self.class.name} received data (#{data}) but #{self.class.name}#receive callback is not defined"
           end
         else
           unauthorized
@@ -66,7 +67,7 @@ module ActionCable
         end
 
         def unauthorized
-          logger.error "[ActionCable] Unauthorized access to #{self.class.name}"
+          log_error "Unauthorized access to #{self.class.name}"
         end
 
         def connect
@@ -101,10 +102,6 @@ module ActionCable
           connection.worker_pool
         end
 
-        def logger
-          connection.logger
-        end
-
     end
 
   end
diff --git a/lib/action_cable/channel/redis.rb b/lib/action_cable/channel/redis.rb
index fda55ec45d..197cf03c8e 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 ]
 
-        logger.info "[ActionCable] Subscribing to the redis channel: #{redis_channel}"
+        log_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|
-              logger.info "[ActionCable] Unsubscribing from the redis channel: #{channel}"
+              log_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
-            logger.info "[ActionCable] Received a message over the redis channel: #{channel} (#{message})"
+            log_info "Received a message over the redis channel: #{channel} (#{message})"
             broadcast ActiveSupport::JSON.decode(message)
           end
         end
diff --git a/lib/action_cable/connection/base.rb b/lib/action_cable/connection/base.rb
index 655e74ee01..2ab62092af 100644
--- a/lib/action_cable/connection/base.rb
+++ b/lib/action_cable/connection/base.rb
@@ -13,7 +13,8 @@ module ActionCable
       end
 
       attr_reader :env, :server
-      delegate :worker_pool, :pubsub, :logger, to: :server
+      attr_accessor :log_tags
+      delegate :worker_pool, :pubsub, to: :server
 
       def initialize(server, env)
         @started_at = Time.now
@@ -23,10 +24,11 @@ module ActionCable
         @accept_messages = false
         @pending_messages = []
         @subscriptions = {}
+        @log_tags = [ 'ActionCable' ]
       end
 
       def process
-        logger.info "[ActionCable] #{started_request_message}"
+        log_info started_request_message
 
         if websocket?
           @websocket = Faye::WebSocket.new(@env)
@@ -50,7 +52,7 @@ module ActionCable
           end
 
           @websocket.on(:close) do |event|
-            logger.info "[ActionCable] #{finished_request_message}"
+            log_info finished_request_message
 
             worker_pool.async.invoke(self, :on_connection_closed)
             EventMachine.cancel_timer(@ping_timer) if @ping_timer
@@ -84,16 +86,10 @@ module ActionCable
       end
 
       def broadcast(data)
-        logger.info "[ActionCable] Sending data: #{data}"
+        log_info "Sending data: #{data}"
         @websocket.send data
       end
 
-      def handle_exception
-        logger.error "[ActionCable] Closing connection"
-
-        @websocket.close
-      end
-
       def statistics
         {
           identifier: connection_identifier,
@@ -102,7 +98,21 @@ module ActionCable
         }
       end
 
-      private
+      def handle_exception
+        log_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)
 
@@ -132,13 +142,13 @@ module ActionCable
           subscription_klass = server.registered_channels.detect { |channel_klass| channel_klass.find_name == id_options[:channel] }
 
           if subscription_klass
-            logger.info "[ActionCable] Subscribing to channel: #{id_key}"
+            log_info "Subscribing to channel: #{id_key}"
             @subscriptions[id_key] = subscription_klass.new(self, id_key, id_options)
           else
-            logger.error "[ActionCable] Subscription class not found (#{data.inspect})"
+            log_error "Subscription class not found (#{data.inspect})"
           end
         rescue Exception => e
-          logger.error "[ActionCable] Could not subscribe to channel (#{data.inspect})"
+          log_error "Could not subscribe to channel (#{data.inspect})"
           log_exception(e)
         end
 
@@ -146,21 +156,21 @@ module ActionCable
           if @subscriptions[message['identifier']]
             @subscriptions[message['identifier']].receive_data(ActiveSupport::JSON.decode message['data'])
           else
-            logger.error "[ActionCable] Unable to process message because no subscription was found (#{message.inspect})"
+            log_exception "Unable to process message because no subscription was found (#{message.inspect})"
           end
         rescue Exception => e
-          logger.error "[ActionCable] Could not process message (#{message.inspect})"
+          log_error "Could not process message (#{message.inspect})"
           log_exception(e)
         end
 
         def unsubscribe_channel(data)
-          logger.info "[ActionCable] Unsubscribing from channel: #{data['identifier']}"
+          log_info "Unsubscribing from channel: #{data['identifier']}"
           @subscriptions[data['identifier']].unsubscribe
           @subscriptions.delete(data['identifier'])
         end
 
         def invalid_request
-          logger.info "[ActionCable] #{finished_request_message}"
+          log_info "#{finished_request_message}"
           [404, {'Content-Type' => 'text/plain'}, ['Page not found']]
         end
 
@@ -194,8 +204,12 @@ module ActionCable
         end
 
         def log_exception(e)
-          logger.error "[ActionCable] There was an exception - #{e.class}(#{e.message})"
-          logger.error e.backtrace.join("\n")
+          log_error "There was an exception - #{e.class}(#{e.message})"
+          log_error e.backtrace.join("\n")
+        end
+
+        def log(type, message)
+          server.logger.tagged(*log_tags) { server.logger.send type, message }
         end
     end
   end
diff --git a/lib/action_cable/connection/internal_channel.rb b/lib/action_cable/connection/internal_channel.rb
index 745fd99b78..5338fc879e 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)
-          logger.info "[ActionCable] Registered connection (#{connection_identifier})"
+          log_info "Registered connection (#{connection_identifier})"
         end
       end
 
@@ -26,12 +26,12 @@ module ActionCable
 
           case message['type']
           when 'disconnect'
-            logger.info "[ActionCable] Removing connection (#{connection_identifier})"
+            log_info "Removing connection (#{connection_identifier})"
             @websocket.close
           end
         rescue Exception => e
-          logger.error "[ActionCable] There was an exception - #{e.class}(#{e.message})"
-          logger.error e.backtrace.join("\n")
+          log_error "There was an exception - #{e.class}(#{e.message})"
+          log_error e.backtrace.join("\n")
 
           handle_exception
         end
diff --git a/lib/action_cable/worker.rb b/lib/action_cable/worker.rb
index 6773535afe..6800a75d1d 100644
--- a/lib/action_cable/worker.rb
+++ b/lib/action_cable/worker.rb
@@ -10,7 +10,7 @@ module ActionCable
         receiver.send method, *args
       end
     rescue Exception => e
-      logger.error "[ActionCable] There was an exception - #{e.class}(#{e.message})"
+      logger.error "There was an exception - #{e.class}(#{e.message})"
       logger.error e.backtrace.join("\n")
 
       receiver.handle_exception if receiver.respond_to?(:handle_exception)