Fix #1110 Socket Mode disconnection issue with the aiohttp-based client by seratch · Pull Request #1112 · slackapi/python-slack-sdk

seratch · 2021-09-09T14:37:35Z

Summary

This pull request fixes #1110 by improving the connection management of the AIOHTTP based Socket Mode client. I will add a few comments on the improvement.

Category (place an `x` in each of the `[ ]`)

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.
I've run python3 -m venv .venv && source .venv/bin/activate && ./scripts/run_validation.sh after making the changes.

…sed client

seratch · 2021-09-09T14:41:53Z

slack_sdk/socket_mode/aiohttp/__init__.py

            self.wss_uri = await self.issue_new_wss_url()
        self.current_session = await self.aiohttp_client_session.ws_connect(
            self.wss_uri,
+            autoping=False,


This is the key change in this pull request. I've decided to stop relying on the AIOHTTP's ping-pong to better track the actual liveness of the connections on our end.

We've added manual ping-pong communication and last_ping_pong_time as the state of the current session. If the value is too old, this Socket Mode client tries to reconnect anyways. This is a proven way in the non-asyncio Socket Mode client. We haven't any similar bug reports for the non-asyncio client.

seratch · 2021-09-09T14:43:41Z

slack_sdk/socket_mode/aiohttp/__init__.py

-                self.monitor_current_session()
-            )
+        if self.current_session_monitor is not None:
+            self.current_session_monitor.cancel()


Also, while doing more tests (=aggressively & repeatedly doing force reconnection), I found that the Task object may refer to old abandoned objects. Thus, cancelling the old Task this way makes this code much safer.

Is it worth filing this issue upstream to the aio project?

Some part of the session object may be related to the behavior but this part is our own code. Thus, no need to file an issue to the project. Basically, we've improved our code to be safer this time 😅

seratch · 2021-09-09T14:44:32Z

slack_sdk/socket_mode/websockets/__init__.py

        web_client: Optional[AsyncWebClient] = None,
        auto_reconnect_enabled: bool = True,
        ping_interval: float = 10,
+        trace_enabled: bool = False,


As we added this flag to the parent class, this should be added to this websockets based implementation too.

seratch · 2021-09-09T14:45:20Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        elif message.type == WSMsgType.CLOSED:
+                            await asyncio.sleep(self.ping_interval)
+                            continue
+                        elif message.type == WSMsgType.PING:


Now that we handles ping / pong on our own, I've added these handlers.

seratch · 2021-09-09T14:46:35Z

slack_sdk/socket_mode/aiohttp/__init__.py

+
+                        if self.last_ping_pong_time is not None:
+                            disconnected_seconds = int(time.time() - self.last_ping_pong_time)
+                            if disconnected_seconds >= (self.ping_interval * 4):


This is the same logic with the non-asyncio client.

codecov · 2021-09-09T14:55:19Z

Codecov Report

Merging #1112 (07af1ee) into main (9f3240d) will decrease coverage by 0.37%.
The diff coverage is 18.96%.

@@            Coverage Diff             @@
##             main    #1112      +/-   ##
==========================================
- Coverage   85.71%   85.34%   -0.38%     
==========================================
  Files         110      110              
  Lines       10443    10506      +63     
==========================================
+ Hits         8951     8966      +15     
- Misses       1492     1540      +48

Impacted Files	Coverage Δ
slack_sdk/socket_mode/builtin/client.py	`79.19% <ø> (-0.68%)`	⬇️
slack_sdk/socket_mode/websocket_client/__init__.py	`60.76% <0.00%> (ø)`
slack_sdk/socket_mode/aiohttp/__init__.py	`46.11% <9.18%> (-10.93%)`	⬇️
slack_sdk/socket_mode/async_client.py	`71.17% <73.33%> (-0.12%)`	⬇️
slack_sdk/socket_mode/websockets/__init__.py	`62.03% <100.00%> (+0.71%)`	⬆️
slack_sdk/socket_mode/builtin/connection.py	`35.71% <0.00%> (-0.43%)`	⬇️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9f3240d...07af1ee. Read the comment docs.

