Socket Mode disconnection issue with the aiohttp-based client

Hello, I'm following up after the issue #1065 and upgrading to Slack Bolt 1.8.

Shortly after upgrading, I experienced disconnections. This happened twice in the last 3 days - with the previous version the disconnection has happened every few weeks. What's visible from my side is a Slack application still running, but unreachable through Slack slash commands. There are no logs related to the websocket, contrary to #1065. The bug symptoms are the same though, which makes me believe it's related.

Reproducible in:

The Slack SDK version

slack-bolt==1.8.1
slack-sdk==3.10.1
slackclient==1.3.2

Python runtime version

Python 3.8.10

OS info

(running in a Docker container based on python:3.8.10-slim-buster)

Steps to reproduce:

Run the app with socket mode for a few days.

Expected result:

The app is always reachable.

Actual result:

Slash commands or interacting with the app messages lead to the Slack error "/foo failed with the error "dispatch failed".

Thank you for your consideration!

Hi @matthieucan, thanks for taking the time to report this issue (again)! I'm sorry to hear that the fix we had didn't help for your case.

I will try to reproduce the situation and do more testing on my end but can I ask you to help us identify the cause of the issue by running a simple app with debug level logging? Having the following lines of code at the top of your source code enables the debug level logging.

import logging
logging.basicConfig(level=logging.DEBUG)

If you find any suspicious behaviors in the detailed logs, sharing the outputs with us would be greatly appreciated.

Hi @seratch, thank you, I'm now running it with debug logs. I can't guarantee I'll let it run until the bug is triggered, as this application is critical enough to warrant reverting the Slack Bolt upgrade. I'll let you know!

Thanks for your help and we're sorry about the disruption of your apps due to this issue. I have been running a simple Socket Mode app in the same Docker image for two days but I haven't managed to reproduce the situation yet. I'm thinking that some race conditions that can arise only when an app is receiving more requests.

FWIW, the following is the example app I'm using now:

main.py:

import logging
logging.basicConfig(level=logging.DEBUG)

import os
from slack_bolt.async_app import AsyncApp
app = AsyncApp(token=os.environ["SLACK_BOT_TOKEN"])

@app.command("/do-something")
async def handle_some_command(ack, body, logger):
    await ack()
    logger.info(body)

from slack_bolt.adapter.socket_mode.async_handler import AsyncSocketModeHandler

async def main():
    handler = AsyncSocketModeHandler(app, os.environ["SLACK_APP_TOKEN"])
    await handler.start_async()

if __name__ == "__main__":
    import asyncio
    asyncio.run(main())

Dockerfile:

FROM python:3.8.10-slim-buster as builder
RUN apt-get update && apt-get clean
COPY requirements.txt /build/
WORKDIR /build/
RUN pip install -U pip && pip install -r requirements.txt

FROM python:3.8.10-slim-buster as app
COPY --from=builder /build/ /app/
COPY --from=builder /usr/local/lib/ /usr/local/lib/
WORKDIR /app/
COPY *.py /app/
ENTRYPOINT python main.py

requirements.text:

slack_bolt>=1.9
aiohttp>=3,<4

Hi @seratch, Thank you for trying to reproduce along! Not much to update on my side, I've been running the app with debug logs for the last 2 days, but the bug didn't happen.

I'm thinking that some race conditions that can arise only when an app is receiving more requests.

This looks correct. For the record I have a copy of the app running in a development cluster, that doesn't receive nearly as many requests, and it never broke like the prod one.

Hi @matthieucan, we've merged more fixes for this issue at #1112 and released a pre-release version - v3.11.0rc1: https://pypi.org/project/slack-sdk/3.11.0rc1/ May I ask you to try the RC1 version in your app?

Hi @matthieucan, we've merged more fixes for this issue at #1112 and released a pre-release version - v3.11.0rc1: https://pypi.org/project/slack-sdk/3.11.0rc1/ May I ask you to try the RC1 version in your app?

Thanks a lot @seratch! I'm now running this pre-release. I'll let you know if anything happens (or not) :)

Hi @seratch, the issue happened again. Here are the DEBUG logs:

