Hang of process after network failure during read data from mongodb socket

[Eugene Batogov]

Hi
I'm using mondoid-3.1.5 and Resque.
When my resque worker go to mongodb and happen network failure during:
moped/connection.rb:177:in `read_data'
then worker hang forever, while I don't invoke kill -9.
Can I tune mongoid and moped for normal exit from this situation ?
Full log: https://gist.github.com/JohnBat26/7412849/raw/8e9d9910077073fb4cc958b76f97d3d07f8d6f3e/gistfile1.txt
Issue: https://github.com/mongoid/mongoid/issues/3391

[Jon]

I just started getting this, too. Dozens of my Sidekiq workers got "stuck" and when I printed out the backtraces of the threads, it's all Moped. Processes are stuck for hours not doing anything until I kill -9 them:

Has anyone else seen this? What kind of workarounds have you done? It's happening at various Mongoid calls in my code.

• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: [ 2:21:58.998520585] (22221) [INFO] /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/sockets/connectable.rb:46:in `read'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/sockets/connectable.rb:46:in `block in read'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/sockets/connectable.rb:118:in `handle_socket_errors'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/sockets/connectable.rb:46:in `read'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:177:in `read_data'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:99:in `block in read'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:202:in `with_connection'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:97:in `read'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/protocol/query.rb:163:in `receive_replies'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:135:in `block in receive_replies'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:134:in `map'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/connection.rb:134:in `receive_replies'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:617:in `block (2 levels) in flush'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:153:in `ensure_connected'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:615:in `block in flush'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:630:in `logging'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/newrelic_moped-0.0.8/lib/newrelic_moped/instrumentation.rb:40:in `block in logging_with_newrelic_trace'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/newrelic_moped-0.0.8/lib/newrelic_moped/instrumentation.rb:60:in `call'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/newrelic_moped-0.0.8/lib/newrelic_moped/instrumentation.rb:60:in `logging_with_newrelic_trace'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:614:in `flush'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:603:in `process'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:92:in `command'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/node.rb:436:in `refresh'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cluster.rb:171:in `block in refresh'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cluster.rb:185:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cluster.rb:185:in `refresh'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cluster.rb:135:in `nodes'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cluster.rb:247:in `with_secondary'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/session/context.rb:104:in `with_node'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cursor.rb:137:in `load_docs'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/cursor.rb:25:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/query.rb:76:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/bundler/gems/moped-6af3788a1f35/lib/moped/query.rb:76:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/contextual/mongo.rb:122:in `block in each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/contextual/mongo.rb:619:in `selecting'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/contextual/mongo.rb:121:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/contextual.rb:19:in `each'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/criterion/findable.rb:125:in `entries'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/criterion/findable.rb:125:in `from_database'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/criterion/findable.rb:93:in `multiple_from_map_or_db'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/criterion/findable.rb:19:in `execute_or_raise'
• Mar 01 09:21:59 worker-prd-iad-ded-06 production.log: /var/www/dashboard/shared/bundle/ruby/2.0.0/gems/mongoid-3.1.6/lib/mongoid/criterion/findable.rb:40:in `find'

[Jon]

It seems this might have been upstream firewall changes timing out outbound connections on idle workers. Not sure why Moped never timed out in the process, but in my specific case I think we figured it out.