Skip to content
This repository has been archived by the owner on Jan 15, 2024. It is now read-only.

Connection Timeout - Waited for item but none was pushed. #223

Closed
madwire opened this issue Oct 9, 2013 · 53 comments · Fixed by #228
Closed

Connection Timeout - Waited for item but none was pushed. #223

madwire opened this issue Oct 9, 2013 · 53 comments · Fixed by #228

Comments

@madwire
Copy link

madwire commented Oct 9, 2013

Hi

After updating mongoid and moped (2.0.0.beta2), Im occasionally getting this:

MOPED: Retrying connection attempt 1 more time(s). runtime: n/a
Timeout::Error - Waited for item but none was pushed.:

Im running in development mode with WEBrick so dont understand why its running out of connections

Versions:

  • mongoid: 4.0.0 (484aa0721e89)
  • moped: 2.0.0.beta2
  • ruby: 2.0.0-p0 MRI
  • rails: 4.0.0
@manusajith
Copy link

same here.
anyone has a fix ?

@gautamrege
Copy link

Getting these errors too. Here is more information:

/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:87:in `block in wait_for_next'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:84:in `loop'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:84:in `wait_for_next'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:51:in `block in pop'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:50:in `synchronize'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:50:in `pop'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:182:in `next_connection'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:47:in `block in checkout'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:38:in `synchronize'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:38:in `checkout'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:158:in `with_connection'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/node.rb:129:in `connection'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/node.rb:117:in `connected?'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/node.rb:173:in `down!'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/node.rb:452:in `rescue in refresh'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/node.rb:439:in `refresh'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:166:in `block in refresh'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:178:in `each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:178:in `refresh'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:135:in `nodes'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:224:in `with_primary'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/read_preference/primary.rb:55:in `block in with_node'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/read_preference/selectable.rb:65:in `call'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/read_preference/selectable.rb:65:in `with_retry'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/read_preference/primary.rb:54:in `with_node'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cursor.rb:136:in `load_docs'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/cursor.rb:27:in `each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/gems/moped-2.0.0.beta2/lib/moped/query.rb:77:in `each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/contextual/mongo.rb:123:in `block in each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/contextual/mongo.rb:650:in `selecting'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/contextual/mongo.rb:122:in `each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/contextual.rb:19:in `each'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/criteria/findable.rb:125:in `entries'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/criteria/findable.rb:125:in `from_database'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/criteria/findable.rb:93:in `multiple_from_map_or_db'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/criteria/findable.rb:19:in `execute_or_raise'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/criteria/findable.rb:40:in `find'
/data/app/staging/releases/28/vendor/bundle/ruby/2.0.0/bundler/gems/mongoid-2f68fccf6b45/lib/mongoid/findable.rb:88:in `find'

We debugged this deep and found that the the read function blocks indefinitely (or for a long time) and results in timeout for other workers after some time. I got this stacktrace in sidekiq with 25 workers. I think this problem is also related to the connection pool.

This "hang" originates from refresh in the configure(command("admin", ismaster: 1)) call.

   # moped/node.rb 
   def command(database, cmd, options = {})
      read(Protocol::Command.new(database, cmd, options))
    end

@manusajith
Copy link

increasing the pool_size in my case helped to fix it temporarily

@arthurnn
Copy link
Contributor

@manusajith @madwire are you guys having this issue on sidekiq too? or that is not related to sidekiq at all?

@manusajith
Copy link

@arthurnn i am not using sidekiq in my project

@gautamrege
Copy link

This is NOT related to sidekiq. I see these problems in my nginx + passenger setup too. It's easily reproducible on sidekiq because of a lot of workers.

@gautamrege
Copy link

@arthurnn @manusajith Does the pool_size option really have any effect in mongoid.yml?

staging:
  sessions:
    default:
      database: app_staging
      hosts:
        - localhost:27017
      options:
        consistency: :strong
  options:
    identity_map_enabled: true
    raise_not_found_error: false
  pool_size: 35

This does not seem to have any effect at all .. did I set it wrong? I have not seen any documentation about setting pool_size.

@madwire
Copy link
Author

madwire commented Oct 11, 2013

@arthurnn no sorry Im not using sidekiq either

@madwire
Copy link
Author

madwire commented Oct 11, 2013

@gautamrege think its like this

staging:
  sessions:
    default:
      database: app_staging
      hosts:
        - localhost:27017
      options:
        consistency: :strong
        pool_size: 35

@gautamrege
Copy link

@madwire An Aha! moment. Thanks 👍 This is undocumented.

@gautamrege
Copy link

INDEED -- the problem reduces as I increase the pool_size.
@arthurnn - this is only delaying the inevitable.

@smd686s
Copy link

smd686s commented Oct 11, 2013

I'm having this issue as well. My app is a Rack application running in Puma 2.6 using Grape 0.6. The error is raised in Jruby 1.7.5 and Ruby 2.0.0.

The first few requests run fine but errors begin when ApacheBench testing more than 5 or so concurrent requests. Upping the pool_size to 20 doesn't help.

@arthurnn
Copy link
Contributor

This seems to be a bug somewhere on moped connection pool.. I will take a look into that this weekend, for the time being you guys can point mongoid to mongoid/mongoid@f91feef , which should not have this bug.

thanks

@arthurnn
Copy link
Contributor

Can you guys try to increase the pool_timeout time instead of the pool_size, something like this:

  sessions:
    default:
      options:
        pool_timeout: 30

And let me know if it works or not.

@smd686s
Copy link

smd686s commented Oct 13, 2013

Hello @arthurnn

Increasing the pool_timeout isn't helping. Here is the top of the stacktrace (from jruby but I get the same in mri):

2013-10-12 22:24:55 -0500: Rack app error: #<Timeout::Error: Waited for item but none was pushed.>
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:87:in 'wait_for_next'
org/jruby/RubyKernel.java:1517:in 'loop'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:84:in 'wait_for_next'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:51:in 'pop'
org/jruby/ext/thread/Mutex.java:149:in 'synchronize'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/queue.rb:50:in 'pop'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:182:in 'next_connection'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:47:in 'checkout'
org/jruby/ext/thread/Mutex.java:149:in 'synchronize'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:38:in 'checkout'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/connection/pool.rb:158:in 'with_connection'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/node.rb:129:in 'connection'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/node.rb:117:in 'connected?'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/node.rb:171:in 'down!'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/node.rb:448:in 'refresh'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:166:in 'refresh'
org/jruby/RubyArray.java:1613:in 'each'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:178:in 'refresh'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:135:in 'nodes'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cluster.rb:224:in 'with_primary'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/read_preference/primary.rb:55:in 'with_node'
org/jruby/RubyProc.java:271:in 'call'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/read_preference/selectable.rb:65:in 'with_retry'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/read_preference/primary.rb:54:in 'with_node'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cursor.rb:136:in 'load_docs'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/cursor.rb:27:in 'each'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/gems/moped-2.0.0.beta2/lib/moped/query.rb:77:in 'each'
/home/sean/.rbenv/versions/jruby-1.7.5/lib/ruby/gems/shared/bundler/gems/mongoid-44b1d46e0cf0/lib/mongoid/contextual/mongo.rb:123:in 'each'

@manusajith
Copy link

@arthurnn dint help me either.
guess the connections aren't returned back to the Queue

@arthurnn
Copy link
Contributor

As I cannot simulate the error, could you guys try this attempt of fixing the error? https://github.com/mongoid/moped/tree/conn_pool

@gautamrege
Copy link

Sure! Already on it.

On 14-Oct-2013, at 11:34 AM, Arthur Nogueira Neves notifications@github.com wrote:

As I cannot simulate the error, could you guys try this attempt of fixing the error? https://github.com/mongoid/moped/tree/conn_pool


Reply to this email directly or view it on GitHub.

@manusajith
Copy link

Seems like the reap method is only called for dead threads, and not on sleeping threads too.
I modified active_threads method in pool.rb to as:

def active_threads
    Thread.list.select{ |thread| thread.status == "run"}.map{ |thread| thread.object_id }
end

and was able to return connection back to the queue.

Dunno its the right way to do it.

@arthurnn
Copy link
Contributor

@manusajith I see that. Wondering how would you have sleep threads if you are not running on a concurrent environment, thats what tricks me..
Could you guys also apply this patch: https://gist.github.com/arthurnn/6978381 and post the result of the error when it shows?

thanks

@madwire
Copy link
Author

madwire commented Oct 14, 2013

@arthurnn It looks like sleep threads to me. Still dont get why, as Im running on webrick and ruby mri

Timeout::Error - Waited for item but none was pushed. [thread list: [#<Thread:0x007fb4a30c0cd8 sleep>, #<Thread:0x007fb4aa8799f0 sleep>, #<Thread:0x007fb4a93e3b08 sleep>, #<Thread:0x007fb4aae23c20 sleep>, #<Thread:0x007fb4a379ee38 sleep>, #<Thread:0x007fb4a379ca20 sleep>, #<Thread:0x007fb4a92f87c0 sleep>, #<Thread:0x007fb4a5188ad8 run>, #<Thread:0x007fb4ac507180 sleep>], current: 70206920344940]:
  /Users/richardadams/code/moped/lib/moped/connection/queue.rb:88:in `block in wait_for_next'
  /Users/richardadams/code/moped/lib/moped/connection/queue.rb:84:in `wait_for_next'
  /Users/richardadams/code/moped/lib/moped/connection/queue.rb:51:in `block in pop'
  /Users/richardadams/code/moped/lib/moped/connection/queue.rb:50:in `pop'
  /Users/richardadams/code/moped/lib/moped/connection/pool.rb:182:in `next_connection'
  /Users/richardadams/code/moped/lib/moped/connection/pool.rb:47:in `block in checkout'
  /Users/richardadams/code/moped/lib/moped/connection/pool.rb:38:in `checkout'
  /Users/richardadams/code/moped/lib/moped/connection/pool.rb:158:in `with_connection'
  /Users/richardadams/code/moped/lib/moped/node.rb:129:in `connection'
  /Users/richardadams/code/moped/lib/moped/node.rb:117:in `connected?'
  /Users/richardadams/code/moped/lib/moped/node.rb:171:in `down!'
  /Users/richardadams/code/moped/lib/moped/node.rb:448:in `rescue in refresh'
  /Users/richardadams/code/moped/lib/moped/node.rb:437:in `refresh'
  /Users/richardadams/code/moped/lib/moped/cluster.rb:166:in `block in refresh'
  /Users/richardadams/code/moped/lib/moped/cluster.rb:178:in `refresh'
  /Users/richardadams/code/moped/lib/moped/cluster.rb:135:in `nodes'
  /Users/richardadams/code/moped/lib/moped/cluster.rb:224:in `with_primary'
  /Users/richardadams/code/moped/lib/moped/read_preference/primary.rb:55:in `block in with_node'
  /Users/richardadams/code/moped/lib/moped/read_preference/selectable.rb:65:in `with_retry'
  /Users/richardadams/code/moped/lib/moped/read_preference/primary.rb:54:in `with_node'
  /Users/richardadams/code/moped/lib/moped/query.rb:116:in `first'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual/mongo.rb:201:in `block (2 levels) in first'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual/mongo.rb:537:in `with_sorting'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual/mongo.rb:200:in `block in first'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual/mongo.rb:449:in `try_cache'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual/mongo.rb:199:in `first'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/contextual.rb:19:in `first'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/criteria/modifiable.rb:168:in `find_or'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/criteria/modifiable.rb:68:in `find_or_create_by'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/findable.rb:15:in `find_or_create_by'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid_session_store-b90048c85f7d/lib/mongoid_session_store/mongoid_store.rb:37:in `find_session'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid_session_store-b90048c85f7d/lib/mongoid_session_store/mongoid_store.rb:21:in `get_session'
  rack (1.5.2) lib/rack/session/abstract/id.rb:266:in `load_session'
  actionpack (4.0.0) lib/action_dispatch/middleware/session/abstract_store.rb:43:in `block in load_session'
  actionpack (4.0.0) lib/action_dispatch/middleware/session/abstract_store.rb:51:in `stale_session_check!'
  actionpack (4.0.0) lib/action_dispatch/middleware/session/abstract_store.rb:43:in `load_session'
  actionpack (4.0.0) lib/action_dispatch/request/session.rb:168:in `load!'
  actionpack (4.0.0) lib/action_dispatch/request/session.rb:160:in `load_for_read!'
  actionpack (4.0.0) lib/action_dispatch/request/session.rb:86:in `[]'
  warden (1.2.3) lib/warden/session_serializer.rb:30:in `fetch'
  warden (1.2.3) lib/warden/proxy.rb:212:in `user'
  warden (1.2.3) lib/warden/proxy.rb:318:in `_perform_authentication'
  warden (1.2.3) lib/warden/proxy.rb:127:in `authenticate!'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/safeguard-307d18d4e84c/lib/safeguard/rails/routes.rb:30:in `block in safeguard!'
  actionpack (4.0.0) lib/action_dispatch/routing/mapper.rb:37:in `block in matches?'
  actionpack (4.0.0) lib/action_dispatch/routing/mapper.rb:35:in `matches?'
  actionpack (4.0.0) lib/action_dispatch/routing/mapper.rb:44:in `call'
  actionpack (4.0.0) lib/action_dispatch/journey/router.rb:71:in `block in call'
  actionpack (4.0.0) lib/action_dispatch/journey/router.rb:59:in `call'
  actionpack (4.0.0) lib/action_dispatch/routing/route_set.rb:655:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/app_request_handler.rb:13:in `call'
  rack-contrib (1.1.0) lib/rack/contrib/response_headers.rb:17:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/headers.rb:16:in `call'
  meta_request (0.2.8) lib/meta_request/middlewares/meta_request_handler.rb:13:in `call'
  newrelic_rpm (3.6.6.147) lib/new_relic/rack/error_collector.rb:43:in `call'
  newrelic_rpm (3.6.6.147) lib/new_relic/rack/agent_hooks.rb:22:in `call'
  newrelic_rpm (3.6.6.147) lib/new_relic/rack/browser_monitoring.rb:16:in `call'
  newrelic_rpm (3.6.6.147) lib/new_relic/rack/developer_mode.rb:28:in `call'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/rack/mongoid/middleware/identity_map.rb:34:in `block in call'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/mongoid/unit_of_work.rb:39:in `unit_of_work'
   () Users/richardadams/.rvm/gems/ruby-2.0.0-p0@brynner/bundler/gems/mongoid-484aa0721e89/lib/rack/mongoid/middleware/identity_map.rb:34:in `call'
  warden (1.2.3) lib/warden/manager.rb:35:in `block in call'
  warden (1.2.3) lib/warden/manager.rb:34:in `call'
  rack (1.5.2) lib/rack/etag.rb:23:in `call'
  rack (1.5.2) lib/rack/conditionalget.rb:25:in `call'
  rack (1.5.2) lib/rack/head.rb:11:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/flash.rb:241:in `call'
  rack (1.5.2) lib/rack/session/abstract/id.rb:225:in `context'
  rack (1.5.2) lib/rack/session/abstract/id.rb:220:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/cookies.rb:486:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.0.0) lib/active_support/callbacks.rb:373:in `_run__1115762122771428067__call__callbacks'
  activesupport (4.0.0) lib/active_support/callbacks.rb:80:in `run_callbacks'
  actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/reloader.rb:64:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
  better_errors (0.9.0) lib/better_errors/middleware.rb:84:in `protected_app_call'
  better_errors (0.9.0) lib/better_errors/middleware.rb:79:in `better_errors_call'
  better_errors (0.9.0) lib/better_errors/middleware.rb:56:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.0.0) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.0.0) lib/rails/rack/logger.rb:21:in `block in call'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `block in tagged'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:25:in `tagged'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `tagged'
  railties (4.0.0) lib/rails/rack/logger.rb:21:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
  rack (1.5.2) lib/rack/runtime.rb:17:in `call'
  activesupport (4.0.0) lib/active_support/cache/strategy/local_cache.rb:83:in `call'
  rack (1.5.2) lib/rack/lock.rb:17:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/static.rb:64:in `call'
  railties (4.0.0) lib/rails/engine.rb:511:in `call'
  railties (4.0.0) lib/rails/application.rb:97:in `call'
  rack (1.5.2) lib/rack/lock.rb:17:in `call'
  rack (1.5.2) lib/rack/content_length.rb:14:in `call'
  rack (1.5.2) lib/rack/handler/webrick.rb:60:in `service'
  /Users/richardadams/.rvm/rubies/ruby-2.0.0-p0/lib/ruby/2.0.0/webrick/httpserver.rb:138:in `service'
  /Users/richardadams/.rvm/rubies/ruby-2.0.0-p0/lib/ruby/2.0.0/webrick/httpserver.rb:94:in `run'
  /Users/richardadams/.rvm/rubies/ruby-2.0.0-p0/lib/ruby/2.0.0/webrick/server.rb:295:in `block in start_thread'