2021-09-17 07:49:07:slack_bolt.AsyncApp:__init__:INFO:The session seems to be already closed. Reconnecting...
2021-09-17 07:49:07:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.1 Python/3.8.3 slackclient/3.11.0rc1 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-09-17 07:49:07:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Fri, 17 Sep 2021 07:49:07 GMT', 'server': 'Apache', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'x-oauth-scopes': 'connections:write', 'x-xss-protection': '0', 'x-slack-req-id': 'c5451302042b13084fca7ee46b6dbd22', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'vary': 'Accept-Encoding', 'x-accepted-oauth-scopes': 'connections:write', 'content-encoding': 'gzip', 'content-length': '163', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '82', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-zlug', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-0p30, envoy-edge-dub-omy6', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=b461b04d-2020-4746-9d04-8a4afb119755&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'}
2021-09-17 07:49:12:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=b461b04d-2020-4746-9d04-8a4afb119755&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
2021-09-17 07:49:22:slack_bolt.AsyncApp:__init__:INFO:The session seems to be already closed. Reconnecting...
2021-09-17 07:49:22:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.1 Python/3.8.3 slackclient/3.11.0rc1 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-09-17 07:49:22:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Fri, 17 Sep 2021 07:49:22 GMT', 'server': 'Apache', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'x-oauth-scopes': 'connections:write', 'x-xss-protection': '0', 'x-slack-req-id': '92e0c85f93dc83f96189c8188fadbffc', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'vary': 'Accept-Encoding', 'x-accepted-oauth-scopes': 'connections:write', 'content-encoding': 'gzip', 'content-length': '164', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '81', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-cm1v', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-88ir, envoy-edge-dub-22lj', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=b2da5d52-d27d-481a-a746-c59463f64cb4&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'}
2021-09-17 07:49:23:slack_bolt.AsyncApp:__init__:INFO:A new session has been established
2021-09-17 07:49:23:slack_bolt.AsyncApp:__init__:INFO:The old session has been abandoned
2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1)
2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None)
2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None)
2021-09-17 07:49:33:slack_bolt.AsyncApp:__init__:INFO:The connection seems to be stale. Reconnecting... reason: disconnected for 45+ seconds)
2021-09-17 07:49:33:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.1 Python/3.8.3 slackclient/3.11.0rc1 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-09-17 07:49:33:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Fri, 17 Sep 2021 07:49:33 GMT', 'server': 'Apache', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'x-oauth-scopes': 'connections:write', 'x-xss-protection': '0', 'x-slack-req-id': '4676bfb7ef8377209aa74a8bfe2067ee', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'vary': 'Accept-Encoding', 'x-accepted-oauth-scopes': 'connections:write', 'content-encoding': 'gzip', 'content-length': '164', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '79', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-tk1z', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-rxxu, envoy-edge-dub-m2br', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=ed59e920-c619-4efc-8370-06c64f4a0e76&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'}
2021-09-17 07:49:33:slack_bolt.AsyncApp:__init__:INFO:A new session has been established
2021-09-17 07:49:33:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1)
2021-09-17 07:49:33:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None)
2021-09-17 07:49:33:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None)

Let me know if there's anything else I can help you with!

@matthieucan Thanks for sharing the logs.

With the given information, your app became unable to connect to and keep a connection with the Slack server side for some reason. Then, the reconnection started failing in the environment.

2021-09-17 07:49:23:slack_bolt.AsyncApp:init:INFO:A new session has been established 2021-09-17 07:49:23:slack_bolt.AsyncApp:init:INFO:The old session has been abandoned 2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1) 2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None) 2021-09-17 07:49:23:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None) 2021-09-17 07:49:33:slack_bolt.AsyncApp:init:INFO:The connection seems to be stale. Reconnecting... reason: disconnected for 45+ seconds) 2021-09-17 07:49:33:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, ...

These lines are unexpected. Although the reconnection succeeded 10 seconds before the The connection seems to be stale. log, the log says ping-pong communications never succeeded at least for 45 seconds. Perhaps, there is something that the aiohttp-based implementation can be improved here. I will continue investigating this part. Thanks again for sharing the detailed information.

