Writes fail with ConnectionPool::PoolShuttingDownError

[dblock]

Something happens in our MongoDB configuration (likely a step down of a master or some kind of failure) that causes all servers to start reporting the following error: ConnectionPool::PoolShuttingDownError on database writes to primary.

This is recent, we've seen it take out all our writes twice.

Moped 2.0.3
Mongoid 4.0.0

…nnection_pool-2.1.1/lib/connection_pool/timed_stack.rb:  78:in `block (2 levels) in pop'
…nnection_pool-2.1.1/lib/connection_pool/timed_stack.rb:  77:in `loop'
…nnection_pool-2.1.1/lib/connection_pool/timed_stack.rb:  77:in `block in pop'
…nnection_pool-2.1.1/lib/connection_pool/timed_stack.rb:  76:in `synchronize'
…nnection_pool-2.1.1/lib/connection_pool/timed_stack.rb:  76:in `pop'
….0.0/gems/connection_pool-2.1.1/lib/connection_pool.rb:  78:in `checkout'
….0.0/gems/connection_pool-2.1.1/lib/connection_pool.rb:  60:in `with'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 114:in `connection'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 140:in `disconnect'
….0.0/gems/moped-2.0.3/lib/moped/failover/disconnect.rb:  26:in `execute'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 185:in `rescue in ensure_connected'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 188:in `ensure_connected'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 589:in `block in flush'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 617:in `block in logging'
…ctivesupport-4.1.8/lib/active_support/notifications.rb: 159:in `block in instrument'
…4.1.8/lib/active_support/notifications/instrumenter.rb:  20:in `instrument'
…ctivesupport-4.1.8/lib/active_support/notifications.rb: 159:in `instrument'
…uby/2.0.0/gems/moped-2.0.3/lib/moped/instrumentable.rb:  31:in `instrument'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 616:in `logging'
…lic_moped-0.0.12/lib/newrelic_moped/instrumentation.rb:  40:in `block in logging_with_newrelic_trace'
…lic_moped-0.0.12/lib/newrelic_moped/instrumentation.rb:  49:in `call'
…lic_moped-0.0.12/lib/newrelic_moped/instrumentation.rb:  49:in `block in logging_with_newrelic_trace'
…lic_moped-0.0.12/lib/newrelic_moped/instrumentation.rb:  46:in `logging_with_newrelic_trace'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 587:in `flush'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 358:in `pipeline'
…by/2.0.0/gems/moped-2.0.3/lib/moped/operation/write.rb:  47:in `execute'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 665:in `write'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 502:in `update'
…gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/query.rb: 427:in `block in update'
…avity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/cluster.rb: 249:in `block in with_primary'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 204:in `block in ensure_primary'
…ty/ruby/2.0.0/gems/moped-2.0.3/lib/moped/executable.rb:  25:in `execute'
…/gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/node.rb: 203:in `ensure_primary'
…avity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/cluster.rb: 248:in `with_primary'
…gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/query.rb: 426:in `update'
…by/2.0.0/gems/mongoid-4.0.0/lib/mongoid/query_cache.rb: 117:in `update_with_clear_cache'
…gravity/ruby/2.0.0/gems/moped-2.0.3/lib/moped/query.rb: 449:in `update_all'
…by/2.0.0/gems/mongoid-4.0.0/lib/mongoid/query_cache.rb: 117:in `update_all_with_clear_cache'
….0/gems/mongoid-4.0.0/lib/mongoid/contextual/atomic.rb: 152:in `set'
…uby/2.0.0/gems/mongoid-4.0.0/lib/mongoid/contextual.rb:  16:in `set'

[Zhomart]

I started getting this error too. Restarting solved. Now I want to know why is this happening.

I have these settings:

production:
  sessions:
    default:
      uri: <%= ENV['MONGO_URI'] %>
      options:
        timeout: 20
        pool_timeout: 5
        pool_size: 32

I'm using puma with 1 worker and 16:64 threads.

[argami]

Same error here.

Similar configuration but using Mongoid 4.0.1 and Moped 2.0.3

Puma with 3 workers and 8:16 Threads

BTW and not sure if is related, i have the pool_timeout set on 5 and still getting "Waited 0.5 sec" Timeout error

[jarthod]

Got this issue too since my last update of moped and mongoid.
I haven't changed my setup so this is probably a regression.
I have a sidekiq process with 10 threads and a long running daemon with 10 threads
My mongoid is configured with a pool size of 15.

[fedenusy]

Seeing this as well. Mongoid 4.0.1 / Moped 2.0.3.

Running pool sizes 5-50 on different parts of my app. Default pool timeout.

Seems most frequent in multi-threaded environments (sidekiq + my own celluloid app).

Don't think I've seen this in my "single-threaded" Rails instances.

[fedenusy]

I think I see the issue. Check out moped/node.rb line 153:

@pool = Connection::Manager.shutdown(self)

@pool will hold its value until shutdown returns. But shutdown may take some time. During this time, other calls to the node will continue to use the pool that's shutting down.

I'll monkey-patch and report back.

[dblock]

@fedenusy 🎸

[niedfelj]

I have a PR that has been sitting there for all of these issues. PR #338 IMHO Durran's connection fix isn't adequate. There are still some issues to resolve with the way moped handles stepdowns/failovers etc, but I think first we have to get the connection pool behaving properly.

[fedenusy]

@arthurnn I think this issue should remain open. I've had my "fix" live on prod for over a week now, and while the ConnectionPool::PoolShuttingDownError occurs less frequently, it's definitely still there.

#338 seems promising. Definitely worth another look.