Recurring rails error on Heroku/Unicorn - 'execution expired', an ActionView::Template::Error

Question

My question is similar to the following, but is happening under slightly different circumstances.

Rails: execution expired on time_zone_select

My setup is:

• Rails 3.2.13
• Unicorn 4.6.2
• Mongoid 3.0.22
• Moped 1.4.2

Running on Heroku Cedar. MongoDB is hosted at MongoLab.

The errors come in batches and are often solved by a Heroku process restart. The first is usually the one below:

An ActionView::Template::Error occurred in [controller]#[action]:

 execution expired
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/sockets/connectable.rb:46:in `read'

The following is the top bit of the stack trace. Happy to add more if needed!

vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/sockets/connectable.rb:46:in `read'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/sockets/connectable.rb:46:in `block in read'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/sockets/connectable.rb:118:in `handle_socket_errors'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/sockets/connectable.rb:46:in `read'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:177:in `read_data'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:99:in `block in read'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:202:in `with_connection'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:97:in `read'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/protocol/query.rb:163:in `receive_replies'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:135:in `block in receive_replies'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:134:in `map'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/connection.rb:134:in `receive_replies'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:553:in `block (2 levels) in flush'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:129:in `ensure_connected'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:551:in `block in flush'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:566:in `logging'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:550:in `flush'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:539:in `process'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/node.rb:349:in `query'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/cursor.rb:138:in `block in load_docs'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/session/context.rb:105:in `block in with_node'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/cluster.rb:250:in `with_secondary'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/session/context.rb:104:in `with_node'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/cursor.rb:137:in `load_docs'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/cursor.rb:25:in `each'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/query.rb:76:in `each'
 vendor/bundle/ruby/1.9.1/gems/moped-1.4.2/lib/moped/query.rb:76:in `each'
 vendor/bundle/ruby/1.9.1/gems/mongoid-3.0.22/lib/mongoid/contextual/mongo.rb:132:in `block in each'
 vendor/bundle/ruby/1.9.1/gems/mongoid-3.0.22/lib/mongoid/contextual/mongo.rb:556:in `selecting'
 vendor/bundle/ruby/1.9.1/gems/mongoid-3.0.22/lib/mongoid/contextual/mongo.rb:131:in `each'
 vendor/bundle/ruby/1.9.1/gems/mongoid-3.0.22/lib/mongoid/contextual.rb:18:in `each'

Rack::Timeout is set for 10 seconds (I believe that was suggested by one of the caching tutorials I read) -- if the answer is to increase the timeout, that's fine. But I wonder if this isn't a slow query issue? The behavior seems to indicate that it's just one of the Unicorn processes that gets hung up (which is why a ps restart seems to cure it).

Any thoughts or tips would be hugely appreciated!

Aleciaaleck

I'm seeing this same problem/stacktrace on EC2 with a very similar stack. – Library

This isn't a solution to the problem, but a slight workaround (and not necessarily a good one) -- I switched out Unicorn for Puma and bumped up to 2 Dynos on Heroku and the problem has reduced by a LARGE factor. But it's still not solved and I'm still getting a handful of 'Execution Expired' errors a day (which is down from a handful an hour). My gut is saying this is a Mongoid/MongoLab issue - either a slow query response or hanging open connections with a non-local database. – Aleciaaleck

Update #2: It's still happening a lot, even with 2 dynos & puma instead of Unicorn. Sigh. – Aleciaaleck

@NoahLehmann-Haupt How many Unicorn workers do you have running? Can you paste your unicorn.rb file into your question? Also, have you confirmed that the query is in fact slow just through Mongo's console? Lastly, it'd be nice to see your controller code. – Bram

@NoahLehmann-Haupt Did you ever get this resolved? I'm having similar problems. – Magyar

I didn't unfortunately :( I ended up switching to Puma and getting rid of Rack::Timeout completely -- site's been working better with that setup. I know that doesn't solve the problem or resolve this issue, sadly. – Aleciaaleck

I'm the guy who asked #15582822 I never ended up figuring out the issue on Heroku, but we switched to Puma (from Unicorn) and moved over to Digital Ocean and the error has been much less common since (about 1/week vs. lots/day). Some people on that question suggested Heroku's file system could be to blame, though I'm not sure why it wouldn't be impacting everyone if that were true. Have you tried asking Heroku support? – Countrydance

Answer 1

I would suggest this is an issue with heroku's file or network system. The modped read method calls' Kernel::select. Select it's self is a system blocking call that will wait for IO objects to become readable. In this case it's the TCP port that makes the external connection to MongoLab. There could be any number of reasons for the TCP port to be come unreadable. Networking and file issues come to mind. I doubt it's a long running query as the socket would be readable during the running of the query there for select would not block the script execution. If the issue persists I would consider moving away from heroku or perhaps an external database on a different network. AWS is always a good choice as they have very low latency between boxen(boxes). HTH

Magnitogorsk

Answer 2

try setting the ruby version to 1.9.3 in your Gemfile, then bundle, commit and deploy again

Cutpurse