If you don't mind, let me ask a few follow-up questions:

Before the log at 07:49:07, do you find anything related to the disconnection? A following log at 07:49:33 says the connection has been inactive for 45+ seconds. This means that ping-pong communications with the Slack server should be failing since 07:48:48 or so.
The log at 07:49:12 says that the app failed to establish a new connection (error code: 408). You didn't share this ERROR level log in the previous report. Is this your first time to see this error?
After the log at 07:49:33, do you have no line in the log? No hello message logs? No The old session has been abandoned logs?
I know that you mentioned that the app became irresponsible without restart but, just to confirm, is the situation the same in this case? Wasn't the app recovered from the irresponsible state without your restart?

Lastly, we'll continue trying to resolve this issue but we are still trying to identify the cause. Thus, we may need more time to completely resolve this issue. As of today, we've never received similar issue reports about the built-in Socket Mode client, which is the most commonly used implementation. If you don't have a strong reason to choose an asyncio-based solution and you don't mind spending more time to change your app, switching to the built-in one may help.

I just reopened this issue and will continue trying to resolve this in the next version.

As the first step, I created a minor update pull request that may mitigate the false behavior here: https://github.com/slackapi/python-slack-sdk/pull/1117

Hi @seratch, thanks a lot for investigating.

If you don't mind, let me ask a few follow-up questions:

Before the log at 07:49:07, do you find anything related to the disconnection? A following log at 07:49:33 says the connection has been inactive for 45+ seconds. This means that ping-pong communications with the Slack server should be failing since 07:48:48 or so.

No I can't find anything related. Those are the logs of the app before that time:

2021/09/17 07:43:58 token renewed
2021-09-17 07:45:35,024 INFO [aiohttp.access]  [17/Sep/2021:07:45:34 +0000] "GET /<redacted> HTTP/1.1" 200 2271 "-" "Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)"
2021-09-17 07:45:35:aiohttp.access:logging:INFO:GET "/<redacted>" 200 OK (response-time=7 ms, size=1347 b, ip=127.0.0.1, http=1.1, agent="Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)")
[2021-09-17T07:45:34.851Z] "GET /<redacted> HTTP/1.1" 200 - 0 1188 180 7 "<redacted>" "Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)" "<redacted>" "<redacted>" "127.0.0.1:8080"
2021-09-17 07:47:06,027 INFO [aiohttp.access]  [17/Sep/2021:07:47:05 +0000] "GET /<redacted> HTTP/1.1" 200 2271 "-" "Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)"
2021-09-17 07:47:06:aiohttp.access:logging:INFO:GET "<redacted>" 200 OK (response-time=8 ms, size=1347 b, ip=127.0.0.1, http=1.1, agent="Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)")
[2021-09-17T07:47:05.886Z] "GET /<redacted> HTTP/1.1" 200 - 0 1188 150 8 "<redacted>" "Mozilla/5.0 (compatible; Google-Apps-Script; beanserver; +https://script.google.com; id: <redacted>)" "<redacted>" "<redacted>" "127.0.0.1:8080"

Nothing special in there, a non-Slack aiohttp endpoint is hit and replies with HTTP 200. Worth noting that this non-Slack endpoint continues to function when the Slack app becomes non-reachable.

Other logs concern K8s healthcheck probes, nothing different than usual there.

The log at 07:49:12 says that the app failed to establish a new connection (error code: 408). You didn't share this ERROR level log in the previous report. Is this your first time to see this error?

I did a search in all logs and found these occurences:

