Heroku taking 40 min to execute a post request from Twilio

Question

I'm building a simple app where a user can text a message to a number and have the message saved in my database. This is a rails app with the Twilio API as the SMS service and is deployed on Heroku.

According to the Heroku logs, it is receiving the post request from Twilio but it is not saving to the database. This issue is being very difficult to solve as the time between the post request and simply logging the message to the console is taking 45 minutes.

the route handling the request:

class MessagesController < ActionController::Base

def index
 puts params["Body"]
 @text = Text.create({message: params["Body"], message_date: Date.now})
 @user = User.first
 @user.texts.push(@text)
 end
end

Heroku is saying that there's a 500 error with the post request:

2016-03-09T22:45:29.713143+00:00 heroku[router]: at=info method=POST path="/received" host=app.herokuapp.com request_id=0ec8e694-2b0d-4ac9-9312-d17182f186bd fwd="54.209.0.88" dyno=web.1 connect=43ms service=31ms status=500 bytes=1754

But then the server doesn't respond for approx 45 minutes:

2016-03-09T23:20:37.332477+00:00 heroku[web.1]: Idling

2016-03-09T23:20:37.333120+00:00 heroku[web.1]: State changed from up to down

2016-03-09T23:20:43.313455+00:00 heroku[web.1]: Stopping all processes with SIGTERM

2016-03-09T23:20:44.849078+00:00 app[web.1]: [2016-03-09 23:20:44] FATAL SignalException: SIGTERM

2016-03-09T23:20:44.849090+00:00 app[web.1]: /app/vendor/ruby-2.2.4/lib/ruby/2.2.0/webrick/server.rb:174:in `select'

2016-03-09T23:20:44.849092+00:00 app[web.1]: /app/vendor/ruby-2.2.4/lib/ruby/2.2.0/webrick/server.rb:174:in `block in start'

2016-03-09T23:20:44.849093+00:00 app[web.1]: /app/vendor/ruby-2.2.4/lib/ruby/2.2.0/webrick/server.rb:32:in `start'

2016-03-09T23:20:44.849093+00:00 app[web.1]: /app/vendor/ruby-2.2.4/lib/ruby/2.2.0/webrick/server.rb:162:in `start'

2016-03-09T23:20:44.849094+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/handler/webrick.rb:34:in `run'

2016-03-09T23:20:44.849095+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/server.rb:286:in `start'

2016-03-09T23:20:44.849096+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands/server.rb:80:in `start'

2016-03-09T23:20:44.849097+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:80:in `block in server'

2016-03-09T23:20:44.849098+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:75:in `tap'

2016-03-09T23:20:44.849098+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:75:in `server'

2016-03-09T23:20:44.849099+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'

2016-03-09T23:20:44.849100+00:00 app[web.1]: /app/vendor/bundle/ruby/2.2.0/gems/railties-4.2.5/lib/rails/commands.rb:17:in `'

2016-03-09T23:20:44.849101+00:00 app[web.1]: bin/rails:9:in `require'

2016-03-09T23:20:44.849102+00:00 app[web.1]: bin/rails:9:in `'

2016-03-09T23:20:44.852841+00:00 app[web.1]: [2016-03-09 23:20:44] INFO going to shutdown ...

2016-03-09T23:20:44.852937+00:00 app[web.1]: [2016-03-09 23:20:44] INFO WEBrick::HTTPServer#start done.

2016-03-09T23:20:45.017655+00:00 app[web.1]: => Booting WEBrick

2016-03-09T23:20:45.017668+00:00 app[web.1]: => Rails 4.2.5 application starting in production on http://0.0.0.0:19472

2016-03-09T23:20:45.017671+00:00 app[web.1]: => Ctrl-C to shutdown server

2016-03-09T23:20:45.017670+00:00 app[web.1]: => Run rails server -h for more startup options

2016-03-09T23:20:45.017675+00:00 app[web.1]: This is a test

2016-03-09T23:20:45.017676+00:00 app[web.1]: Exiting

2016-03-09T23:20:45.983638+00:00 heroku[web.1]: Process exited with status 143

Additionally, Twilio is giving a 11200 HTTP retrieval failure, so we're not sure how it is eventually logging the message to our console 40 minutes later.

Any ideas as to what the problem could be? Is this a heroku error, a twilio error, or something we can fix on our own?

Thanks!

Heroku actually responds in 74ms (connect=43ms service=31ms) with the error. Then it does nothing for 35 minutes, and then it goes to sleep (because you're using a free dyno). — Petr Bela

GeekFitness GeekFitness · Accepted Answer · 2016-03-10T21:43:51

My Heroku server did that a while back, and the issue was not running heroku run rake db:migrate first. I did that, and it worked for me after long idles like this.

If you don't have a lot of info in the DB yet, you may need to reset it and try again, which this SO thread helped me with: How to empty DB in heroku

Heroku taking 40 min to execute a post request from Twilio

2 Answers