Constant Errors When Reading from RTM Stream

pchang388 commented 3 years ago

I am...

[ ] Reporting a bug
[ ] Suggesting a new feature
[X ] Requesting help with running my bot
[ ] Requesting help writing plugins
[ ] Here about something else

I am running...

Errbot version: 6.4.1
slackclient version: 1.3.2
OS version: Ubuntu 18 / Mac OSX
Python version: 3.6.5
Using a virtual environment: yes
Docker: Yes - Ubuntu 18 base image
Kubernetes: Tried with and without

Issue description

After processing a slack event/message like "$status", I see in the logs:

2021-01-12 22:54:06,831 DEBUG    errbot.backends.slack     Message size: 1607.
2021-01-12 22:54:06,833 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:54:06,838 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:54:06,839 DEBUG    urllib3.connectionpool    Starting new HTTPS connection (1): slack.com:443
2021-01-12 22:54:06,840 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:54:06,842 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:54:06,842 DEBUG    root                      RTM disconnected
2021-01-12 22:54:06,842 ERROR    errbot.backends.slack     Error reading from RTM stream:
Traceback (most recent call last):
  File "/home/errbot/pyenv/lib/python3.6/site-packages/slackclient/server.py", line 283, in websocket_safe_read
    data += "{0}\n".format(self.websocket.recv())
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 310, in recv
    opcode, data = self.recv_data()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 327, in recv_data
    opcode, frame = self.recv_data_frame(control_frame)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 340, in recv_data_frame
    frame = self.recv_frame()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 374, in recv_frame
    return self.frame_buffer.recv_frame()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_abnf.py", line 361, in recv_frame
    self.recv_header()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_abnf.py", line 309, in recv_header
    header = self.recv_strict(2)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_abnf.py", line 396, in recv_strict
    bytes_ = self.recv(min(16384, shortage))
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 449, in _recv
    return recv(self.sock, bufsize)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_socket.py", line 94, in recv
    "Connection is already closed.")
websocket._exceptions.WebSocketConnectionClosedException: Connection is already closed.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/errbot/pyenv/lib/python3.6/site-packages/errbot/backends/slack.py", line 442, in serve_once
    for message in self.sc.rtm_read():
  File "/home/errbot/pyenv/lib/python3.6/site-packages/slackclient/client.py", line 235, in rtm_read
    json_data = self.server.websocket_safe_read()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/slackclient/server.py", line 301, in websocket_safe_read
    "Unable to send due to closed RTM websocket"
slackclient.server.SlackConnectionError: Unable to send due to closed RTM websocket

Also at times seeing:

2021-01-12 22:11:57,400 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:11:57,402 DEBUG    errbot.backends.slack     Message size: 1608.
2021-01-12 22:11:57,404 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:11:57,408 DEBUG    urllib3.connectionpool    Starting new HTTPS connection (1): slack.com:443
2021-01-12 22:11:57,409 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:11:57,410 DEBUG    errbot.backends.slack     No event handler available for user_change, ignoring this event
2021-01-12 22:11:57,410 ERROR    errbot.backends.slack     Error reading from RTM stream:
Traceback (most recent call last):
  File "/home/errbot/pyenv/lib/python3.6/site-packages/errbot/backends/slack.py", line 442, in serve_once
    for message in self.sc.rtm_read():
  File "/home/errbot/pyenv/lib/python3.6/site-packages/slackclient/client.py", line 235, in rtm_read
    json_data = self.server.websocket_safe_read()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/slackclient/server.py", line 283, in websocket_safe_read
    data += "{0}\n".format(self.websocket.recv())
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 310, in recv
    opcode, data = self.recv_data()
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 327, in recv_data
    opcode, frame = self.recv_data_frame(control_frame)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 358, in recv_data_frame
    self.pong(frame.data)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 301, in pong
    self.send(payload, ABNF.OPCODE_PONG)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 250, in send
    return self.send_frame(frame)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 275, in send_frame
    l = self._send(data)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_core.py", line 445, in _send
    return send(self.sock, data)
  File "/home/errbot/pyenv/lib/python3.6/site-packages/websocket/_socket.py", line 117, in send
    return sock.send(data)
  File "/usr/lib/python3.6/ssl.py", line 944, in send
    return self._sslobj.write(data)
  File "/usr/lib/python3.6/ssl.py", line 642, in write
    return self._sslobj.write(data)
BrokenPipeError: [Errno 32] Broken pipe

Steps to reproduce

Run errbot and wait for it to start up and connect to Slack. Then run any "$status" command and the bot may respond at times before running into the errors above or just throw the error without responding to the command.

Additional info

I am trying to understand why the connection to slack keeps closing and tried playing around with the XMPP_KEEPALIVE_INTERVAL property in the config but with no results/improvements.

I am running into the "Broken Pipe" more consistently and any help would be appreciated.

ppinzon commented 3 years ago

I would suggest running a newer version of the bot with the slackRTM backend, which uses the newer slack-client versions.

On your requirements you can get it by putting errbot as:

errbot[slack-rtm]

or

errbot==6.1.7
slackclient==2.9.3

then in config file put the backend as 'SlackRTM'

I'm not sure is this will work fine in python3.6, but if you are using docker you can just bump the base image to python3.8

pchang388 commented 3 years ago

Hey @ppinzon,

Thanks for the suggestion! The update to slackclient >= 2.9.3 seems to have resolved the issue with intermittent connection resets. I actually didn't see that in the documentation so this was very helpful.

errbotio / errbot