prod.log 2021-08-22 01:49:46:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=f497503d-2010-4472-a50f-ea3920b24239&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
dev.log 2021-08-22 01:49:47:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=71f724b3-e307-499d-8390-655cfdb5f17b&app_id=236eabf4392193192501199ea6c3dd0bcd3f173a91d6b8581def965396fa0ca7'))
prod.log 2021-08-22 01:50:02:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=2ae06084-9429-42da-b685-d7404a4a0b07&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
dev.log 2021-08-22 01:50:02:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=98407f71-14c5-48f4-9a77-996a60d24ae7&app_id=236eabf4392193192501199ea6c3dd0bcd3f173a91d6b8581def965396fa0ca7'))
prod.log 2021-08-22 01:50:17:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=9d1a5bff-0d08-40a2-b03c-24e49e5ba96d&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
dev.log 2021-08-22 01:50:18:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=8aaa3f8a-1d94-4cbc-a131-d3d07450bd51&app_id=236eabf4392193192501199ea6c3dd0bcd3f173a91d6b8581def965396fa0ca7'))
prod.log 2021-08-22 01:50:32:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=46ed7f56-783c-4181-8679-3f14c4b83feb&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
prod.log 2021-08-22 01:50:47:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=1d5aad7c-6594-43d0-9307-c4f58a8c6187&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))
dev.log 2021-08-27 16:45:19:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=a0f090c2-1777-40d9-bae4-002d93c20de4&app_id=236eabf4392193192501199ea6c3dd0bcd3f173a91d6b8581def965396fa0ca7'))
dev.log 2021-08-27 16:45:34:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=0ce2df65-96c7-452d-bde9-ab74dbd4e21b&app_id=236eabf4392193192501199ea6c3dd0bcd3f173a91d6b8581def965396fa0ca7'))
prod.log 2021-09-17 07:49:12:slack_bolt.AsyncApp:__init__:ERROR:Failed to check the current session or reconnect to the server (error: WSServerHandshakeError, message: 408, message='Invalid response status', url=URL('wss://wss-primary.slack.com/link/?ticket=b461b04d-2020-4746-9d04-8a4afb119755&app_id=a11ae1b21747c198bea15ae23c4146d456285406400bad4eb9b8454cc089437d'))

This is very interesting:

See prefixes prod.log and dev.log for both instances of the app. They seem to always occur at the same time, except for today where it only occurred in prod.
Those timestamps don't match with when we experienced the non-reachability issue.

After the log at 07:49:33, do you have no line in the log? No hello message logs? No The old session has been abandoned logs?

No, nothing relevant until I manually killed the app ~1h later.

I know that you mentioned that the app became irresponsible without restart but, just to confirm, is the situation the same in this case? Wasn't the app recovered from the irresponsible state without your restart?

I confirm it's the same, I was informed around 1 hour later (than those logs) that the app was not responsive (so I can only assume it was not responsive in the last hour).

Lastly, we'll continue trying to resolve this issue but we are still trying to identify the cause. Thus, we may need more time to completely resolve this issue. As of today, we've never received similar issue reports about the built-in Socket Mode client, which is the most commonly used implementation. If you don't have a strong reason to choose a asyncio-based solution and you don't mind spending more time to change your app, switching to the built-in one may help.

Thank you so much for your efforts. I can't easily move away from the aiohttp integration, as the app is integrated with a few non-Slack endpoints, but I'll keep that in mind.

@matthieucan Thanks for sharing further info. So, you're running the SocketModeClient as part of AIOHTTP web app. Does that mean that your app uses SocketModeHandler#connect_async(), not #start_async()?

If so, your app can use SocketModeHandler#client.is_connect() to test if the underlying connection is alive (in a background job). If it's inactive, the app can recreate the client (=call #close() method and then create a new instance). To make the validation more rigorous, I've updated the is_connected() method to have more check logic: https://github.com/slackapi/python-slack-sdk/pull/1117/commits/0e7bc1f2cabcf38769aff101975402a5f2206982

Although I don't think that being part of AIOHTTP web app can be the cause of the connectivity issue, I've never done any testing with such an application. I will check if there is any difference in the case by running a simple web app.

@matthieucan Thanks for sharing further info. So, you're running the SocketModeClient as part of AIOHTTP web app. Does that mean that your app uses SocketModeHandler#connect_async(), not #start_async()?

Yes, that's correct.

If so, your app can use SocketModeHandler#client.is_connect() to test if the underlying connection is alive (in a background job). If it's inactive, the app can recreate the client (=call #close() method and then create a new instance). To make the validation more rigorous, I've updated the is_connected() method to have more check logic: 0e7bc1f

