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!

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