Randomly getting BlockingIOError

[daverstam]

I see this error from time to time in our log, wondering if it's normal behaviour?

ERROR:slack_bolt.App:on_error invoked (session id: xxxxxx, error: BlockingIOError, message: [Errno 11] Resource temporarily unavailable)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/slack_sdk/socket_mode/builtin/connection.py", line 284, in run_until_completion
    ] = _receive_messages(
  File "/usr/local/lib/python3.9/site-packages/slack_sdk/socket_mode/builtin/internals.py", line 228, in _receive_messages
    return _fetch_messages(
  File "/usr/local/lib/python3.9/site-packages/slack_sdk/socket_mode/builtin/internals.py", line 251, in _fetch_messages
    remaining_bytes = receive()
  File "/usr/local/lib/python3.9/site-packages/slack_sdk/socket_mode/builtin/internals.py", line 226, in receive
    raise e
  File "/usr/local/lib/python3.9/site-packages/slack_sdk/socket_mode/builtin/internals.py", line 217, in receive
    received_bytes = sock.recv(size)
  File "/usr/local/lib/python3.9/ssl.py", line 1226, in recv
    return self.read(buflen)
  File "/usr/local/lib/python3.9/ssl.py", line 1101, in read
    return self._sslobj.read(len)
BlockingIOError: [Errno 11] Resource temporarily unavailable
INFO:slack_bolt.App:The connection has been closed (session id: xxxxxx)
INFO:slack_bolt.App:Stopped receiving messages from a connection (session id: xxxxxx)
INFO:slack_bolt.App:The session seems to be already closed. Going to reconnect... (session id: xxxxxx)
INFO:slack_bolt.App:Connecting to a new endpoint...
INFO:slack_bolt.App:The connection has been closed (session id: xxxxxx)
INFO:slack_bolt.App:A new session has been established (session id: xxxxxx)
INFO:slack_bolt.App:Connected to a new endpoint...
INFO:slack_bolt.App:Starting to receive messages from a new connection (session id: xxxxxx)

Reproducible in:

$ pip freeze | grep slack
slack-bolt==1.6.0
slack-sdk==3.5.1
$ python --version
Python 3.9.4

The Slack SDK version

$ pip freeze | grep slack
slack-bolt==1.6.0
slack-sdk==3.5.1

Python runtime version

$ python --version
Python 3.9.4

OS info

python:3.9-alpine3.12 Docker image

Steps to reproduce:

Running in socketmode, listening for events

Expected result:

Not disconnecting/reconnecting

Actual result:

Everything works, just that from time to time I see the above error and the client reconnects.

[seratch]

Hi @daverstam, thanks for sharing this. I'm unsure what the cause of this is yet but this may be specific to your hosts / Docker containers. I've never heard of this issue.

That being said, the built-in Socket Mode library may have some room for improvement in terms of proper management of sockets. The SocketModeClient supports other widely used open-source library for WebSocket connection management: https://slack.dev/python-slack-sdk/socket-mode/index.html websocket_client should be an alternative option for you.

If you have a chance, trying the websocket_client implementation out may eliminate the issue. If it works well for you, letting us know that would be greatly appreciated.

[daverstam]

@seratch Thanks for the swift reply!
I must admit since you have not heard of this issue before it sounds like it's my environment that is causing the issue. I'm running the client on a rancher (k8s) cluster and it could be some miss-configuration there that is causing the error.

I will give websocket_client a try during the day/night and let u know if I encounter similar issues

[daverstam]

@seratch I have been running with websocket_client now and it looks a bit better in the logs I would say, with the builtin socket module I would get a lot more disconnects/reconnects.

I get this every fifth hour, I guess it's normal behavior and is coming from slack re-negotiating the connection?:

INFO:slack_bolt.App:Connecting to a new endpoint...
ERROR:websocket:error from callback <function SocketModeClient.connect.<locals>.on_close at 0x7f40e5ce2dc0>: on_close() takes 1 positional argument but 3 were given
INFO:slack_bolt.App:A new session has been established
INFO:slack_bolt.App:Stopped receiving messages from a connection
INFO:slack_bolt.App:Connected to a new endpoint...
INFO:slack_bolt.App:Starting to receive messages from a new connection

If you don't see anything that is strange behavior and should be more investigated I think this case can be closed. If you want to further investigate I will gladly assist in any way I can.

[seratch]

@daverstam Thanks for sharing the results. This is greatly helpful! I appreciate it. As you guessed, regularly reconnecting to a new endpoint is a normal behavior. However,

ERROR:websocket:error from callback <function SocketModeClient.connect..on_close at 0x7f40e5ce2dc0>: on_close() takes 1 positional argument but 3 were given

this error should be fixed. I will create a new issue for this and will look into this.

If you don't see anything that is strange behavior and should be more investigated I think this case can be closed. If you want to further investigate I will gladly assist in any way I can.

Thank you very much for saying this! Although we are keen to reduce unnecessary disconnections, I intentionally designed the built-in client to promptly detect lost connections as early as possible for apps' stability. As long as the reconnection does not fail, we can safely say that this is not a critical issue. As you suggested, I would like to close this issue for now. Thanks again for your help on this 👍