slackapi/python-slack-sdk

[error ] Failed to receive or enqueue a message: TypeError, object of type 'NoneType' has no len()

Closed this issue · 1 comments

jhofeditz commented

We are seeing an unexpected error in our async socket mode logs whenever there is a network issue.
Looking at the code, it appears that simply checking if message_data is not None before checking len() would remove this error without any other effects?

python-slack-sdk/slack_sdk/socket_mode/aiohttp/__init__.py

Line 241 in 7e71b73

if len(message_data) > 0:

Reproducible in:

The slack_sdk version

slack-bolt 1.18.1 The Bolt Framework for Python
slack-sdk 3.26.2 The Slack API Platform SDK for Python

Python runtime version

Python 3.11.4

OS info

issue also occurs in Docker linux container
ProductName: macOS
ProductVersion: 14.2.1
BuildVersion: 23C71
Darwin Kernel Version 23.2.0: Wed Nov 15 21:54:10 PST 2023; root:xnu-10002.61.3~2/RELEASE_X86_64

Steps to reproduce:

  1. start the socket mode async example: https://github.com/slackapi/bolt-python/blob/main/examples/socket_mode_async.py
  2. disconnect the network until the Slack client notices and logs an error
  3. reconnect network and Slack client reconnects successfully (but with an extra error)

Expected result:

This ERROR should not occur in the normal disconnect/reconnect process:

2024-02-11T03:46:58.356189Z [error    ] Failed to receive or enqueue a message: TypeError, object of type 'NoneType' has no len() (s_296440909) location=slack_sdk.socket_mode.aiohttp:302

Actual result:

2024-02-11T03:46:47.653122Z [error    ] Failed to check the current session (s_296440909) or reconnect to the server (error: ClientConnectorError, message: Cannot connect to host ssl:default [nodename nor servname provided, or not known]) location=slack_sdk.socket_mode.aiohttp:202
2024-02-11T03:46:57.652975Z [info     ] The session (s_296440909) seems to be already closed. Reconnecting... location=slack_sdk.socket_mode.aiohttp:185
2024-02-11T03:46:57.653354Z [debug    ] Inactive connection detected (session_id: s_296440909, closed: False, stale: False, current_session.closed: True, is_ping_pong_failing: False) location=slack_sdk.socket_mode.aiohttp:330
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': 'Python/3.11.4 slackclient/3.26.2 Darwin/23.2.0'}
Received the following response - status: 200, headers: {'Date': 'Sun, 11 Feb 2024 03:46:58 GMT', 'Server': 'Apache', }
2024-02-11T03:46:58.356189Z [error    ] Failed to receive or enqueue a message: TypeError, object of type 'NoneType' has no len() (s_296440909) location=slack_sdk.socket_mode.aiohttp:302
2024-02-11T03:46:58.356483Z [info     ] The old session (s_296440909) has been abandoned location=slack_sdk.socket_mode.aiohttp:365
2024-02-11T03:46:58.983811Z [info     ] A new session (s_296441593) has been established location=slack_sdk.socket_mode.aiohttp:384
2024-02-11T03:46:58.984019Z [debug    ] Sending a ping message with the newly established connection (s_296441593)... location=slack_sdk.socket_mode.aiohttp:388
2024-02-11T03:46:58.984273Z [debug    ] A new monitor_current_session() executor has been recreated for s_296441593 location=slack_sdk.socket_mode.aiohttp:396
2024-02-11T03:46:58.984454Z [debug    ] A new receive_messages() executor has been recreated for s_296441593 location=slack_sdk.socket_mode.aiohttp:402
2024-02-11T03:46:58.984600Z [debug    ] The monitor_current_session task for s_296440909 is now cancelled location=slack_sdk.socket_mode.aiohttp:152
2024-02-11T03:46:58.984841Z [debug    ] A new monitor_current_session() execution loop for s_296441593 started location=slack_sdk.socket_mode.aiohttp:144
2024-02-11T03:46:58.985053Z [debug    ] The running receive_messages task for s_296440909 is now cancelled location=slack_sdk.socket_mode.aiohttp:309
2024-02-11T03:46:58.985210Z [debug    ] A new receive_messages() execution loop with s_296441593 started location=slack_sdk.socket_mode.aiohttp:218
2024-02-11T03:46:58.999602Z [debug    ] Received message (type: TEXT, data: {"type":"hello","num_connections":2,"debug_info":{"host":"applink-1","build_number":81,"approximate_connection_time":18060},"connection_info":{"app_id":"A1234"}}, extra: , session: s_296441593) location=slack_sdk.socket_mode.aiohttp:243
2024-02-11T03:46:58.999957Z [debug    ] A new message enqueued (current queue size: 1, session: s_296441593) location=slack_sdk.socket_mode.async_client:105
2024-02-11T03:46:59.000394Z [debug    ] Message processing started (type: hello, envelope_id: None, session: s_296441593) location=slack_sdk.socket_mode.async_client:137
2024-02-11T03:46:59.000662Z [debug    ] Message processing completed (type: hello, envelope_id: None, session: s_296441593) location=slack_sdk.socket_mode.async_client:163
2024-02-11T03:46:59.212906Z [debug    ] Received message (type: PONG, data: bytearray(b'sdk-ping-pong:1707623218.984142'), extra: , session: s_296441593) location=slack_sdk.socket_mode.aiohttp:243
seratch commented

@jhofeditz Thanks for reporting this issue. As you already analyzed, this looks like a simple bug that can happen only when debug-level logging is enabled. We will resolve it in the next release. If you have interest and time to send a PR to resolve it, we are happy to have your contribution! Otherwise, I will take a look at it later this week.