Skip to content

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

Closed
@mistydemeo

Description

@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:

# 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.

Activity

seratch

seratch commented on Mar 18, 2020

@seratch
Contributor

@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.

added
needs infoAn issue that is claimed to be a bug and hasn't been reproduced, or otherwise needs more info
on Mar 18, 2020
mistydemeo

mistydemeo commented on Mar 30, 2020

@mistydemeo
ContributorAuthor

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

seratch commented on Apr 1, 2020

@seratch
Contributor

@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.

added
bugM-T: A confirmed bug report. Issues are confirmed when the reproduction steps are documented
and removed
needs infoAn issue that is claimed to be a bug and hasn't been reproduced, or otherwise needs more info
on Apr 1, 2020
self-assigned this
on Apr 1, 2020
added a commit that references this issue on Apr 1, 2020

Fix slackapi#586 hubot-slack calling bots.info a suspicious number of…

334ccc8
added a commit that references this issue on Apr 3, 2020

Merge pull request #588 from seratch/issue-586

3767644
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugM-T: A confirmed bug report. Issues are confirmed when the reproduction steps are documented

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions

    hubot-slack calling bots.info a suspicious number of times · Issue #586 · slackapi/hubot-slack