This sounds like a very nice mitigation strategy, albeit requires an additional background task. Do you think something like checking every 10 seconds is fine?

Although I don't think that being part of AIOHTTP web app can be the cause of the connectivity issue, I've never done any testing with such an application. I will check if there is any difference in the case by running a simple web app.

Super, thank you!

Do you think something like checking every 10 seconds is fine?

Yes, I do. Also for better safety, I would recommend recreating your client if the background job sees 2+ consecutive False response is_connected() method.

Hi @matthieucan, I just released a new patch version, which includes many improvements on the asyncio-based Socket Mode clients: https://github.com/slackapi/python-slack-sdk/releases/tag/v3.11.1

I hope the changes eliminate the issues you're facing! But, even if they only mitigate, newly added debug-level logging will provide more useful information for further investigation.

Also, as the is_connected() is improved, you can use the method to check the current state of your Socket mode client instance in your code.

Thanks for being patient with this issue. Please try the latest version if you have a chance 🙇

Hi @seratch , Apologies for getting back to you late. Thank you for the new releases, we're now running slack-bolt 1.9.2 and slack-sdk 3.11.2. I'll report back if any issue appears :)

@seratch I'm encountering similar issues.

The Slack SDK version

slack-bolt==1.9.2 slack-sdk==3.11.1

Python runtime version

Python 3.8.12

(Also running in a Docker container based on python:3.8-slim-buster)

I'm experiencing consistent 'missed' messages and delayed messaging processing (sometimes 5-6 minutes) that are predicated on websocket connection recycling related to this issue, e.g.

2021-10-11 21:36:19UTC DEBUG    A new monitor_current_session() executor has been recreated for s_276282781
2021-10-11 21:36:19UTC DEBUG    A new receive_messages() executor has been recreated for s_276282781
2021-10-11 21:36:19UTC INFO     The old session (s_276273553) has been abandoned
2021-10-11 21:36:19UTC DEBUG    The monitor_current_session task for s_276273553 is now cancelled
2021-10-11 21:36:19UTC DEBUG    A new monitor_current_session() execution loop for s_276282781 started
2021-10-11 21:36:19UTC DEBUG    The running receive_messages task for s_276273553 is now cancelled
...
2021-10-11 22:41:02UTC INFO     The session (s_286099053) seems to be already closed. Reconnecting...
2021-10-11 22:41:02UTC DEBUG    Inactive connection detected (session_id: s_286099053, closed: False, stale: False, current_session.closed: True, is_ping_pong_failing: False)
2021-10-11 22:41:04UTC INFO     A new session (s_286141377) has been established
2021-10-11 22:41:04UTC DEBUG    Sending a ping message with the newly established connection (s_286141377)...
2021-10-11 22:41:04UTC DEBUG    A new monitor_current_session() executor has been recreated for s_286141377
2021-10-11 22:41:04UTC DEBUG    A new receive_messages() executor has been recreated for s_286141377
2021-10-11 22:41:04UTC INFO     The old session (s_286099053) has been abandoned
2021-10-11 22:41:04UTC DEBUG    The monitor_current_session task for s_286099053 is now cancelled
2021-10-11 22:41:04UTC DEBUG    A new monitor_current_session() execution loop for s_286141377 started
2021-10-11 22:41:04UTC DEBUG    The running receive_messages task for s_286099053 is now cancelled
2021-10-11 22:41:04UTC DEBUG    A new receive_messages() execution loop with s_286141377 started
2021-10-11 22:41:04UTC DEBUG    A new message enqueued (current queue size: 1, session: s_286141377)
2021-10-11 22:41:04UTC DEBUG    Message processing started (type: hello, envelope_id: None, session: s_286141377)
2021-10-11 22:41:04UTC DEBUG    Message processing completed (type: hello, envelope_id: None, session: s_286141377)
2021-10-11 22:45:49UTC DEBUG    A new message enqueued (current queue size: 1, session: s_286141377)

Implementation is pretty much spot on the documentation:

from slack_bolt.async_app import AsyncApp

app = AsyncApp(token=Config.bot_token)

async def main():
    bot = AsyncSocketModeHandler(
        app, app_token=config.app_token
    )
    await bot.start_async()

