Merge pull request #23813 from lifo/faye-websocket

Improve Action Cable reconnection reliability

5 files changed, 51 insertions, 7 deletions

diff --git a/actioncable/app/assets/javascripts/action_cable.coffee.erb b/actioncable/app/assets/javascripts/action_cable.coffee.erb
index 18a48c0610..d95fe78ac5 100644
--- a/actioncable/app/assets/javascripts/action_cable.coffee.erb
+++ b/actioncable/app/assets/javascripts/action_cable.coffee.erb
@@ -21,3 +21,14 @@
       a.href
     else
       url
+
+  startDebugging: ->
+    @debugging = true
+
+  stopDebugging: ->
+    @debugging = null
+
+  log: (messages...) ->
+    if @debugging
+      messages.push(Date.now())
+      console.log("[ActionCable]", messages...)
diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee
index fbd7dbd35b..ee888f567b 100644
--- a/actioncable/app/assets/javascripts/action_cable/connection.coffee
+++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee
@@ -16,9 +16,12 @@ class ActionCable.Connection
       false
 
   open: =>
-    if @webSocket and not @isState("closed")
+    if @isAlive()
+      ActionCable.log("Attemped to open WebSocket, but existing socket is #{@getState()}")
       throw new Error("Existing connection must be closed before opening")
     else
+      ActionCable.log("Opening WebSocket, current state is #{@getState()}")
+      @uninstallEventHandlers() if @webSocket?
       @webSocket = new WebSocket(@consumer.url)
       @installEventHandlers()
       true
@@ -27,19 +30,26 @@ class ActionCable.Connection
     @webSocket?.close()
 
   reopen: ->
-    if @isState("closed")
-      @open()
-    else
+    ActionCable.log("Reopening WebSocket, current state is #{@getState()}")
+    if @isAlive()
       try
         @close()
+      catch error
+        ActionCable.log("Failed to reopen WebSocket", error)
       finally
+        ActionCable.log("Reopening WebSocket in #{@constructor.reopenDelay}ms")
         setTimeout(@open, @constructor.reopenDelay)
+    else
+      @open()
 
   isOpen: ->
     @isState("open")
 
   # Private
 
+  isAlive: ->
+    @webSocket? and not @isState("closing", "closed")
+
   isState: (states...) ->
     @getState() in states
 
@@ -53,6 +63,11 @@ class ActionCable.Connection
       @webSocket["on#{eventName}"] = handler
     return
 
+  uninstallEventHandlers: ->
+    for eventName of @events
+      @webSocket["on#{eventName}"] = ->
+    return
+
   events:
     message: (event) ->
       {identifier, message, type} = JSON.parse(event.data)
@@ -66,13 +81,16 @@ class ActionCable.Connection
           @consumer.subscriptions.notify(identifier, "received", message)
 
     open: ->
+      ActionCable.log("WebSocket onopen event")
       @disconnected = false
       @consumer.subscriptions.reload()
 
     close: ->
+      ActionCable.log("WebSocket onclose event")
       @disconnect()
 
     error: ->
+      ActionCable.log("WebSocket onerror event")
       @disconnect()
 
   disconnect: ->
diff --git a/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee b/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee
index 99b9a1c6d5..75a6f1fb07 100644
--- a/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee
+++ b/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee
@@ -17,6 +17,7 @@ class ActionCable.ConnectionMonitor
     @reset()
     @pingedAt = now()
     delete @disconnectedAt
+    ActionCable.log("ConnectionMonitor connected")
 
   disconnected: ->
     @disconnectedAt = now()
@@ -33,10 +34,12 @@ class ActionCable.ConnectionMonitor
     @startedAt = now()
     @poll()
     document.addEventListener("visibilitychange", @visibilityDidChange)
+    ActionCable.log("ConnectionMonitor started, pollInterval is #{@getInterval()}ms")
 
   stop: ->
     @stoppedAt = now()
     document.removeEventListener("visibilitychange", @visibilityDidChange)
+    ActionCable.log("ConnectionMonitor stopped")
 
   poll: ->
     setTimeout =>
@@ -52,8 +55,12 @@ class ActionCable.ConnectionMonitor
 
   reconnectIfStale: ->
     if @connectionIsStale()
+      ActionCable.log("ConnectionMonitor detected stale connection, reconnectAttempts = #{@reconnectAttempts}")
       @reconnectAttempts++
-      unless @disconnectedRecently()
+      if @disconnectedRecently()
+        ActionCable.log("ConnectionMonitor skipping reopen because recently disconnected at #{@disconnectedAt}")
+      else
+        ActionCable.log("ConnectionMonitor reopening")
         @consumer.connection.reopen()
 
   connectionIsStale: ->
@@ -66,6 +73,7 @@ class ActionCable.ConnectionMonitor
     if document.visibilityState is "visible"
       setTimeout =>
         if @connectionIsStale() or not @consumer.connection.isOpen()
+          ActionCable.log("ConnectionMonitor reopening stale connection after visibilitychange to #{document.visibilityState}")
           @consumer.connection.reopen()
       , 200
 
diff --git a/actioncable/lib/action_cable/connection/base.rb b/actioncable/lib/action_cable/connection/base.rb
index 06706860c2..60f3ad3e06 100644
--- a/actioncable/lib/action_cable/connection/base.rb
+++ b/actioncable/lib/action_cable/connection/base.rb
@@ -154,7 +154,7 @@ module ActionCable
         def handle_open
           connect if respond_to?(:connect)
           subscribe_to_internal_channel
-          beat
+          confirm_connection_monitor_subscription
 
           message_buffer.process!
           server.add_connection(self)
@@ -173,6 +173,13 @@ module ActionCable
           disconnect if respond_to?(:disconnect)
         end
 
+        def confirm_connection_monitor_subscription
+          # Send confirmation message to the internal connection monitor channel.
+          # This ensures the connection monitor state is reset after a successful
+          # websocket connection.
+          transmit ActiveSupport::JSON.encode(identifier: ActionCable::INTERNAL[:identifiers][:ping], type: ActionCable::INTERNAL[:message_types][:confirmation])
+        end
+
         def allow_request_origin?
           return true if server.config.disable_request_forgery_protection
 
diff --git a/actioncable/test/connection/base_test.rb b/actioncable/test/connection/base_test.rb
index e2b017a9a1..3bef9e95a1 100644
--- a/actioncable/test/connection/base_test.rb
+++ b/actioncable/test/connection/base_test.rb
@@ -56,7 +56,7 @@ class ActionCable::Connection::BaseTest < ActionCable::TestCase
     run_in_eventmachine do
       connection = open_connection
 
-      connection.websocket.expects(:transmit).with(regexp_matches(/\_ping/))
+      connection.websocket.expects(:transmit).with({ identifier: "_ping", type: "confirm_subscription" }.to_json)
       connection.message_buffer.expects(:process!)
 
       connection.process