hubot-slack calling bots.info a suspicious number of times

[mistydemeo]

Description

We believe that hubot-slack is calling the bots.info API excessively without caching.

We experienced a rate limit event with our Hubot today. After some investigation from Slack support, this is what they found:

According to our logs, what seems to have happened is that this bot called the bots.info API method (https://api.slack.com/methods/bots.info) at a sustained rate of 70 requests/minute for about 40 minutes.

I audited our own code and it doesn't look like we call it directly. I suspect it might be this uncached invocation in hubot-slack, which is outside our application's code:

hubot-slack/src/client.coffee

Lines 247 to 248 in baca884

	# Bot user is not in mapping - call bots.info
	@web.bots.info(bot: botId).then((r) => r.bot)

What type of issue is this?

• bug
• enhancement (feature request)
• question
• documentation related
• testing related
• discussion

Requirements

• I've read and understood the Contributing guidelines and have done my best effort to follow them.
• I've read and agree to the Code of Conduct.
• I've searched for any related issues and avoided creating a duplicate issue.

---

Bug Report

Reproducible in:

hubot-slack version: Latest git master

node version: v8.2.0

OS version(s): Debian stretch

Steps to reproduce:

Unsure as of yet - because it happens outside our own code we don't know how to cause it to reproduce.

Expected result:

hubot-slack works as normal.

Actual result:

hubot-slack is rate-limited by Slack.

Attachments:

The Slack support request 2659016 may have some additional context for you.

[seratch]

@mistydemeo Hello, thanks for taking the time to report this!

I suspect it might be this uncached invocation in hubot-slack

The implementation has a simple memory cache: https://github.com/slackapi/hubot-slack/blob/v4.7.1/src/client.coffee#L244-L248

Just in case, I've verified it works as expected but I haven't detected any issues so far. It seems properly working at least for simple use cases.

As it's a simple memory caching, restarting your hubot apps or simultaneously running multiple hubot apps may result in issuing more bots.info calls. But I'm not sure if that's the case you mentioned yet.

[mistydemeo]

As it's a simple memory caching, restarting your hubot apps or simultaneously running multiple hubot apps may result in issuing more bots.info calls. But I'm not sure if that's the case you mentioned yet.

We have two Hubots, one of which acts as a backup; it's a form of high-availability with automated failover. However, we've been running in that setup for about four years now. We don't restart Hubot frequently.

We had another outage today, and we're waiting on response from Slack support to find out if it was another rate limiting event for the same reason. There isn't anything in our slackbot's logs to indicate we were rate-limited, however.

[seratch]

@mistydemeo I've verified the behavior of hubot-slack's internal cache for bots.info calls and figured out that the cache is not working with the latest payloads from Slack servers.

I will come up with a pull request addressing the bug and we'll ship a new version including the fix. Thank you very much for reporting this issue and we really appreciate your patience on this.