socket-mode: Handling WS errors during handshake #2099

filmaj · 2024-11-22T16:27:53Z

This PR fixes #2094

If a websocket error is raised during WS connection establishment, and retries are on, the library today may start a runaway loop of doubling the number of WS connections as it attempts to retry. This was caused by the SlackWebSocket class not tracking a fresh new WS connection until the connection was established; if an error occurred during the handshake, a new WS connection would be created and the old one would not be cleaned up. The core of the fix in this PR involves tracking the WS connection at all times.

…ing handshake

codecov · 2024-11-22T16:31:40Z

Codecov Report

Attention: Patch coverage is 50.00000% with 7 lines in your changes missing coverage. Please review.

Project coverage is 91.89%. Comparing base (278514f) to head (1c035e3).
Report is 20 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #2099      +/-   ##
==========================================
+ Coverage   91.65%   91.89%   +0.23%     
==========================================
  Files          38       38              
  Lines       10311    10320       +9     
  Branches      647      649       +2     
==========================================
+ Hits         9451     9484      +33     
+ Misses        848      824      -24     
  Partials       12       12

Flag	Coverage Δ
cli-hooks	`95.24% <ø> (+0.01%)`	⬆️
cli-test	`94.48% <ø> (+0.01%)`	⬆️
oauth	`77.39% <ø> (ø)`
socket-mode	`61.82% <50.00%> (+3.59%)`	⬆️
web-api	`96.88% <ø> (ø)`
webhook	`96.65% <ø> (ø)`

Flags with carried forward coverage won't be shown. Click here to find out more.

filmaj · 2024-11-22T21:23:59Z

packages/socket-mode/src/SlackWebSocket.ts

      this.logger.debug('WebSocket open event received (connection established)!');
-      this.websocket = ws;


Not tracking the current websocket instance was a problem in the case the web socket server returns an error. Since only once the open event was emitted would we keep track of the websocket (this line), any errors during the websocket handshake would call into disconnect which, crucially, only terminates the underlying network resources for the tracked this.websocket.

That was the underlying issue that caused the "doubling up" of reconnection attempts (see "Issue 1" described by @gdhardy1 in this comment): each time an error was encountered during websocket handshake, there would be an 'untracked' ws instance still executing reconnect attempts in addition to a new one being spawned. Essentially websocket-connection-bombing ourselves.

If you remove the changes in this file, you will see the integration test I added at the end of this PR fail.

Thank you for finding this. I was able to patch this in and test it while we await a full fix. It stabilized things tremendously.

filmaj · 2024-11-22T21:28:12Z

packages/socket-mode/src/SocketModeClient.ts