eddyg · 2021-09-09T14:48:42Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        should_reconnect = False
+                        if self.current_session is None or self.current_session.closed:
+                            self.logger.info(
+                                "The session seems to be already closed. Going to reconnect..."


Suggesting "Reconnecting..." instead of "Going to reconnect..." to be more consistent with "Disconnecting..."

eddyg · 2021-09-09T14:50:09Z

slack_sdk/socket_mode/aiohttp/__init__.py

+
+                        if should_reconnect is True or not await self.is_connected():
+                            await self.connect_to_new_endpoint()
+                            self.logger.info("Reconnection done.")


Suggest "Reconnected to endpoint" (with no period at end; other log messages don't end with punctuation)

eddyg · 2021-09-09T14:50:40Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        elif message.type == WSMsgType.CLOSE:
+                            if self.auto_reconnect_enabled:
+                                self.logger.info(
+                                    "Received CLOSE event. Going to reconnect..."


Suggesting "Reconnecting..." instead of "Going to reconnect..." here too

eddyg · 2021-09-09T14:52:59Z

slack_sdk/socket_mode/async_client.py

        try:
            await self.connect_operation_lock.acquire()
+            if self.trace_enabled:
+                self.logger.debug("For reconnection, the connect_operation_lock was acquired")


Is this called in other cases than a reconnect? If so, suggest simpler "Acquired connect_operation_lock"

eddyg · 2021-09-09T14:53:38Z

slack_sdk/socket_mode/async_client.py

            if self.connect_operation_lock.locked() is True:
                self.connect_operation_lock.release()
+                if self.trace_enabled:
+                    self.logger.debug("The connect_operation_lock for reconnection was released")


If changing above, suggest simpler "Released connection_operation_lock" here also

seratch · 2021-09-09T15:01:31Z

@eddyg Thanks for the suggestion! I agree with you on the log message consistency. I've updated them.

filmaj

Looks good to me!

I wasn't able to determine from a quick ack through the project, but, are there tests for handling ping/pong messages? Possibly should we add tests for the monitoring / reconnection behaviours?

filmaj · 2021-09-09T14:55:40Z

slack_sdk/socket_mode/aiohttp/__init__.py

-                self.monitor_current_session()
-            )
+        if self.current_session_monitor is not None:
+            self.current_session_monitor.cancel()


Is it worth filing this issue upstream to the aio project?

filmaj · 2021-09-09T15:03:33Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                try:
+                    message: WSMessage = await self.current_session.receive()
+                    if self.trace_enabled and self.logger.level <= logging.DEBUG:
+                        type = WSMsgType(message.type)


The next conditional below checks that message is not None - should that be done here too?

The type should always exists but just in case, we may want to have additional check before the assignment. will update this part later.

filmaj · 2021-09-09T15:06:53Z

slack_sdk/socket_mode/builtin/connection.py

                    if is_stale:
                        self.logger.info(
-                            "The connection seems to be stale. Disconnecting..."
+                            "The connection seems to be stale. Reconnecting..."


Just to clarify and for my own understanding: so the next disconnect() call will end up actually re-establishing the connection via the monitoring loop you added?

Thanks. You're right. This change should be reverted as the situation here is not always auto-reconnection enabled.

seratch · 2021-09-09T15:26:37Z

@filmaj

are there tests for handling ping/pong messages?

Yes, this test runs the code of the patterns.

Possibly should we add tests for the monitoring / reconnection behaviours?

Right now, we don't have any tests for this scenario. The reconnection tests require more updates on the testing utility side. I did lots of manual testing this time. Let me add automated tests for it in future updates.

filmaj · 2021-09-09T15:28:07Z

OK sounds good - I am not saying it is required, I am mainly asking questions to learn 😄

Fix slackapi#1110 Socket Mode disconnection issue with the aiohttp-ba…

ed8292d

…sed client

seratch added Version: 3x socket-mode labels Sep 9, 2021

seratch added this to the 3.11.0 milestone Sep 9, 2021

seratch self-assigned this Sep 9, 2021

seratch commented Sep 9, 2021

View reviewed changes

Fix lint errors

b0f2cf5

seratch requested a review from filmaj September 9, 2021 14:52

eddyg reviewed Sep 9, 2021

View reviewed changes

Make info logs more consistent

cd374e1

filmaj approved these changes Sep 9, 2021

View reviewed changes

Revert log change and improve details

07af1ee

seratch merged commit dafdef0 into slackapi:main Sep 9, 2021

seratch deleted the issue-1110-aiohttp-socket-mode branch September 9, 2021 15:55

This was referenced Sep 9, 2021

Socket Mode disconnection issue with the aiohttp-based client #1110

Closed

Improve the stability of SocketModeClient implementations #1114

Merged

seratch mentioned this pull request Sep 17, 2021

asyncio-based Socket Mode client improvements #1117

Merged

16 tasks

Conversation

seratch commented Sep 9, 2021

Summary

Category (place an x in each of the [ ])

Requirements (place an x in each [ ])

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch Sep 9, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov bot commented Sep 9, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch commented Sep 9, 2021

Uh oh!

filmaj left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch commented Sep 9, 2021

Uh oh!

filmaj commented Sep 9, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Category (place an `x` in each of the `[ ]`)

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

seratch Sep 9, 2021 •

edited

Loading

codecov bot commented Sep 9, 2021 •

edited

Loading