Old events firing when botkit restarts (after upgrade)

[sporkd]

Hi. I just upgraded to latest version of botkit from a pretty old version (v0.1.1). The problem is now when I start (or restart) botkit, it seems to be remembering the last message that was received, and is triggering that event again. The reason I know it's an old event, is the incoming message contains the same value, e.g { reply_to: 106 } even between restarts. The only way to make it forget 106 is to send a new message into slack. But then that new message becomes the one that gets stuck as reply_to when I restart botkit.

This was definitely not an issue in the previous version I was using.

My event handlers look mostly like this: (however the one that gets triggered will depend on the current message stuck in reply_to)

controller.hears('\\b(subscribe)\\b', ['direct_message','direct_mention','mention'], (bot, message) => {
  // Respond code
});

[sporkd]

A little more info: On startup, I am also seeing other messages without the reply_to attribute. Typically in that case it will be of {type: desktop_notification}. Sometimes it even seems that botkit is responding to its own message that it just posted.

[sporkd]

Final note: When I revert back to v0.2.2 it seems to fix the issue. So whatever it is, it seems to have been introduced by changes in v0.4.

[benbrown]

@sporkd This may actually be related to an issue Slack is having with their API.

[sporkd]

Thanks @benbrown. However, if I move back and forth between v0.2.2 and v0.4 it consistently happens only on v0.4. Does that sound like it could still be an API issue?

[benbrown]

Perhaps not!

Are you using the RTM? Events API?

[sporkd]

@benbrown I'm using RTM in a custom integration. I've put in some additional logging and can confirm that the bot is in fact responding to one of it's own previous replies from before the restart. The whole interaction is happening inside a Slack direct message session I'm having with the bot itself. Botkit seems to be regarding it's own most recent reply as a direct message to itself, and is re-triggering it on the every restart. I am using CTL-C in development mode to stop nodemon.

[benbrown]

So you are receiving those messages again after the bot has restarted? Can you confirm that they are coming down the wire from Slack again?

[sporkd]

Good question. Actually the message does not appear to be coming from slack. I have the following and the hears block is the only thing getting logged...

controller.on('message_received', function(bot, message) {
  console.log("MESSAGE RECEIVED ", message);
}

controller.hears('\\b(help)\\b', ['direct_message','direct_mention','mention'], (bot, message) => {
  console.log("HELP EVENT RECEIVED ", message);
});

In this case, it seems to be replaying a message that the bot itself already generated. The message.text getting logged is text that the bot already responded with in a previous server run. e.g. "For usage help on this bot, just say `help`.". It's detecting it's own reply containing the string help.

[benbrown]

message_received does not fire for the most part in Slack because the messages are always one of the other types...

This is strange for a number of reasons, not the least of which is that Botkit by default should NOT hear its own messages.

[sporkd]

Yes, I do see message_received for other events, like type: hello and presence_changed, but not for this message. Not sure how to test if the message is indeed coming from slack or just being replayed somehow. Perhaps it's something to do with being in a DM with a bot. If no further ideas I can put together a gist to try and reproduce outside our project.

[sporkd]

@benbrown Ok, found the problem! The line of code in SlackBot.js to check if a message is from the Bot itself looks like this: if (message.user == bot.identity.id && message.bot_id).

Unfortunately message.bot_id is not always present! I discovered in our case it's because I have 2 different Botkit instances connecting to the same Bot configured in Slack. Guessing that may not be standard, but perhaps valid when trying to divide event handling between multiple instances. Anyway, the root of the problem seems to be twofold given two instances, botkit1 and botkit2:

1. message.bot_id will always come back undefined when botkit2 instance hears a message from botkit1. In that case I would think the proper thing to do would be to ignore the message because message.user == bot.identity.id. That means the message was sent by the bot user configured in Slack. However, in the scenario above, the first test will pass, but message.bot_id will be undefined. So botkit2 will go ahead and continue processing that message, even though it's from... "itself"?

2. Then, the issue I was seeing on restart was a bit of a continuation of the first; It seems that when RTM reconnects, Slack will remember the most recent message from (all?) users in that channel, and resend them. Guessing so you can attempt to reprocess. So again, what was happening was a message sent by botkit1 was getting picked up when botkit2 instance came online.

Now I think the second scenario in particular is where there's a strong argument that message.bot_id shouldn't be checked. Imagine a scenario where an EC2 instance gets rebuilt and comes back online to replace an old instance. As things currently stand, the Bot will try to process it's own most recent messages thinking they are from a non-bot user.

I located the commit where the bot_id check was introduced here. 6db1cff

And I can confirm that reverting that commit solves all my issues. 😂

I also have suspicion that it might also be a factor in the following reported issues involving duplicate messages: (in some instances I was seeing duplicate messages from instances replying to eachother and on RTM reconnect)
#393
#473

[jonchurch]

Ive touched that line of code before, when events api was released. I cant recall why I made the choice that I did there (or maybe I made a different one). Theres some concerns with slack I believe where bot_id is all you have when using an incoming webhook to post as your app. Its a lil messy on the slack end with determining if the message was by YOUR bot or just a bot. In order to avoid infinite loops of bots talking to bots, I think, we are ignoring messages from all bots here. Botkit doesnt have a standard for talking to other bots, yet. Would be a cool api to implement if anyones up for it! We need to make tests that can catch this stuff when things get changed, especially as more people are relying on botkit and getting bigger. Im trying to create a serverless botkit flavor for a client project to prepare them to scale easily, so very interested in your efforts to load balance on ec2! We are using elastic beanstalk until I can get us onto lambda 👍

…

On Fri, Feb 17, 2017 at 5:24 PM Peter Gumeson ***@***.***> wrote: @benbrown <https://github.com/benbrown> Ok, found the problem! The line of code in SlackBot.js to check if a message is from the Bot itself looks like this: if (message.user == bot.identity.id && message.bot_id). Unfortunately message.bot_id is not always present! I discovered in our case it's because I have 2 different Botkit instances connecting to the same Bot configured in Slack. Guessing that may not be standard, but perhaps valid when trying to divide event handling between multiple instances. Anyway, the root of the problem seems to be twofold given two instances, botkit1 and botkit2: 1. message.bot_id will always come back undefined when botkit2 instance hears a message from botkit1. In that case I would think the proper thing to do would be to ignore the message because message.user == bot.identity.id. That means the message was sent by the bot user configured in Slack. However, in the scenario above, the first test will pass, but message.bot_id will be undefined. So botkit2 will go ahead and continue processing that message, even though it's from... "itself"? 2. Then, the issue I was seeing on restart was a bit of a continuation of the first; It seems that when RTM reconnects, Slack will remember the most recent message from (all?) users in that channel, and resend them. Guessing so you can attempt to reprocess. So again, what was happening was a message sent by botkit1 was getting picked up when botkit2 instance came online. Now I think the second scenario in particular is where there's a strong argument that message.bot_id shouldn't be checked. Imagine a scenario where an EC2 instance gets rebuilt and comes back online to replace an old instance. As things currently stand, the Bot will try to process it's own most recent messages thinking they are from a non-bot user. I located the commit where the bot_id check was introduced here. 6db1cff <6db1cff> And I can confirm that reverting that commit solves all my issues. 😂 I also have suspicion that it might also be a factor in the following reported issues involving duplicate messages: #393 <#393> #473 <#473> — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#663 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AMUR24fHQMko94YEeEV2Wkl_oK0lbpoEks5rdh4cgaJpZM4MDeHK> .

[sporkd]

Thanks for your reply @jonchurch. Sorry I'm just now getting back to you. to address your first point:

I think, we are ignoring messages from all bots here.

This is actually not true. That would be:
|| message.bot_id instead of && message.bot_id

As it stands, it only ignores if message.user == bot.identity.user, which only ignores your bot alone. Of course you want that at the very least, but my whole point was the addition of && message.bot_id can be problematic. That's because sometimes bot_id is undefined (even when it's actually a bot posting). I've observed it when one instance of my bot posts and another hears.