@app.event("message")
async def message_event(ack, client, message):
    await ack()
    message_text = message.get("text")
    if message_text and MATCH_CONDITION.match(message_text):
        logger.info(f"message ACK - ({message_text})")
        await handle_message(data=message, web_client=client)
        logger.info("message END")
    else:
        logger.info(f"message DISCARD - {message_text}")

if __name__ == "__main__":
    asyncio.run(main())

The common pattern would be, the bot processes a single message correctly. Another message executed directly after the initial one is not detected and there's no logging (indicating the message isn't received from the websocket) and then some arbitrary time later the message will get processed--this could be 30 seconds and sometimes I've seen over 5 minutes.

While waiting for a reset of the websocket connection, debug lines like this appear:

2021-10-11 22:49:01UTC DEBUG    100 WebSocket messages received after the previous same log (s_286141377)

I'm not sure if this is normal behavior and a red-herring, or indicative of an issue with the app. Unfortunately, there's not really any other meaningful logs in the stream, and I've verified with my networking team there's no policies affecting connections to Slack's API.

Thanks in advance.

Hi @seratch, The latest version is running more smoothly than before, but in the last weeks the issue happened once. Here are the annotated logs. I kept the last working interaction with Slack at the top, then things are happening with the websocket/session. Hours later the app was manually killed, and interestingly enough it was able to post a message on Slack (reporting the shutdown). So it seems the app can send messages, but not receive them?

Thank you in advance for your help!

# Last working interaction with Slack