-        this.logger.debug('Continuing with reconnect...');
-        this.emit(State.Reconnecting);
-        cb.apply(this).then(res);
+        if (this.shuttingDown) {


While not a problem brought up by users, I noticed a problem here when writing integration tests:

if you turn on the socket mode client and it is seeing errors from the web socket server, and

in between reconnect attempts you call disconnect() to stop the client,

.. then the client will keep trying to reconnect forever via this part of the code. Adding this guard here just in case.

this makes for an awesome catch 🙏 ✨ Thanks for guarding against it!

filmaj · 2024-11-22T21:29:22Z

packages/socket-mode/src/errors.ts

@@ -61,10 +61,7 @@ function errorWithCode(error: Error, code: ErrorCode): CodedError {
 * A factory to create SMWebsocketError objects.
 */
 export function websocketErrorWithOriginal(original: Error): SMWebsocketError {
-  const error = errorWithCode(
-    new Error(`Failed to send message on websocket: ${original.message}`),


Removed "Failed to send message" as part of this error, as this error can be raised unrelated to message-sending. In this PR, I noticed that websocket handshake errors also used this code path, which made the error message misleading.

filmaj · 2024-11-22T21:30:05Z

packages/socket-mode/test/integration.spec.js

@@ -168,6 +169,47 @@ describe('Integration tests with a WebSocket server', () => {
      assert.isTrue(debugLoggerSpy.calledWith(sinon.match('Unable to parse an incoming WebSocket message')));
      await client.disconnect();
    });
+    it('should maintain one serial reconnection attempt if WSS server sends unexpected HTTP response during handshake, like a 409', async () => {


This is the test testing for the exponential reconnection doubling spiral bug.

zimeg

LGTM! Keeping track of what's been instantiated in this is such a great fix!

I've tested this with a few common cases and error cases with a Bolt app using the RC from slackapi/bolt-js#2347, including:

Running an app for a while
Running multiple apps at the same time
Running >10 apps at once for infinite retries due to too_many_websockets
Turning internet off and back on while apps are running

And found all of these to connect with the right retries! One socket connection process persisted after exit which was due to some tooling strangeness and scripting I had setup, but after kill the num_connections returned to the expected 1 😌 🎉

With the backend rollout resolving most 409 errors and reports from @gdhardy1 that this is working well, I think this is set to merge and release! 🚢 💨

Going to coordinate a few other changes before this, but I appreciate this PR so much ❤️

zimeg · 2024-12-06T20:30:28Z

packages/socket-mode/src/SocketModeClient.ts

-        this.logger.debug('Continuing with reconnect...');
-        this.emit(State.Reconnecting);
-        cb.apply(this).then(res);
+        if (this.shuttingDown) {


this makes for an awesome catch 🙏 ✨ Thanks for guarding against it!

zimeg · 2024-12-06T20:32:00Z

packages/socket-mode/src/SlackWebSocket.spec.ts

 import sinon from 'sinon';
-
-import { SlackWebSocket } from './SlackWebSocket';
+proxyquire.noPreserveCache();


Superb test setups all throughout 👏 This adds so much confidence around the changes.

With some of the retry timing we might have to lookout for flakiness of tests due to the CI runners - nothing a rerun might not solve, but with the matrix setups I think our chances of this happening increase eversomuch 👾

zimeg · 2024-12-06T20:34:32Z

packages/socket-mode/test/integration.spec.js

@@ -90,7 +90,7 @@ describe('Integration tests with a WebSocket server', () => {
      await client.disconnect();
    });
  });
-  describe('catastrophic server behaviour', () => {


zimeg · 2024-12-06T20:35:07Z

packages/socket-mode/test/integration.spec.js

+      client.on('close', () => {
+        closed++;
+      });
+      // do not use await here, since `start()` won't return until the connection is established. we are intentionally testing connection establishment failure, so that will never finish. so, let's run this in a rogue "thread", e.g. fire off an async method and let it do its thing!


This is awesome 👏

WilliamBergamin

This looks good to me as well 💯

Thank you @zimeg for manually stress testing these changes 🙏

I tested out our socket-mode-oauth example and seems like the socket gets established properly 👍

zimeg · 2024-12-09T19:35:01Z

@WilliamBergamin 🙏 And thank you for checking with the example! Let's merge this great fix for the next release 🚀

test: add integration test for 409 response from websocket server dur…

9132ac1

…ing handshake

filmaj mentioned this pull request Nov 22, 2024

WebSocket error occurred: Unexpected server response: 409 #2094

Closed

filmaj mentioned this pull request Nov 22, 2024

test: add test for socket server returning 409 slackapi/python-slack-sdk#1599

Draft

fix doubling up on reconnection attempts

4b4dd72

filmaj commented Nov 22, 2024

View reviewed changes

Filip Maj added 2 commits November 22, 2024 16:35

documenting bug and test validating the fix

6f918b0

add a unit test for connect() method of SlackWebSocket

2fecb13

filmaj changed the title ~~WIP: Handling 409 response from websocket server~~ socket-mode: Handling WS errors during handshake Nov 26, 2024

filmaj marked this pull request as ready for review November 26, 2024 15:39

filmaj requested a review from a team November 26, 2024 15:39

Publish @slack/socket-mode@2.0.3-rc.1

1c035e3

filmaj mentioned this pull request Nov 26, 2024

bump socket-mode to 2.0.3-rc.1, publish as @slack/bolt@4.1.2-rc.1 slackapi/bolt-js#2347

Closed

filmaj added this to the socket-mode@2.0.3 milestone Nov 26, 2024

WilliamBergamin requested review from zimeg and WilliamBergamin December 4, 2024 19:49

zimeg approved these changes Dec 6, 2024

View reviewed changes

WilliamBergamin approved these changes Dec 9, 2024

View reviewed changes

zimeg merged commit c389a75 into main Dec 9, 2024
56 of 57 checks passed

zimeg deleted the handle-409 branch December 9, 2024 19:36

zimeg mentioned this pull request Dec 9, 2024

Release: @slack/socket-mode@2.0.3, @slack/oauth@3.0.2, @slack/rtm-api@7.0.2 #2120

Merged

2 tasks

WilliamBergamin mentioned this pull request Jan 14, 2025

health: flaky socket mode unit tests #2138

Open

7 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

socket-mode: Handling WS errors during handshake #2099

socket-mode: Handling WS errors during handshake #2099

filmaj commented Nov 22, 2024 •

edited

Loading

codecov bot commented Nov 22, 2024 •

edited

Loading

filmaj Nov 22, 2024 •

edited

Loading

gdhardy1 Nov 26, 2024 •

edited

Loading

filmaj Nov 22, 2024

zimeg Dec 6, 2024

filmaj Nov 22, 2024

filmaj Nov 22, 2024

zimeg left a comment

zimeg Dec 6, 2024

zimeg Dec 6, 2024

zimeg Dec 6, 2024

zimeg Dec 6, 2024

WilliamBergamin left a comment

zimeg commented Dec 9, 2024

		this.logger.debug('WebSocket open event received (connection established)!');
		this.websocket = ws;

socket-mode: Handling WS errors during handshake #2099

socket-mode: Handling WS errors during handshake #2099

Conversation

filmaj commented Nov 22, 2024 • edited Loading

codecov bot commented Nov 22, 2024 • edited Loading

Codecov Report

filmaj Nov 22, 2024 • edited Loading

Choose a reason for hiding this comment

gdhardy1 Nov 26, 2024 • edited Loading

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

zimeg left a 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

WilliamBergamin left a comment

Choose a reason for hiding this comment

zimeg commented Dec 9, 2024

filmaj commented Nov 22, 2024 •

edited

Loading

codecov bot commented Nov 22, 2024 •

edited

Loading

filmaj Nov 22, 2024 •

edited

Loading

gdhardy1 Nov 26, 2024 •

edited

Loading