From de8390959664eaccf3453d69be5fa8ce09f97297 Mon Sep 17 00:00:00 2001
From: Pratik Naik <pratiknaik@gmail.com>
Date: Tue, 7 Apr 2015 16:32:45 -0500
Subject: [PATCH] Log request start and finish

---
 lib/action_cable/connection/base.rb | 34 +++++++++++++++++++++++++++--
 1 file changed, 32 insertions(+), 2 deletions(-)

diff --git a/lib/action_cable/connection/base.rb b/lib/action_cable/connection/base.rb
index 4ad1e7d065b68..2e62c78bee6b7 100644
--- a/lib/action_cable/connection/base.rb
+++ b/lib/action_cable/connection/base.rb
@@ -16,7 +16,9 @@ def initialize(server, env)
       end
 
       def process
-        if Faye::WebSocket.websocket?(@env)
+        logger.info "[ActionCable] #{started_request_message}"
+
+        if websocket?
           @subscriptions = {}
 
           @websocket = Faye::WebSocket.new(@env)
@@ -40,6 +42,8 @@ def process
           end
 
           @websocket.on(:close) do |event|
+            logger.info "[ActionCable] #{finished_request_message}"
+
             worker_pool.async.invoke(self, :cleanup_subscriptions)
             worker_pool.async.invoke(self, :cleanup_internal_redis_subscriptions)
             worker_pool.async.invoke(self, :disconnect) if respond_to?(:disconnect)
@@ -75,7 +79,7 @@ def cleanup_subscriptions
       end
 
       def broadcast(data)
-        logger.info "Sending data: #{data}"
+        logger.info "[ActionCable] Sending data: #{data}"
         @websocket.send data
       end
 
@@ -133,6 +137,7 @@ def unsubscribe_channel(data)
         end
 
         def invalid_request
+          logger.info "[ActionCable] #{finished_request_message}"
           [404, {'Content-Type' => 'text/plain'}, ['Page not found']]
         end
 
@@ -140,6 +145,31 @@ def websocket_alive?
           @websocket && @websocket.ready_state == Faye::WebSocket::API::OPEN
         end
 
+        def request
+          @request ||= ActionDispatch::Request.new(env)
+        end
+
+        def websocket?
+          @is_websocket ||= Faye::WebSocket.websocket?(@env)
+        end
+
+        def started_request_message
+          'Started %s "%s"%s for %s at %s' % [
+            request.request_method,
+            request.filtered_path,
+            websocket? ? ' [Websocket]' : '',
+            request.ip,
+            Time.now.to_default_s ]
+        end
+
+        def finished_request_message
+          'Finished "%s"%s for %s at %s' % [
+            request.filtered_path,
+            websocket? ? ' [Websocket]' : '',
+            request.ip,
+            Time.now.to_default_s ]
+        end
+
     end
   end
 end