Arvados

On 4xphq, with the newly installed keep-balance (cf. #9966), I'm seeing:

keep-balance logs:

Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 timer went off
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 starting next run
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 Run: start
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 skipping 4xphq-bi6l4-rbtrws2jxul6i4t with service type "proxy" 
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 GetCurrentState: start
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 4xphq-bi6l4-8009ayh02ibjfpx (keep1.4xphq.arvadosapi.com:25107, s3): retrieve index
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 4xphq-bi6l4-dk9mjspdg2v8mhq (keep0.4xphq.arvadosapi.com:25107, s3): retrieve index
Oct 31 17:24:37 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:37 collections: 0/25457
Oct 31 17:24:38 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:38 collections: 1000/25457
Oct 31 17:24:39 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:39 collections: 2000/25457
Oct 31 17:24:51 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:51 4xphq-bi6l4-8009ayh02ibjfpx (keep1.4xphq.arvadosapi.com:25107, s3): add 37685 replicas to map
Oct 31 17:24:51 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:51 4xphq-bi6l4-8009ayh02ibjfpx (keep1.4xphq.arvadosapi.com:25107, s3): done
Oct 31 17:24:52 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:52 4xphq-bi6l4-dk9mjspdg2v8mhq (keep0.4xphq.arvadosapi.com:25107, s3): add 37685 replicas to map
Oct 31 17:24:52 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:24:52 4xphq-bi6l4-dk9mjspdg2v8mhq (keep0.4xphq.arvadosapi.com:25107, s3): done
Oct 31 17:25:13 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:25:13 GetCurrentState: took 35.815118053s
Oct 31 17:25:13 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:25:13 Run: took 35.846179352s
Oct 31 17:25:13 4xphq.arvadosapi.com keep-balance[8022]: 2016/10/31 17:25:13 run failed: request failed: {https  <nil> 4xphq.arvadosapi.com:443 /arvados/v1/collections  %!s(bool=false) filters=%5B%5B%22modified_at%22%2C%22%5Cu003e%3D%22%2C%222014-11-07T15%3A42%3A32.50418Z%22%5D%2C%5B%22uuid%22%2C%22%21%3D%22%2C%224xphq-4zz18-ttsnywvm921kkw8%22%5D%5D&limit=100000&order=modified_at%2C+uuid&select=%5B%22uuid%22%2C%22manifest_text%22%2C%22modified_at%22%2C%22portable_data_hash%22%2C%22replication_desired%22%5D }: 422 Unprocessable Entity

api server logs:

#<NoMemoryError: failed to allocate memory>
/var/www/arvados-api/current/app/controllers/application_controller.rb:188:in `dump'
/var/www/arvados-api/current/app/controllers/application_controller.rb:188:in `send_json'
/var/www/arvados-api/current/app/controllers/application_controller.rb:494:in `render_list'
/var/www/arvados-api/current/app/controllers/application_controller.rb:75:in `index'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/base.rb:167:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rendering.rb:10:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:590:in `_run__36149969870514075__process_action__2372069873549583241__callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `__run_callback'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:81:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/callbacks.rb:17:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rescue.rb:29:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications.rb:123:in `block in instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications.rb:123:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/base.rb:121:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/rendering.rb:45:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal.rb:203:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal.rb:246:in `block in action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:73:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:36:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:608:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:177:in `call!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:157:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/builder.rb:48:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/etag.rb:23:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/conditionalget.rb:25:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/head.rb:14:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/flash.rb:242:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:210:in `context'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:205:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/cookies.rb:341:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/query_cache.rb:64:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `_run__2636124107984033352__call__75134247275516573__callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `__run_callback'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:81:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/lograge-0.3.6/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/rack/logger.rb:16:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/tagged_logging.rb:22:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/rack/logger.rb:16:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/request_id.rb:22:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/methodoverride.rb:21:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/runtime.rb:17:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/lock.rb:15:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:245:in `fetch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/var/www/arvados-api/current/app/middlewares/arvados_api_token.rb:59:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/engine.rb:484:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/application.rb:231:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/railtie/configurable.rb:30:in `method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

Error 1477935314+0c4830bc: 422

Once #6830 is done, revisit keep-balance on 4xphq to see if that fixed the problem.