2021-10-11 22:42:12:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/chat.postMessage, params: {}, files: {}, data: {}, json: {(redacted)}, proxy: {}, headers: {'Content-Type': 'application/json;charset=utf-8', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.2 Python/3.8.3 slackclient/3.11.2 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-10-11 22:42:12:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {(redacted)}, body: {'ok': True, (redacted)}

# Then this dance happens

2021-10-11 22:43:49:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 22:52:09:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 22:53:10:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-11 23:00:30:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:08:50:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:09:50:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-11 23:17:10:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:25:30:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:26:30:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-11 23:33:50:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:42:10:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:43:10:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-11 23:50:30:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:58:50:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-11 23:59:50:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-12 00:07:10:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:15:30:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:16:30:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-12 00:23:50:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:32:10:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:33:10:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-12 00:40:30:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:48:51:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382398600)
2021-10-12 00:49:50:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382398600)
2021-10-12 00:50:07:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1, session: s_8734382398600)
2021-10-12 00:50:07:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: disconnect, envelope_id: None, session: s_8734382398600)
2021-10-12 00:50:07:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.2 Python/3.8.3 slackclient/3.11.2 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-10-12 00:50:08:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Tue, 12 Oct 2021 00:50:08 GMT', 'server': 'Apache', 'x-xss-protection': '0', 'pragma': 'no-cache', 'x-oauth-scopes': 'connections:write', 'cache-control': 'private, no-cache, no-store, must-revalidate', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'x-slack-req-id': '(redacted)', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'x-robots-tag': 'noindex,nofollow', 'x-accepted-oauth-scopes': 'connections:write', 'expires': 'Mon, 26 Jul 1997 05:00:00 GMT', 'vary': 'Accept-Encoding', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'content-encoding': 'gzip', 'content-length': '164', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '85', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-8s3d', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-qpon, envoy-edge-dub-000p', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=(redacted)&app_id=(redacted)'}
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:INFO:A new session (s_8734374893837) has been established
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:Sending a ping message with the newly established connection (s_8734374893837)...
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() executor has been recreated for s_8734374893837
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() executor has been recreated for s_8734374893837
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:The monitor_current_session task for s_8734382398600 is now cancelled
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() execution loop for s_8734374893837 started
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:The running receive_messages task for s_8734382398600 is now cancelled
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() execution loop with s_8734374893837 started
2021-10-12 00:50:08:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1, session: s_8734374893837)
2021-10-12 00:50:08:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None, session: s_8734374893837)
2021-10-12 00:50:08:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None, session: s_8734374893837)
2021-10-12 00:50:08:slack_bolt.AsyncApp:__init__:INFO:The old session (s_8734382398600) has been abandoned
2021-10-12 00:50:08:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: disconnect, envelope_id: None, session: s_8734382398600)
2021-10-12 00:58:18:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:06:38:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734374893837)
2021-10-12 01:06:38:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:14:58:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:23:18:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734374893837)
2021-10-12 01:23:18:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:31:38:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:39:58:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734374893837)
2021-10-12 01:39:58:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:48:18:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 01:56:38:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734374893837)
2021-10-12 01:56:38:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 02:04:58:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 02:13:18:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734374893837)
2021-10-12 02:13:19:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 02:21:39:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734374893837)
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:INFO:The session (s_8734374893837) seems to be already closed. Reconnecting...
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:Inactive connection detected (session_id: s_8734374893837, closed: False, stale: False, current_session.closed: True, is_ping_pong_failing: False)
2021-10-12 02:29:49:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.2 Python/3.8.3 slackclient/3.11.2 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-10-12 02:29:49:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Tue, 12 Oct 2021 02:29:49 GMT', 'server': 'Apache', 'x-xss-protection': '0', 'pragma': 'no-cache', 'x-oauth-scopes': 'connections:write', 'cache-control': 'private, no-cache, no-store, must-revalidate', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'x-slack-req-id': '(redacted)', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'x-robots-tag': 'noindex,nofollow', 'x-accepted-oauth-scopes': 'connections:write', 'expires': 'Mon, 26 Jul 1997 05:00:00 GMT', 'vary': 'Accept-Encoding', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'content-encoding': 'gzip', 'content-length': '164', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '90', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-rvb2', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-3vq7, envoy-edge-dub-a417', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=(redacted)&app_id=(redacted)'}
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:INFO:A new session (s_8734383645471) has been established
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:Sending a ping message with the newly established connection (s_8734383645471)...
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() executor has been recreated for s_8734383645471
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() executor has been recreated for s_8734383645471
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:INFO:The old session (s_8734374893837) has been abandoned
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:The monitor_current_session task for s_8734374893837 is now cancelled
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() execution loop for s_8734383645471 started
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:The running receive_messages task for s_8734374893837 is now cancelled
2021-10-12 02:29:49:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() execution loop with s_8734383645471 started
2021-10-12 02:29:49:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1, session: s_8734383645471)
2021-10-12 02:29:49:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None, session: s_8734383645471)
2021-10-12 02:29:49:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None, session: s_8734383645471)
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:INFO:The session (s_8734383645471) seems to be already closed. Reconnecting...
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:Inactive connection detected (session_id: s_8734383645471, closed: False, stale: False, current_session.closed: True, is_ping_pong_failing: False)
2021-10-12 02:33:09:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/apps.connections.open, params: {}, files: {}, data: {}, json: {}, proxy: {}, headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.2 Python/3.8.3 slackclient/3.11.2 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-10-12 02:33:09:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {'date': 'Tue, 12 Oct 2021 02:33:09 GMT', 'server': 'Apache', 'x-xss-protection': '0', 'pragma': 'no-cache', 'x-oauth-scopes': 'connections:write', 'cache-control': 'private, no-cache, no-store, must-revalidate', 'access-control-allow-origin': '*', 'x-slack-backend': 'r', 'access-control-expose-headers': 'x-slack-req-id, retry-after', 'x-slack-req-id': '(redacted)', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'referrer-policy': 'no-referrer', 'x-content-type-options': 'nosniff', 'x-robots-tag': 'noindex,nofollow', 'x-accepted-oauth-scopes': 'connections:write', 'expires': 'Mon, 26 Jul 1997 05:00:00 GMT', 'vary': 'Accept-Encoding', 'access-control-allow-headers': 'slack-route, x-slack-version-ts, x-b3-traceid, x-b3-spanid, x-b3-parentspanid, x-b3-sampled, x-b3-flags', 'content-encoding': 'gzip', 'content-length': '164', 'content-type': 'application/json; charset=utf-8', 'x-envoy-upstream-service-time': '78', 'x-backend': 'main_normal main_bedrock_normal_with_overflow main_canary_with_overflow main_bedrock_canary_with_overflow main_control_with_overflow main_bedrock_control_with_overflow', 'x-server': 'slack-www-hhvm-main-iad-y7yv', 'x-slack-shared-secret-outcome': 'no-match', 'via': 'envoy-www-iad-ln57, envoy-edge-dub-kb1i', 'x-slack-edge-shared-secret-outcome': 'no-match'}, body: {'ok': True, 'url': 'wss://wss-primary.slack.com/link/?ticket=(redacted)&app_id=(redacted)'}
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:INFO:A new session (s_8734382387911) has been established
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:Sending a ping message with the newly established connection (s_8734382387911)...
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() executor has been recreated for s_8734382387911
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() executor has been recreated for s_8734382387911
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:INFO:The old session (s_8734383645471) has been abandoned
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:The monitor_current_session task for s_8734383645471 is now cancelled
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:A new monitor_current_session() execution loop for s_8734382387911 started
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:The running receive_messages task for s_8734383645471 is now cancelled
2021-10-12 02:33:09:slack_bolt.AsyncApp:__init__:DEBUG:A new receive_messages() execution loop with s_8734382387911 started
2021-10-12 02:33:09:slack_bolt.AsyncApp:async_client:DEBUG:A new message enqueued (current queue size: 1, session: s_8734382387911)
2021-10-12 02:33:09:slack_bolt.AsyncApp:async_client:DEBUG:Message processing started (type: hello, envelope_id: None, session: s_8734382387911)
2021-10-12 02:33:09:slack_bolt.AsyncApp:async_client:DEBUG:Message processing completed (type: hello, envelope_id: None, session: s_8734382387911)
2021-10-12 02:41:19:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 02:49:39:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 02:49:39:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 02:57:59:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:06:19:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 03:06:20:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:14:40:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:23:00:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 03:23:00:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:31:20:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:39:40:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 03:39:40:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:48:00:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 03:56:20:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 03:56:20:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:04:40:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:13:00:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 04:13:00:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:21:20:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:29:40:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 04:29:40:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:38:00:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:46:20:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 04:46:20:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 04:54:40:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:03:00:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 05:03:00:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:11:21:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:19:41:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 05:19:41:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:28:01:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:36:21:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 05:36:21:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:44:41:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 05:53:01:slack_bolt.AsyncApp:__init__:DEBUG:100 session verification executed after the previous same log (s_8734382387911)
2021-10-12 05:53:01:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 06:01:22:slack_bolt.AsyncApp:__init__:DEBUG:100 WebSocket messages received after the previous same log (s_8734382387911)
2021-10-12 06:02:26:slack_bolt.AsyncApp:__init__:DEBUG:The monitor_current_session task for s_8734382387911 is now cancelled
2021-10-12 06:02:26:slack_bolt.AsyncApp:__init__:DEBUG:The running receive_messages task for s_8734382387911 is now cancelled
2021-10-12 06:02:26:slack_bolt.AsyncApp:__init__:INFO:The current session (s_8734382387911) has been abandoned by disconnect() method call

# Somewhere around here, the app is killed. When it's killed, it actually posts a message to a Slack channel to report on this. I can confirm this message was succesfuly posted.

2021-10-12 06:02:26:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Sending a request - url: POST https://www.slack.com/api/chat.postMessage, params: {}, files: {}, data: {}, json: {(redacted)}, proxy: {}, headers: {'Content-Type': 'application/json;charset=utf-8', 'Authorization': '(redacted)', 'User-Agent': 'Bolt-Async/1.9.2 Python/3.8.3 slackclient/3.11.2 Linux/4.14.186-146.268.amzn2.x86_64'}
2021-10-12 06:02:26:slack_bolt.AsyncApp:async_internal_utils:DEBUG:Received the following response - status: 200, headers: {(redacted)}, body: {'ok': True, (redacted)}

Hi @seratch, this didn't happen since my last report above. I believe we can close this issue :) Thank you again for your help!

That's great to hear! Thanks for sharing the result 👍 Let me close this issue now.

slackapi / python-slack-sdk