@manusajith
Copy link

@arthurnn
Copy link
Contributor

@manusajith Why do you have so many sleep threads? The implementation of moped connection_pool is to pull one connection from the pool for each thread. So if you have threads pulling the connection, going to sleep without releasing them, that might be an application issue.

@madwire
Copy link
Author

madwire commented Oct 15, 2013

@arthurnn I cant see how it can be app related for me, Im not doing anything with threads. Its a very generic app running on MRI and WEBrick in development.

Here is my output again:

Timeout::Error - Waited for item but none was pushed. [thread list: [#<Thread:0x007fb4a30c0cd8 sleep>, #<Thread:0x007fb4aa8799f0 sleep>, #<Thread:0x007fb4a93e3b08 sleep>, #<Thread:0x007fb4aae23c20 sleep>, #<Thread:0x007fb4a379ee38 sleep>, #<Thread:0x007fb4a379ca20 sleep>, #<Thread:0x007fb4a92f87c0 sleep>, #<Thread:0x007fb4a5188ad8 run>, #<Thread:0x007fb4ac507180 sleep>], current: 70206920344940]:

@ralberto
Copy link

Same here.

@thibaudgg
Copy link

Same issue here Timeout::Error: Waited for item but none was pushed, with Sidekiq (concurrency at 25) and pool_size (100) and pool_timeout (30).

Any workaround/patch in the meantime?

Thanks!

@m-barthelemy
Copy link

We have the issue too, had to raise pool_size.
I don't know if it is relevant, but we use Puma with multiple processes and multiple threads.

@manusajith
Copy link

@ralberto @thibaudgg @m-barthelemy is everyone having sleep threads ?

@ralberto
Copy link

Yes.
Here's the output produced after applying @manusajith patch.

ActionView::Template::Error (Waited for item but none was pushed. [
thread list: [#<Thread:0x00000002363c40 sleep>, 
#<Thread:0x00000005e6b428 sleep>, 
#<Thread:0x00000005c3fcf8 sleep>, 
#<Thread:0x00000005c3f0c8 sleep>, 
#<Thread:0x00000005c3e970 sleep>, 
#<Thread:0x00000005c3e100 sleep>,
 #<Thread:0x00000002fce9d0 sleep>, 
#<Thread:0x00000003226b10 run>, 
#<Thread:0x00000005a87d70 sleep>], 
current: 26293640])

@XORwell
Copy link

XORwell commented Oct 22, 2013

for me the error disappeared since i've increased my pool_size + pool_timeout. but i think the root cause, in my case, was an 'app issue': i was updating embedded documents within an after_validation callback. i havent met this error since i changed that to after_save

@zires
Copy link

zires commented Oct 22, 2013

I got same error.

@arthurnn
Copy link
Contributor

WEBBrick on default MRI, spins a new thread to handle every request concurrently: https://github.com/ruby/ruby/blob/trunk/lib/webrick/server.rb#L175, and if the request has a keep-alive header the socket will be open until there is a timeout.(https://github.com/ruby/ruby/blob/trunk/lib/webrick/httpserver.rb#L115)

So if you have a connection_pool sized to 5 and 5+ connections happening within the timeframe of the timeout you`ll get the problem, because threads would be holding the connection without using it.
I wrote a simple middleware to fix this for the time being, https://gist.github.com/arthurnn/7124345, please use that and lemme know if it works.

For sidekiq we need as many connection as the concurrency number, thats by design.

I will discuss the design of the thread pool with @durran and we should try to fix this without having to add the middleware.

@madwire
Copy link
Author

madwire commented Oct 23, 2013

@arthurnn thanks for the update, that explains a lot.

@pkieltyka
Copy link
Contributor

Yea, I'm getting the same issue with mongoid-head, rails 4 and puma

@madwire
Copy link
Author

madwire commented Oct 28, 2013

@pkieltyka if your using puma then all you have todo is increase your pool_size (default 10)

development:
  sessions:
    default:
      database: development_app
      hosts:
        - localhost:27017
      options:
        pool_size: 16

@ghost ghost assigned arthurnn Oct 28, 2013
@pkieltyka
Copy link
Contributor

Thanks Ill give that a shot

On 2013-10-28, at 4:42 PM, Richard Adams notifications@github.com wrote:

@pkieltyka if your using puma then all you have todo is increase your pool_size (default 10)

development:
sessions:
default:
database: development_app
hosts:
- localhost:27017
options:
pool_size: 16

Reply to this email directly or view it on GitHub.

@arthurnn
Copy link
Contributor

branch https://github.com/mongoid/moped/tree/conn_pool_checkin should fix the problem. Could you guys try that out and let me know.

Using that branch, the middleware I wrote is not necessary anymore.

Please let me know if it works, so I can merge it to master.
thanks guys.

@blackxored
Copy link

I'm still experiencing the same error. I haven't tweaked connection pool/tmout though.

@arthurnn
Copy link
Contributor

@blackxored have u tried to use this branch ?

@scotthelm
Copy link

can confirm that a pool size increase did eliminate my Timeout error in sidekiq

@blackxored
Copy link

@Arthur: nevermind, it does fix it I just somehow assumed it was merged on master, realized that wasn't two minutes from my reply. ;) 

Best Regards,
Adrian Perez

Sent from my phone.

On Wed, Oct 30, 2013 at 5:54 AM, scotthelm notifications@github.com
wrote:

can confirm that a pool size increase did eliminate my Timeout error in sidekiq

Reply to this email directly or view it on GitHub:
#223 (comment)

@bmxpert1
Copy link

Branch working good here too. Thanks!

@m-barthelemy
Copy link

@arthurnn The conn_pool_checkin branch seems to have solved the issue for us.

@madwire
Copy link
Author

madwire commented Nov 1, 2013

@arthurnn same here, all is well :)

@gergoerdosi
Copy link

@arthurnn, @durran : Thanks for fixing this. Could you please release beta4 and update Mongoid's gemspec, so we can safely update it on our servers?

@miclovich
Copy link

Could you please merge this to master?

@tetherit
Copy link

tetherit commented Jul 6, 2014

I'm also getting the same issue with mongoid-head, rails 4 and puma - could you please merge this to master?

@geoffw8
Copy link

geoffw8 commented Jul 29, 2014

We seem to be getting this exact same issue. Rails 4 + Sidekiq 3 + Mongoid 4.

@jclusso
Copy link

jclusso commented Oct 23, 2014

Same here.... any idea since we can't set the pool_size?

@Elyasin
Copy link

Elyasin commented Feb 17, 2015

I do believe I still have this error. Increasing pool size did not work for me.

@geoffw8
Copy link

geoffw8 commented Jun 28, 2015

Heh. And I'm back here a year later. Surprised to see my own comment above. Note: increasing pool_size in mongoid worked for me.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.