Botkit: possible problems with Events API and Heroku

[tylermachado]

Putting this here for posterity's sake.

I've been attempting to port my Heroku-based bot to the Events API instead of the RTM API and have been having no luck so far.

This problem initially arose on my primary bot which does not use Botkit Studio. The bot would not respond to commands after switching to the Events API. Nothing would appear in Slack, and the Heroku logs only responded with a "Request timeout" message. Additionally, attempts to console.log the inbound messages to Heroku weren't responding with anything in the logs.

As an experiment, I booted up two Botkit Studio-based bots using the _botkit-starter-slack_ repo, one locally and one on Heroku, leaving them otherwise identical and not making any modifications to the code. The local one continues to work as expected. The Heroku one responded to my first couple of interactions, but then stopped responding and now nothing appears in Slack when I direct message it. I am not getting any error messages in Slack. I am only getting a timeout message in my Heroku logs as the only sign of an error.

2017-03-20T19:19:00.104243+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/slack/receive" host=hbr-botkit-test-2.herokuapp.com request_id=[LONGSTRING] fwd="52.90.33.223" dyno=web.1 connect=1ms service=30001ms status=503 bytes=0 protocol=https

[peterswimm]

Could you try and open a ticket with Heroku and see if they can provide any additional debug information?

[tylermachado]

Will do.

[jonchurch]

Have you checked out issue #504?

[peterswimm]

@jonchurch thanks for reminding me about these, Ill see about getting the info added to our docs.
@tylermachado Let me know if that fixes your problem!

[tylermachado]

Unfortunately I'm still seeing a 503 timeout error in my logs.

(To be clear, since my bot architecture is slightly different than that example, what I did was add a Procfile with node bot.js and made sure that new Worker dyno was on after deploying. Already had my config vars in place, a start script and PORT in all caps.)

The Worker dyno idea does kinda make sense to me though? Do requests to the /slack/receive URL require a certain type of dyno? I believe I've been on web only with the RTM API and attempts at Events API.

[tylermachado]

Still going back and forth with Heroku trying to get information, but I have a theory:

Using the botkit-starter-slack setup, the bot works fine until the Heroku dyno goes to sleep, after 30 minutes or so. When the dyno wakes back up, the bot is not working again unless I go back to the Oauth page and re-authorize it, then it's fine. So maybe the Oauth information stored somewhere on Heroku's ephemeral storage system, and subsequently wiped out, and so after it's been idle for a second those requests are coming from what the bot thinks is a non-authed place?

(I'm hazy on both the server storage stuff and exactly where Oauth tokens are required in the Slack setup, so maybe this is way off.)

[benbrown]

@tylermachado yes, i think you nailed it. the starter kit, by default, uses the local filesystem storage, which Heroku clears each time.

We have an internal issue open to turn on a Mongo plugin automatically when deploying to Heroku, but have not yet implemented the change.

[jonchurch]

Hmmm Im not sure why you'd be seeing a timeout in this instance? Ben is right that a JSON filestore wont work on heroku, you can switch to the botkit mongo storage module

I could be misunderstanding the error heroku is throwing, but you say you dont have an error in your botkit logs? Even with debugging on?

When the JSON file system gets wiped out by heroku, itll cause the findAppropriateTeam() function in handleWebhookPayload() to throw an error (or at least it certainly should!).

But it sounds like from your logs the message is never hitting your server? Because we respond promptly with a 200 at the webhook, before we go looking in the db for team info. So the bot could fail without team info, but that request shouldn't timeout.

Can you confirm if you are getting a request sent to your webhook? Maybe stick a console.log in there to see that youre getting the request body.

[tylermachado]

@jonchurch Yeah the JSON file storage thing was mainly a problem on the sample bot I set up. We use a custom Postgres storage system on the real bot -- trying to figure out if something got disconnected from that when switching to Events.

I do have debug turned on, and I see the other usual debug events (like debug: Setting up a handler for direct_message,direct_mention,mention and so forth.)

But when I send a DM to the bot, I don't see any debug event or anything else from Slack. I only see the Heroku 503 error that I put in my initial post.

I think that's correct that the message isn't hitting the server? I put a console.log() as the very first thing in the default handler for any direct message, but nothing is getting logged from the Slack side. Like SOMETHING is coming from Slack to trigger that timeout, but anything in my direct message handler isn't coming through.

(one more thing: a lot of my code is based on an earlier version of Botkit, like 0.2.0 -- I notice now that the samples are architected much differently. I do have createWebhookEndpoints and handleWebhookPayload in my controller setup and I've updated my version of Botkit and its dependencies, but I'm digging around for other possible incompatibilities too.)

[tylermachado]

Just to be clear on my previous message: I am also console.logging req.body in controller.webserver.post to the slack/receive URL, and that works fine. The place where console.log doesn't work is controller.on('direct_message, ....

[tylermachado]

Just to close the loop on this: I think all my issues were ultimately due to some differences in how my app was parsing my Postgres DB vs. how the Botkit samples do. Eventually solved by duplicating a lot of the library code in my custom additions, changing parts relating to storage as need be. Thanks for all the help and guidance, all.

(I'm still working through how much of the tips from 504 are needed for the Slack implementation -- for example I'm not sure you need to spin up a Heroku worker dyno in my case.)

[abinashmohanty]

I'm just facing the same issue after adding the urls of interactive message to myherokuapp.com/slack/receive

2017-04-27T18:43:17.493888+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/slack/receive" host=slack-uxbot.herokuapp.com request_id=c9b52875-2064-4bb5-b8fe-52df56a3eaa0 fwd="54.165.241.61" dyno=web.1 connect=1ms service=30000ms status=503 bytes=0 protocol=https

Already posted this via heroku ticket.

[dgs10]

I'm facing this issue too...