From 832f88bdf35f5ac3333f3ccc2100223e32ca034a Mon Sep 17 00:00:00 2001 From: Javan Makhmali Date: Wed, 17 Feb 2016 16:07:21 -0500 Subject: Add client-side console logging to help debug reconnect issues --- .../app/assets/javascripts/action_cable/connection.coffee | 7 +++++++ .../assets/javascripts/action_cable/connection_monitor.coffee | 9 ++++++++- 2 files changed, 15 insertions(+), 1 deletion(-) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee index fbd7dbd35b..866bb20870 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -17,8 +17,10 @@ class ActionCable.Connection open: => if @webSocket and not @isState("closed") + console.log("[cable] Attemped to open WebSocket, but existing socket is #{@getState()}", Date.now()) throw new Error("Existing connection must be closed before opening") else + console.log("[cable] Opening WebSocket", Date.now()) @webSocket = new WebSocket(@consumer.url) @installEventHandlers() true @@ -27,12 +29,14 @@ class ActionCable.Connection @webSocket?.close() reopen: -> + console.log("[cable] Reopening WebSocket, current state is #{@getState()}", Date.now()) if @isState("closed") @open() else try @close() finally + console.log("[cable] Failed to reopen WebSocket, retrying in #{@constructor.reopenDelay}ms", Date.now()) setTimeout(@open, @constructor.reopenDelay) isOpen: -> @@ -66,13 +70,16 @@ class ActionCable.Connection @consumer.subscriptions.notify(identifier, "received", message) open: -> + console.log("[cable] WebSocket onopen event", Date.now()) @disconnected = false @consumer.subscriptions.reload() close: -> + console.log("[cable] WebSocket onclose event", Date.now()) @disconnect() error: -> + console.log("[cable] WebSocket onerror event", Date.now()) @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..e92a43688a 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee @@ -33,10 +33,12 @@ class ActionCable.ConnectionMonitor @startedAt = now() @poll() document.addEventListener("visibilitychange", @visibilityDidChange) + console.log("[cable] ConnectionMonitor started, pollInterval is #{@getInterval()}ms", Date.now()) stop: -> @stoppedAt = now() document.removeEventListener("visibilitychange", @visibilityDidChange) + console.log("[cable] ConnectionMonitor stopped", Date.now()) poll: -> setTimeout => @@ -52,8 +54,12 @@ class ActionCable.ConnectionMonitor reconnectIfStale: -> if @connectionIsStale() + console.log("[cable] ConnectionMonitor detected stale connection, reconnectAttempts = #{@reconnectAttempts}", Date.now()) @reconnectAttempts++ - unless @disconnectedRecently() + if @disconnectedRecently() + console.log("[cable] ConnectionMonitor skipping repopen because recently disconnected at #{@disconnectedAt}", Date.now()) + else + console.log("[cable] ConnectionMonitor reopening", Date.now()) @consumer.connection.reopen() connectionIsStale: -> @@ -66,6 +72,7 @@ class ActionCable.ConnectionMonitor if document.visibilityState is "visible" setTimeout => if @connectionIsStale() or not @consumer.connection.isOpen() + console.log("[cable] ConnectionMonitor reopening stale connection after visibilitychange", Date.now()) @consumer.connection.reopen() , 200 -- cgit v1.2.3 From 725c913c902902d84a595760cd9fdb933cfa824d Mon Sep 17 00:00:00 2001 From: Pratik Naik Date: Thu, 18 Feb 2016 14:38:22 -0600 Subject: Treat 'closing' state as closed. We are seeing cases where the websockets get stuck in the 'closing' state after a tab has been in background for a while. So lets treat those websockets as closed. --- .../app/assets/javascripts/action_cable/connection.coffee | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee index 866bb20870..b1343a111c 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -16,11 +16,11 @@ class ActionCable.Connection false open: => - if @webSocket and not @isState("closed") + if @webSocket and not @isClosed() console.log("[cable] Attemped to open WebSocket, but existing socket is #{@getState()}", Date.now()) throw new Error("Existing connection must be closed before opening") else - console.log("[cable] Opening WebSocket", Date.now()) + console.log("[cable] Opening WebSocket, current state is #{@getState()}", Date.now()) @webSocket = new WebSocket(@consumer.url) @installEventHandlers() true @@ -30,7 +30,7 @@ class ActionCable.Connection reopen: -> console.log("[cable] Reopening WebSocket, current state is #{@getState()}", Date.now()) - if @isState("closed") + if @isClosed() @open() else try @@ -44,6 +44,9 @@ class ActionCable.Connection # Private + isClosed: -> + @isState("closing", "closed") + isState: (states...) -> @getState() in states -- cgit v1.2.3 From 426676e8d0fdde079406e35f6bc13c8c20bd8a92 Mon Sep 17 00:00:00 2001 From: Pratik Naik Date: Thu, 18 Feb 2016 18:17:17 -0600 Subject: Confirm connection monitor subscription on open --- actioncable/lib/action_cable/connection/base.rb | 9 ++++++++- actioncable/test/connection/base_test.rb | 2 +- 2 files changed, 9 insertions(+), 2 deletions(-) (limited to 'actioncable') diff --git a/actioncable/lib/action_cable/connection/base.rb b/actioncable/lib/action_cable/connection/base.rb index 1acef93025..ea7513e72b 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 -- cgit v1.2.3 From 96118db3354553399754600fabe21468b13c078a Mon Sep 17 00:00:00 2001 From: Pratik Naik Date: Thu, 18 Feb 2016 18:27:48 -0600 Subject: Log ConnectionMonitor connect --- .../app/assets/javascripts/action_cable/connection_monitor.coffee | 1 + 1 file changed, 1 insertion(+) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee b/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee index e92a43688a..3216408430 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 + console.log("[cable] ConnectionMonitor connected", Date.now()) disconnected: -> @disconnectedAt = now() -- cgit v1.2.3 From ab28276713af8503b667ecbc8c1672c187e944d7 Mon Sep 17 00:00:00 2001 From: Javan Makhmali Date: Fri, 19 Feb 2016 10:24:17 -0500 Subject: Connection#isAlive --- actioncable/app/assets/javascripts/action_cable/connection.coffee | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee index b1343a111c..78028bda3c 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -16,7 +16,7 @@ class ActionCable.Connection false open: => - if @webSocket and not @isClosed() + if @isAlive() console.log("[cable] Attemped to open WebSocket, but existing socket is #{@getState()}", Date.now()) throw new Error("Existing connection must be closed before opening") else @@ -44,8 +44,8 @@ class ActionCable.Connection # Private - isClosed: -> - @isState("closing", "closed") + isAlive: -> + not @isState("closing", "closed") isState: (states...) -> @getState() in states -- cgit v1.2.3 From 1a90ff9a4d43b118448fcad72d547074c1efb2fb Mon Sep 17 00:00:00 2001 From: Javan Makhmali Date: Fri, 19 Feb 2016 10:26:41 -0500 Subject: Uninstall event handlers when replacing WebSocket instance Ensures we don't get "onclose" events from a previous WebSocket that was in the "closing" state --- actioncable/app/assets/javascripts/action_cable/connection.coffee | 6 ++++++ 1 file changed, 6 insertions(+) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee index 78028bda3c..a67ad6e915 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -21,6 +21,7 @@ class ActionCable.Connection throw new Error("Existing connection must be closed before opening") else console.log("[cable] Opening WebSocket, current state is #{@getState()}", Date.now()) + @uninstallEventHandlers() if @webSocket? @webSocket = new WebSocket(@consumer.url) @installEventHandlers() true @@ -60,6 +61,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) -- cgit v1.2.3 From dde833816a46c2738fa40af179751e9162a468eb Mon Sep 17 00:00:00 2001 From: Javan Makhmali Date: Fri, 19 Feb 2016 10:48:50 -0500 Subject: ActionCable.log --- actioncable/app/assets/javascripts/action_cable.coffee.erb | 11 +++++++++++ .../app/assets/javascripts/action_cable/connection.coffee | 14 +++++++------- .../javascripts/action_cable/connection_monitor.coffee | 14 +++++++------- 3 files changed, 25 insertions(+), 14 deletions(-) (limited to 'actioncable') 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 a67ad6e915..39277255f7 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -17,10 +17,10 @@ class ActionCable.Connection open: => if @isAlive() - console.log("[cable] Attemped to open WebSocket, but existing socket is #{@getState()}", Date.now()) + ActionCable.log("Attemped to open WebSocket, but existing socket is #{@getState()}") throw new Error("Existing connection must be closed before opening") else - console.log("[cable] Opening WebSocket, current state is #{@getState()}", Date.now()) + ActionCable.log("Opening WebSocket, current state is #{@getState()}") @uninstallEventHandlers() if @webSocket? @webSocket = new WebSocket(@consumer.url) @installEventHandlers() @@ -30,14 +30,14 @@ class ActionCable.Connection @webSocket?.close() reopen: -> - console.log("[cable] Reopening WebSocket, current state is #{@getState()}", Date.now()) + ActionCable.log("Reopening WebSocket, current state is #{@getState()}") if @isClosed() @open() else try @close() finally - console.log("[cable] Failed to reopen WebSocket, retrying in #{@constructor.reopenDelay}ms", Date.now()) + ActionCable.log("Failed to reopen WebSocket, retrying in #{@constructor.reopenDelay}ms") setTimeout(@open, @constructor.reopenDelay) isOpen: -> @@ -79,16 +79,16 @@ class ActionCable.Connection @consumer.subscriptions.notify(identifier, "received", message) open: -> - console.log("[cable] WebSocket onopen event", Date.now()) + ActionCable.log("WebSocket onopen event") @disconnected = false @consumer.subscriptions.reload() close: -> - console.log("[cable] WebSocket onclose event", Date.now()) + ActionCable.log("WebSocket onclose event") @disconnect() error: -> - console.log("[cable] WebSocket onerror event", Date.now()) + 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 3216408430..75a6f1fb07 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection_monitor.coffee @@ -17,7 +17,7 @@ class ActionCable.ConnectionMonitor @reset() @pingedAt = now() delete @disconnectedAt - console.log("[cable] ConnectionMonitor connected", Date.now()) + ActionCable.log("ConnectionMonitor connected") disconnected: -> @disconnectedAt = now() @@ -34,12 +34,12 @@ class ActionCable.ConnectionMonitor @startedAt = now() @poll() document.addEventListener("visibilitychange", @visibilityDidChange) - console.log("[cable] ConnectionMonitor started, pollInterval is #{@getInterval()}ms", Date.now()) + ActionCable.log("ConnectionMonitor started, pollInterval is #{@getInterval()}ms") stop: -> @stoppedAt = now() document.removeEventListener("visibilitychange", @visibilityDidChange) - console.log("[cable] ConnectionMonitor stopped", Date.now()) + ActionCable.log("ConnectionMonitor stopped") poll: -> setTimeout => @@ -55,12 +55,12 @@ class ActionCable.ConnectionMonitor reconnectIfStale: -> if @connectionIsStale() - console.log("[cable] ConnectionMonitor detected stale connection, reconnectAttempts = #{@reconnectAttempts}", Date.now()) + ActionCable.log("ConnectionMonitor detected stale connection, reconnectAttempts = #{@reconnectAttempts}") @reconnectAttempts++ if @disconnectedRecently() - console.log("[cable] ConnectionMonitor skipping repopen because recently disconnected at #{@disconnectedAt}", Date.now()) + ActionCable.log("ConnectionMonitor skipping reopen because recently disconnected at #{@disconnectedAt}") else - console.log("[cable] ConnectionMonitor reopening", Date.now()) + ActionCable.log("ConnectionMonitor reopening") @consumer.connection.reopen() connectionIsStale: -> @@ -73,7 +73,7 @@ class ActionCable.ConnectionMonitor if document.visibilityState is "visible" setTimeout => if @connectionIsStale() or not @consumer.connection.isOpen() - console.log("[cable] ConnectionMonitor reopening stale connection after visibilitychange", Date.now()) + ActionCable.log("ConnectionMonitor reopening stale connection after visibilitychange to #{document.visibilityState}") @consumer.connection.reopen() , 200 -- cgit v1.2.3 From c889408e0d01f7d4fb061dbc53a2426bd359496c Mon Sep 17 00:00:00 2001 From: Javan Makhmali Date: Fri, 19 Feb 2016 10:57:43 -0500 Subject: Fix isAlive condition and add more logging --- .../app/assets/javascripts/action_cable/connection.coffee | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) (limited to 'actioncable') diff --git a/actioncable/app/assets/javascripts/action_cable/connection.coffee b/actioncable/app/assets/javascripts/action_cable/connection.coffee index 39277255f7..ee888f567b 100644 --- a/actioncable/app/assets/javascripts/action_cable/connection.coffee +++ b/actioncable/app/assets/javascripts/action_cable/connection.coffee @@ -31,14 +31,16 @@ class ActionCable.Connection reopen: -> ActionCable.log("Reopening WebSocket, current state is #{@getState()}") - if @isClosed() - @open() - else + if @isAlive() try @close() + catch error + ActionCable.log("Failed to reopen WebSocket", error) finally - ActionCable.log("Failed to reopen WebSocket, retrying in #{@constructor.reopenDelay}ms") + ActionCable.log("Reopening WebSocket in #{@constructor.reopenDelay}ms") setTimeout(@open, @constructor.reopenDelay) + else + @open() isOpen: -> @isState("open") @@ -46,7 +48,7 @@ class ActionCable.Connection # Private isAlive: -> - not @isState("closing", "closed") + @webSocket? and not @isState("closing", "closed") isState: (states...) -> @getState() in states -- cgit v1.2.3