And it seems I'm not alone in noticing missing bot_id from bot messages.
See this ticket: rickeyski/slack-api#13

The original issue #271 that introduced the && message.bot_id check was to accommodate an edge case where a bot wants to impersonate a user and actually DOES want to see messages from itself. They are running the bot with "client" permission which lets a bot take on the username and avatar of a non-bot user. In that case, message.user will still be the same, so they needed a way to know when it was actually from the bot. Enter message.bot_id, which they noticed is present if a bot posts on behalf of a user. Here's an announcement regarding that:

https://medium.com/slack-developer-blog/api-update-new-field-in-api-responses-d23076ea2ef3#.7l27waoxx

However, notice in the above announcement that an as_user: true attribute should also be present in that case. So my suggestion would be to only check for bot_id only if as_user is first true. That should accommodate the bot impersonation feature while I think resolving the unreliability many seem to be seeing with bot_id. I can submit a PR for this.

[sporkd]

Another suggestion is to actually just go ahead and make the change to || message.bot_id. This would always ignore messages from your bot and other bots too. Would solve the problem I'm having and would still be compatible with already merged PR. Can't think of anyone it would break unless they're actually listening to bots other than self-impersonating bots. Seems unusual.

So either

if (message.as_user) {
  // this is our bot posting as another user
  if (message.user == bot.identity.id && message.bot_id) {
    return false;
  }
} else {
  // this is our bot
  if (message.user == bot.identity.id) {
    return false;
  }
}

or

// this is our bot or any another bot
if (message.user == bot.identity.id || message.bot_id) {
  return false;
}

EDIT: removed 3rd option b/c it probably wouldn't work.

Thoughts? @benbrown @jonchurch

[jonchurch]

@sporkd I see now what you are talking about! Thanks for all the detail.

I think that as_user: true is something that is sent on a request to Slack itself, I don't think we get that as part of the response from messages, or in channels.history. At least, in the article you linked to, that seems to be the case. Bot_id and user_id were both present without an as_user field, and I haven't seen as_user in channels.history before. Can anyone confirm this?

I'm partial to the second choice. This sounds like a sane and pragmatic fix for some smelly code. Would remove the ability for people to respond to bot messages, but this isn't officially supported yet anyways. Closing it off for the master branch would give us time to think through officially supporting that before people start relying on it as a feature.

I'll submit a PR

This might solve some of the phantom double message edge case issues that have been kicking around forever to boot.

[sporkd]

Sounds good @jonchurch. In that case I also agree second option is better. In Issue #271 they even propose an additional fix would be checking for ANY presence of bot_id, which option 2 does. I'll watch for the new release and test it out. Thanks for bearing with the long description. Lots of details.

[tlvenn]

Is there any update on this ? I am experiencing the same issue with a single slack bot on reconnect. Slack is sending back the last message 1 or 2 times so it get processed again. @jonchurch did you get to submit a PR in the end ?

Thanks in advance for the update.

[dosberg]

@tlvenn I too was experiencing this problem. I ended up editing my Slackbot_worker.js to include lastPong != 0 on line 210.

if (message != null && bot.botkit.config.rtm_receive_messages && lastPong != 0) {
    botkit.receiveMessage(bot, message);
} 

[Azzuen1]

How do I access the slackbot_worker.js file if I'm using glitch?