SlackRTM: websocket closing causes echoing

[torgeirl]

I am...

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

I am running...

• Errbot version: v6.1, but from PR fix: Missing 'id_' argument #1443
• OS version: Debian
• Python version: 3.7
• Using a virtual environment: no (using Docker instead)
• Backend: SlackRTM

Issue description

After less than 24h the bot starts echoing command, as if they were given multiple times. It seems to happen after the slack.rtm.client reports that the websocket was closed, in some instances after six+ hours inactivity. After just a few days, you'll get ten+ answers per command given.

Steps to reproduce

Create a bot using the SlackRTM backend, and let it run for a few days. Try the !uptimecommand, and after a day your should get multiple answers. You should have a warning for the websocket to close for each extra copy:

WARNING  slack.rtm.client          Websocket was closed.
INFO     errbot.core               Activate internal commands
INFO     errbot.plugin_manager     Activate bot plugins...
INFO     errbot.plugin_manager     Activate plugin: TextCmds.
INFO     errbot.core_plugins.wsview Checking TextModeCmds for webhooks
INFO     errbot.plugin_manager     Activate plugin: Webserver.
INFO     errbot.plugins.Webserver  Webserver is not configured. Forbid activation
INFO     errbot.core_plugins.wsview Checking Webserver for webhooks
INFO     errbot.core_plugins.wsview Webhook routing echo
INFO     errbot.core               Notifying connection to all the plugins...
INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
INFO     errbot.core               Plugin activation done.
INFO     errbot.core               Activate internal commands
INFO     errbot.plugin_manager     Activate bot plugins...
INFO     errbot.plugin_manager     Activate plugin: TextCmds.
INFO     errbot.core_plugins.wsview Checking TextModeCmds for webhooks
INFO     errbot.plugin_manager     Activate plugin: Webserver.
INFO     errbot.plugins.Webserver  Webserver is not configured. Forbid activation
INFO     errbot.core_plugins.wsview Checking Webserver for webhooks
INFO     errbot.core_plugins.wsview Webhook routing echo
INFO     errbot.core               Notifying connection to all the plugins...
INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
INFO     errbot.core               Plugin activation done.

Note: this list of actions caused from a websocket closing is not the same as an initial start of the bot or a restart using the !restart command (those two looks to be exact copies).

Additional info

Workaround: restart your bot using the !restart command.

[sijis]

Would you be able to see if experience the same effects if you use the Slack backend that's on master branch?

We got a recent merged on updating the backend to work with the recent api depreciation, so it's possible the rtm based one may actually not be required anymore

[torgeirl]

@sijis: I'm testing with the master branch now, but it will take me some days to test due to the nature of this issue.

[torgeirl]

It actually took less than three hours to reproduce this issue using the master branch:

2020-09-03 15:30:32,853 INFO     **last interaction with user command**
2020-09-03 18:25:39,615 WARNING  slack.rtm.client          Websocket was closed.
2020-09-03 18:25:40,373 INFO     errbot.core               Activate internal commands
2020-09-03 18:25:40,374 INFO     errbot.plugin_manager     Activate bot plugins...
2020-09-03 18:25:40,374 INFO     errbot.plugin_manager     Activate plugin: TextCmds.
2020-09-03 18:25:40,375 INFO     errbot.core_plugins.wsview Checking TextModeCmds for webhooks
2020-09-03 18:25:40,375 INFO     errbot.plugin_manager     Activate plugin: Webserver.
2020-09-03 18:25:40,376 INFO     errbot.plugins.Webserver  Webserver is not configured. Forbid activation
2020-09-03 18:25:40,376 INFO     errbot.core_plugins.wsview Checking Webserver for webhooks
2020-09-03 18:25:40,376 INFO     errbot.core_plugins.wsview Webhook routing echo
2020-09-03 18:25:40,377 INFO     errbot.core               Notifying connection to all the plugins...
2020-09-03 18:25:40,377 INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
2020-09-03 18:25:40,377 INFO     errbot.core               Plugin activation done.
2020-09-03 18:25:40,377 INFO     errbot.core               Activate internal commands
2020-09-03 18:25:40,377 INFO     errbot.plugin_manager     Activate bot plugins...
2020-09-03 18:25:40,378 INFO     errbot.plugin_manager     Activate plugin: TextCmds.
2020-09-03 18:25:40,378 INFO     errbot.core_plugins.wsview Checking TextModeCmds for webhooks
2020-09-03 18:25:40,378 INFO     errbot.plugin_manager     Activate plugin: Webserver.
2020-09-03 18:25:40,379 INFO     errbot.plugins.Webserver  Webserver is not configured. Forbid activation
2020-09-03 18:25:40,379 INFO     errbot.core_plugins.wsview Checking Webserver for webhooks
2020-09-03 18:25:40,379 INFO     errbot.core_plugins.wsview Webhook routing echo
2020-09-03 18:25:40,380 INFO     errbot.core               Notifying connection to all the plugins...
2020-09-03 18:25:40,380 INFO     errbot.plugins.ChatRoom   Connecting bot chatrooms
2020-09-03 18:25:40,380 INFO     errbot.core               Plugin activation done.
2020-09-03 19:01:31,088 INFO     errbot.plugins.ACLs       Matching ACL {} against username @torgeirl for command Health:uptime.
2020-09-03 19:01:31,089 INFO     errbot.core               Processing command "uptime" with parameters "" from @torgeirl
2020-09-03 19:01:31,375 INFO     errbot.plugins.ACLs       Matching ACL {} against username @torgeirl for command Health:uptime.
2020-09-03 19:01:31,376 INFO     errbot.core               Processing command "uptime" with parameters "" from @torgeirl

We got a recent merged on updating the backend to work with the recent api depreciation, so it's possible the rtm based one may actually not be required anymore

So it could be working this the old Slack API?

[sijis]

Ya. The "Slack" backend was recently updated to handle the depreciation api's, so it should work there. The rtm one was headed that way but those api's also became obsolete too (as it took us a long time to get there.)

[torgeirl]

Ok, testing the regular Slack backend from the master branch now. So far so good!

[torgeirl]

• the master branch also experience a websocket exception that cause a Python error (issue Gracefully handle Slack websocket closing #1449)
• contrary to the SlackRTM backend, the Slack backend does not trigger command echoing 🎉