-
Type: Bug
-
Resolution: Done
-
Priority: Minor - P4
-
Affects Version/s: 2.2.1
-
Component/s: None
-
None
We upgraded a cluster to 3.0.8 today and under heavy load the mongoS CPU skyrocketed, which caused a bunch of failures for us. Until we got the mongoS under control, we had thousands of failures from processes which seemed to be talking to that mongoS. I've attached a stack trace.
What are your thoughts here? I've considered doing something like raising an OperationFailure with a magic reconnect string like "query failed" if the deserialize_header method ends up returning an empty array, which should rescan and reconnect.
Jan 07 13:10:26 production.log: [ 6:10:26.455541342] (25416) [ERROR] Uncaught exception: ArgumentError: comparison of Fixnum with nil failed (comparison of Fixnum with nil failed)
Jan 07 13:10:26 production.log: [ 6:10:26.456353665] (25416) [INFO] Stack trace of preceding exception:
Jan 07 13:10:26 production.log: [ 6:10:26.456826961] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/protocol/message.rb:117:in `>'
Jan 07 13:10:26 production.log: [ 6:10:26.457341328] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/protocol/message.rb:117:in `deserialize'
Jan 07 13:10:26 production.log: [ 6:10:26.457783375] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connectable.rb:107:in `block in read'
Jan 07 13:10:26 production.log: [ 6:10:26.458217886] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connectable.rb:91:in `ensure_connected'
Jan 07 13:10:26 production.log: [ 6:10:26.458624425] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connectable.rb:106:in `read'
Jan 07 13:10:26 production.log: [ 6:10:26.458946512] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:180:in `deliver'
Jan 07 13:10:26 production.log: [ 6:10:26.459239606] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:124:in `block in dispatch'
Jan 07 13:10:26 production.log: [ 6:10:26.459529114] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/monitoring/publishable.rb:47:in `publish_command'
Jan 07 13:10:26 production.log: [ 6:10:26.459854535] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:123:in `dispatch'
Jan 07 13:10:26 production.log: [ 6:10:26.460184791] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/auth/cr.rb:57:in `login'
Jan 07 13:10:26 production.log: [ 6:10:26.460463864] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:100:in `authenticate!'
Jan 07 13:10:26 production.log: [ 6:10:26.460726332] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:65:in `connect!'
Jan 07 13:10:26 production.log: [ 6:10:26.460997762] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connectable.rb:89:in `ensure_connected'
Jan 07 13:10:26 production.log: [ 6:10:26.461285063] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:205:in `write'
Jan 07 13:10:26 production.log: [ 6:10:26.461602737] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:179:in `deliver'
Jan 07 13:10:26 production.log: [ 6:10:26.461893333] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:124:in `block in dispatch'
Jan 07 13:10:26 production.log: [ 6:10:26.462198144] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/monitoring/publishable.rb:47:in `publish_command'
Jan 07 13:10:26 production.log: [ 6:10:26.462451279] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:123:in `dispatch'
Jan 07 13:10:26 production.log: [ 6:10:26.462706619] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/auth/cr.rb:57:in `login'
Jan 07 13:10:26 production.log: [ 6:10:26.462995311] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection.rb:100:in `authenticate!'
Jan 07 13:10:26 production.log: [ 6:10:26.463274500] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/context.rb:66:in `block in with_connection'
Jan 07 13:10:26 production.log: [ 6:10:26.463537944] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/connection_pool.rb:108:in `with_connection'
Jan 07 13:10:26 production.log: [ 6:10:26.463779126] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/server/context.rb:63:in `with_connection'
Jan 07 13:10:26 production.log: [ 6:10:26.463854208] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/operation/executable.rb:34:in `execute'
Jan 07 13:10:26 production.log: [ 6:10:26.463898893] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/collection/view/iterable.rb:79:in `send_initial_query'
Jan 07 13:10:26 production.log: [ 6:10:26.463946978] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/collection/view/iterable.rb:41:in `block in each'
Jan 07 13:10:26 production.log: [ 6:10:26.463985731] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/retryable.rb:48:in `call'
Jan 07 13:10:26 production.log: [ 6:10:26.464022837] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/retryable.rb:48:in `read_with_retry'
Jan 07 13:10:26 production.log: [ 6:10:26.464058912] (25416) [INFO] /var/www/platform/shared/dashboard/bundle/ruby/2.2.0/bundler/gems/mongo-ruby-driver-e081de005a92/lib/mongo/collection/view/iterable.rb:39:in `each'