Fix #1243 Socket Mode reconnection issue #1465

seratch · 2022-04-13T10:53:44Z

Summary

This pull request resolves #1243

The cause of the issue is that the heartbeat() method can work only when a SocketModeClient receives ping from Slack server. When the connection is unable to receive ping from Slack for some reason (stale connection etc.), the reconnecting logic no longer works.

This pull request adds additional connection validation, which sends ping from SocketModeClient side and checks if the client receives pong from Slack server. If the client does not receive pong for a certain amount of time, the client does reconnection anyway. This is a proven approach in Python and Java SDK.

Requirements (place an `x` in each `[ ]`)

I've read and understood the Contributing Guidelines and have done my best effort to follow them.
I've read and agree to the Code of Conduct.

seratch · 2022-04-13T11:10:33Z

packages/socket-mode/src/SocketModeClient.ts

+
+  /* eslint-disable @typescript-eslint/indent, newline-per-chained-call */
+
+  private connectingSubmachine: Configuration<string, string> = Finity.configure()


connectingSubmachine and refreshingSubmachine are mostly the same. Perhaps, we can have a factory method, which returns a new Configuration instance instead of duplicated code. Thoughts? @stevengill

It seems that having the two is the root cause of the reconnection issue. I've removed the refreshingSubmachine and simplified the logic.

This makes a lot of sense! In theory there should be no difference between initially-connecting and reconnecting.

seratch · 2022-04-13T11:11:44Z

packages/socket-mode/src/SocketModeClient.ts

+        }
+        // Start heartbeat to keep track of the websocket connection continuing to be alive
+        this.startPeriodicallySendingPingToSlack();
+        this.startMonitoringPingFromSlack();


This used to be heartbeat(). I've renamed the method to be more specific.

seratch · 2022-04-13T11:11:51Z

packages/socket-mode/src/SocketModeClient.ts

+          this.badConnection = false;
+        }
+        // Start heartbeat to keep track of the websocket connection continuing to be alive
+        this.startPeriodicallySendingPingToSlack();


This is the newly added one.

seratch · 2022-04-13T11:15:51Z

packages/socket-mode/src/SocketModeClient.ts

+    this.logger.debug('Tearing down WebSocket connections finished');
+  }
+
+  private startPeriodicallySendingPingToSlack(): void {


This method is the newly added validation logic.

seratch · 2022-04-13T11:16:00Z

packages/socket-mode/src/SocketModeClient.ts

-  private heartbeat(): void {
-    if (this.pingTimeout !== undefined) {
-      clearTimeout(this.pingTimeout);
+  private startMonitoringPingFromSlack(): void {


seratch · 2022-04-13T11:50:05Z

It seems that the new validation logic does not work in all the possible patterns. I will do more testing and improve the logic tomorrow .

seratch · 2022-04-13T14:02:22Z

packages/socket-mode/src/SocketModeClient.ts

-
+    if (this.clientOptions.retryConfig === undefined) {
+      // For faster retries of apps.connections.open API calls for reconnecting
+      this.clientOptions.retryConfig = { retries: 100, factor: 1.3 };


Improved the interval to run the WSS URL fetching API calls.

seratch · 2022-04-13T14:03:11Z

packages/socket-mode/src/SocketModeClient.ts

+        });
+      })
+      .on('server disconnect warning')
+        .transitionTo('connecting').withCondition(() => this.autoReconnectEnabled)


Changed from refreshing-connection to connecting. The whole logic is much simpler now.

seratch · 2022-04-13T14:17:56Z

packages/socket-mode/src/SocketModeClient.ts

      // currently have two websockets, so tear down the older one
      this.websocket.removeAllListeners('open');
      this.websocket.removeAllListeners('close');
      this.websocket.removeAllListeners('error');
      this.websocket.removeAllListeners('message');
+      this.websocket.close();


The old connection needs to be closed.

Ooo good catch

seratch · 2022-04-13T14:18:02Z

packages/socket-mode/src/SocketModeClient.ts

      // only one websocket to tear down
      this.websocket.removeAllListeners('open');
      this.websocket.removeAllListeners('close');
      this.websocket.removeAllListeners('error');
      this.websocket.removeAllListeners('message');
+      this.websocket.close();


Same as above

seratch · 2022-04-13T14:39:16Z

The current revision still does not work in some scenarios. I will check it in detail tomorrow

filmaj

LGTM! The removal of reconnecting logic and consolidating around a single connecting state machine is a great improvement.

I tested by running the simple.js example you provided, seeing the ping/pongs from both the client and the server side, disconnecting my wifi, and after some time reconnecting my wifi. It seemed to work well.

Just for my own education: when the client receives a ping from the server, the client does not respond with a pong - is that correct? Or am I missing something? When watching the debug logs in the simple example, I noticed that for the client-initiated heartbeat, we log out both pings and pongs, but for the server-initiated heartbeat, we only log the pings. Is that by design?

packages/socket-mode/src/SocketModeClient.ts

filmaj · 2022-04-13T14:06:24Z

packages/socket-mode/src/SocketModeClient.ts

+
+  /* eslint-disable @typescript-eslint/indent, newline-per-chained-call */
+
+  private connectingSubmachine: Configuration<string, string> = Finity.configure()


This makes a lot of sense! In theory there should be no difference between initially-connecting and reconnecting.

packages/socket-mode/src/SocketModeClient.ts

filmaj · 2022-04-13T14:28:03Z

packages/socket-mode/src/SocketModeClient.ts

      // currently have two websockets, so tear down the older one
      this.websocket.removeAllListeners('open');
      this.websocket.removeAllListeners('close');
      this.websocket.removeAllListeners('error');
      this.websocket.removeAllListeners('message');
+      this.websocket.close();


Ooo good catch

seratch · 2022-04-14T09:38:52Z

@stevengill @filmaj
I've moved some unrelated refactoring changes to the following smaller PRs:

Once we merge these, I will rebase this PR again. Also, today I've applied a bunch of changes and now I don't see any issues with the latest code here. If you have time tomorrow, can you check the code for me? Thanks for your time!

filmaj

Still looks good, and thanks for splitting the PRs out - that made reviewing a lot easier. I did leave one question around a specific debug log message you added that I can't seem to reproduce when testing locally... here's the relevant log output during my test, shortly before, during and after I disconnected and reconnected my wifi from my laptop:

[DEBUG]  socket-mode:SocketModeClient:0 Received pong from Slack server (data: Ping from client (1649966865067))
[DEBUG]  socket-mode:SocketModeClient:0 Received ping from Slack server (data: Ping from applink-78ccf745b6-56dzm)
[DEBUG]  socket-mode:SocketModeClient:0 Sent ping to Slack: Ping from client (1649966866733)
[DEBUG]  socket-mode:SocketModeClient:0 Sent ping to Slack: Ping from client (1649966868399)
[DEBUG]  socket-mode:SocketModeClient:0 Sent ping to Slack: Ping from client (1649966870067)
[DEBUG]  socket-mode:SocketModeClient:0 Sent ping to Slack: Ping from client (1649966871733)
[INFO]  socket-mode:SocketModeClient:0 A pong wasn't received from the server before the timeout of 5000ms!
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connected:reconnecting
[DEBUG]  socket-mode:SocketModeClient:0 Sent ping to Slack: Ping from client (1649966873400)
[INFO]  socket-mode:SocketModeClient:0 A pong wasn't received from the server before the timeout of 5000ms!
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: reconnecting
[DEBUG]  socket-mode:SocketModeClient:0 Since only the primary WebSocket exists, going to tear it down...
[DEBUG]  socket-mode:SocketModeClient:0 Tearing down WebSocket connections finished
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connecting
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connecting:authenticating
[DEBUG]  socket-mode:SocketModeClient:0 Going to retrieve a new WSS URL ...
[DEBUG]  web-api:WebClient:0 apiCall('apps.connections.open') start
[DEBUG]  web-api:WebClient:0 will perform http request
[WARN]  web-api:WebClient:0 http request failed getaddrinfo ENOTFOUND slack.com
[DEBUG]  web-api:WebClient:0 will perform http request
[WARN]  web-api:WebClient:0 http request failed getaddrinfo ENOTFOUND slack.com
[DEBUG]  web-api:WebClient:0 will perform http request
[WARN]  web-api:WebClient:0 http request failed getaddrinfo ENOTFOUND slack.com
[DEBUG]  web-api:WebClient:0 will perform http request
[WARN]  web-api:WebClient:0 http request failed getaddrinfo ENOTFOUND slack.com
[DEBUG]  web-api:WebClient:0 will perform http request
[WARN]  web-api:WebClient:0 http request failed getaddrinfo ENOTFOUND slack.com
[DEBUG]  web-api:WebClient:0 will perform http request
[DEBUG]  web-api:WebClient:0 http response received
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connecting:authenticated
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connecting:handshaking
[DEBUG]  socket-mode:SocketModeClient:0 received a message on the WebSocket: {"type":"hello","num_connections":2,"debug_info":{"host":"applink-78ccf745b6-vxtsq","build_number":3,"approximate_connection_time":18060},"connection_info":{"app_id":"A02DH5S1NM6"}}
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connected
[DEBUG]  socket-mode:SocketModeClient:0 Transitioning to state: connected:ready
[DEBUG]  socket-mode:SocketModeClient:0 Received ping from Slack server (data: Ping from applink-78ccf745b6-56dzm)
[DEBUG]  socket-mode:SocketModeClient:0 Received pong from Slack server (data: Ping from client (1649966866733))
[DEBUG]  socket-mode:SocketModeClient:0 Received pong from Slack server (data: Ping from client (1649966868399))

I was expecting to see a DEBUG log for "Reconnecting to Slack..." but it's not there... not sure why?

filmaj · 2022-04-14T20:01:47Z

packages/socket-mode/src/SocketModeClient.ts

@@ -20,11 +20,40 @@ import { UnrecoverableSocketModeStartError } from './UnrecoverableSocketModeStar

 const packageJson = require('../package.json'); // eslint-disable-line import/no-commonjs, @typescript-eslint/no-var-requires

+// These enum values are used only in the state machine


I like this 👍

filmaj · 2022-04-14T20:03:26Z

packages/socket-mode/src/SocketModeClient.ts

-    .state('reconnecting')
+    .state(State.Reconnecting)
+      .onEnter(() => {
+        this.logger.debug('Reconnecting to Slack ...');


This looks good but is it essentially a duplicate of the global state machine's generic onStateEnter event logger at the very top of this state machine's definition? In fact, after running the simple example you provided, this log does not come up at all...?

If you don't see this log, the SocketModeClient code might be a bit older one. I've added this log mainly for debugging. We can remove it if it sounds duplicated with other logs.

mwbrooks

Thanks for splitting the PR. I imagine it greatly improved the readability!

I tested this locally with simple.js and temporarily disconnected my wi-fi. Works great! I think this is a huge improvement for those facing the socket mode disconnected issue. 🎉 If we have missed a use-case, then we can continue to refine it later.

seratch · 2022-04-14T22:45:20Z

@filmaj Can you run link.sh again? The logs shows a bit older behavior.

seratch · 2022-04-14T22:47:52Z

packages/socket-mode/src/SocketModeClient.ts

-    .state('reconnecting')
+    .state(State.Reconnecting)
+      .onEnter(() => {
+        this.logger.debug('Reconnecting to Slack ...');


If you don't see this log, the SocketModeClient code might be a bit older one. I've added this log mainly for debugging. We can remove it if it sounds duplicated with other logs.

seratch · 2022-04-14T22:50:45Z

packages/socket-mode/src/SocketModeClient.ts

      this.websocket.removeAllListeners('open');
      this.websocket.removeAllListeners('close');
      this.websocket.removeAllListeners('error');
      this.websocket.removeAllListeners('message');
+      this.websocket.close();


Probably we can improve this switching logic to be a bit safer.

have a local variable for the old connection and assign the existing connection to it

switch this.websocekt to the new connection

setTimeout

remove the listeners from the old connection

close the old one

seratch · 2022-04-14T22:54:27Z

@filmaj

[DEBUG] socket-mode:SocketModeClient:0 Transitioning to state: connected:reconnecting

In the latest revision, I've removed this state "connected:reconnecting". Having two "reconnecting" state in the state machine was an issue in the code yesterday

Co-authored-by: Fil Maj <maj.fil@gmail.com>

seratch added bug M-T: A confirmed bug report. Issues are confirmed when the reproduction steps are documented pkg:socket-mode applies to `@slack/socket-mode` labels Apr 13, 2022

seratch added this to the socket-mode@1.3.0 milestone Apr 13, 2022

seratch requested review from mwbrooks, filmaj and stevengill April 13, 2022 10:53

seratch self-assigned this Apr 13, 2022

seratch commented Apr 13, 2022

View reviewed changes

seratch removed the request for review from mwbrooks April 13, 2022 11:17

seratch commented Apr 13, 2022

View reviewed changes

filmaj approved these changes Apr 13, 2022

View reviewed changes

filmaj approved these changes Apr 14, 2022

View reviewed changes

mwbrooks approved these changes Apr 14, 2022

View reviewed changes

seratch commented Apr 14, 2022

View reviewed changes

seratch and others added 2 commits April 15, 2022 08:30

Fix slackapi#1243 Socket Mode reconnection issue

ae8f0b0

Many updates

e8a8f78

Co-authored-by: Fil Maj <maj.fil@gmail.com>

seratch force-pushed the issue-1243-socket-mode branch from 5f56cf1 to e8a8f78 Compare April 14, 2022 23:32

seratch added 4 commits April 15, 2022 09:45

Improvement

65863a9

Improvements

df39c6b

Improvements

90c1cbf

Update

a29c484

seratch merged commit 65744d2 into slackapi:main Apr 15, 2022

seratch deleted the issue-1243-socket-mode branch April 15, 2022 04:05

This was referenced Apr 15, 2022

ERROR: Cannot send message when client is not ready #1464

Closed

Socket mode: Bolt doesn't handle WebSocket disconnections gracefully #1243

Closed

seratch added a commit to seratch/node-slack-sdk that referenced this pull request Apr 16, 2022

Apply more improvements to slackapi#1465 changes

93dac84

seratch mentioned this pull request Apr 16, 2022

Apply more improvements to #1465 changes #1470

Merged

2 tasks

seratch added a commit that referenced this pull request Apr 16, 2022

Apply more improvements to #1465 changes (#1470)

738e89f

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix #1243 Socket Mode reconnection issue #1465

Fix #1243 Socket Mode reconnection issue #1465

seratch commented Apr 13, 2022 •

edited

seratch Apr 13, 2022

seratch Apr 13, 2022

filmaj Apr 13, 2022

seratch Apr 13, 2022

seratch Apr 13, 2022

seratch Apr 13, 2022

seratch Apr 13, 2022

seratch commented Apr 13, 2022

seratch Apr 13, 2022

seratch Apr 13, 2022

seratch Apr 13, 2022

filmaj Apr 13, 2022

seratch Apr 13, 2022

seratch commented Apr 13, 2022

filmaj left a comment

filmaj Apr 13, 2022

filmaj Apr 13, 2022

seratch commented Apr 14, 2022

filmaj left a comment •

edited

filmaj Apr 14, 2022

filmaj Apr 14, 2022

seratch Apr 14, 2022

mwbrooks left a comment

seratch commented Apr 14, 2022

seratch Apr 14, 2022

seratch Apr 14, 2022

seratch commented Apr 14, 2022


		/* eslint-disable @typescript-eslint/indent, newline-per-chained-call */

		private connectingSubmachine: Configuration<string, string> = Finity.configure()

		@@ -20,11 +20,40 @@ import { UnrecoverableSocketModeStartError } from './UnrecoverableSocketModeStar

		const packageJson = require('../package.json'); // eslint-disable-line import/no-commonjs, @typescript-eslint/no-var-requires

		// These enum values are used only in the state machine

Fix #1243 Socket Mode reconnection issue #1465

Fix #1243 Socket Mode reconnection issue #1465

Conversation

seratch commented Apr 13, 2022 • edited

Summary

Requirements (place an x in each [ ])

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

seratch commented Apr 13, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

seratch commented Apr 13, 2022

filmaj left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

seratch commented Apr 14, 2022

filmaj left a comment • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mwbrooks left a comment

Choose a reason for hiding this comment

seratch commented Apr 14, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

seratch commented Apr 14, 2022

seratch commented Apr 13, 2022 •

edited

Requirements (place an `x` in each `[ ]`)

filmaj left a comment •

edited