Ruby China

新手问题 Unicorn + Mongoid 发现 Unicorn 工作进程在压力测试的时候挂的，求破

zangcw · 2013年11月24日 · 最后由 allenwei 回复于 2013年11月24日 · 3491 次阅读

环境是这样的 ruby 1.9.3-p448 mongoid 3.1.5 padrino 0.11.2 unicorn 4.7 正常跑起来没有事，但是用 ab 压力测试，就发现 unicorn.stderr.log 里 worker 都挂了，挂的原因还都不一样 有

ArgumentError - negative length -463994859 given:

app error: "The operation: #<Moped::Protocol::Command\n  @length=58\n  @request_id=3\n  @response_to=0\n  @op_code=2004\n  @flags=[]\n  @full_collection_name=\"admin.$cmd\"\n  @skip=0\n  @limit=-1\n  @selector={:ismaster=>1}\n  @fields=nil>\nfailed with error nil" (Moped::Errors::OperationFailure)

Moped::Errors::OperationFailure - The operation: #<Moped::Protocol::Command
  @length=123
  @request_id=11
  @response_to=0
  @op_code=2004
  @flags=[:slave_ok]
  @full_collection_name="group_production.$cmd"
  @skip=0
  @limit=-1
  @selector={:count=>"users", :query=>{"$and"=>[{"_id"=>{"$in"=>[]}}]}}
  @fields=nil>
failed with error nil:

单体跑的时候都正常，为什么呢？有没有相同遭遇的？

linjunhalida #1 2013年11月24日

traceback 信息呢？贴出来看看哪里出错。

zangcw #2 2013年11月24日 

E, [2013-11-24T18:52:09.628399 #2355] ERROR -- : app error: undefined method `__bson_load__' for nil:NilClass (NoMethodError)
E, [2013-11-24T18:52:09.628594 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/bson/extensions/array.rb:29:in `__bson_load__'
E, [2013-11-24T18:52:09.645368 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/bson/extensions/hash.rb:30:in `__bson_load__'
E, [2013-11-24T18:52:09.645538 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/bson/document.rb:21:in `deserialize'
E, [2013-11-24T18:52:09.645605 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:116:in `block (2 levels) in read'
E, [2013-11-24T18:52:09.645667 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:115:in `times'
E, [2013-11-24T18:52:09.645730 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:115:in `each'
E, [2013-11-24T18:52:09.645792 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:115:in `map'
E, [2013-11-24T18:52:09.645854 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:115:in `block in read'
E, [2013-11-24T18:52:09.645915 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:202:in `with_connection'
E, [2013-11-24T18:52:09.645977 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:97:in `read'
E, [2013-11-24T18:52:09.646039 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/protocol/query.rb:163:in `receive_replies'
E, [2013-11-24T18:52:09.646120 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:135:in `block in receive_replies'
E, [2013-11-24T18:52:09.646205 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:134:in `map'
E, [2013-11-24T18:52:09.646277 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/connection.rb:134:in `receive_replies'
E, [2013-11-24T18:52:09.646343 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:584:in `block (2 levels) in flush'
E, [2013-11-24T18:52:09.646407 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:150:in `ensure_connected'
E, [2013-11-24T18:52:09.646469 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:582:in `block in flush'
E, [2013-11-24T18:52:09.646542 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:597:in `logging'
E, [2013-11-24T18:52:09.646620 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:581:in `flush'
E, [2013-11-24T18:52:09.646687 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:570:in `process'
E, [2013-11-24T18:52:09.646751 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/node.rb:370:in `query'
E, [2013-11-24T18:52:09.646815 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/session/context.rb:44:in `block in query'
E, [2013-11-24T18:52:09.646878 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/session/context.rb:105:in `block in with_node'
E, [2013-11-24T18:52:09.646953 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/cluster.rb:251:in `with_secondary'
E, [2013-11-24T18:52:09.647032 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/session/context.rb:104:in `with_node'
E, [2013-11-24T18:52:09.647110 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/session/context.rb:43:in `query'
E, [2013-11-24T18:52:09.647205 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/moped-1.5.1/lib/moped/query.rb:115:in `first'
E, [2013-11-24T18:52:09.647296 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/mongoid-3.1.5/lib/mongoid/contextual/mongo.rb:196:in `block in first'
E, [2013-11-24T18:52:09.647363 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/mongoid-3.1.5/lib/mongoid/contextual/mongo.rb:506:in `with_sorting'
E, [2013-11-24T18:52:09.647429 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/mongoid-3.1.5/lib/mongoid/contextual/mongo.rb:195:in `first'
E, [2013-11-24T18:52:09.647492 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/mongoid-3.1.5/lib/mongoid/contextual.rb:19:in `first'
E, [2013-11-24T18:52:09.647554 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/mongoid-3.1.5/lib/mongoid/finders.rb:102:in `find_by'
E, [2013-11-24T18:52:09.647618 #2355] ERROR -- : /home/group/csdn_group/app/auth_middleware.rb:13:in `call'
E, [2013-11-24T18:52:09.647679 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/xss_header.rb:18:in `call'
E, [2013-11-24T18:52:09.647740 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/base.rb:50:in `call'
E, [2013-11-24T18:52:09.647800 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/base.rb:50:in `call'
E, [2013-11-24T18:52:09.647863 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/path_traversal.rb:16:in `call'
E, [2013-11-24T18:52:09.647925 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/json_csrf.rb:18:in `call'
E, [2013-11-24T18:52:09.647997 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/base.rb:50:in `call'
E, [2013-11-24T18:52:09.648061 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/base.rb:50:in `call'
E, [2013-11-24T18:52:09.648135 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-protection-1.5.1/lib/rack/protection/frame_options.rb:31:in `call'
E, [2013-11-24T18:52:09.648202 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'
E, [2013-11-24T18:52:09.648264 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'
E, [2013-11-24T18:52:09.648325 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'
E, [2013-11-24T18:52:09.648386 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'
E, [2013-11-24T18:52:09.648447 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/sinatra-1.4.4/lib/sinatra/base.rb:2004:in `call'
E, [2013-11-24T18:52:09.648510 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/sinatra-1.4.4/lib/sinatra/base.rb:1469:in `block in call'
E, [2013-11-24T18:52:09.648571 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/sinatra-1.4.4/lib/sinatra/base.rb:1778:in `synchronize'
E, [2013-11-24T18:52:09.648643 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/sinatra-1.4.4/lib/sinatra/base.rb:1469:in `call'
E, [2013-11-24T18:52:09.648717 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/padrino-core-0.11.2/lib/padrino-core/router.rb:83:in `block in call'
E, [2013-11-24T18:52:09.648781 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/padrino-core-0.11.2/lib/padrino-core/router.rb:76:in `each'
E, [2013-11-24T18:52:09.648844 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/padrino-core-0.11.2/lib/padrino-core/router.rb:76:in `call'
E, [2013-11-24T18:52:09.648906 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/lib/unicorn/http_server.rb:580:in `process_client'
E, [2013-11-24T18:52:09.648969 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/lib/unicorn/http_server.rb:660:in `worker_loop'
E, [2013-11-24T18:52:09.649045 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/lib/unicorn/http_server.rb:527:in `spawn_missing_workers'
E, [2013-11-24T18:52:09.649120 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/lib/unicorn/http_server.rb:538:in `maintain_worker_count'
E, [2013-11-24T18:52:09.649261 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/lib/unicorn/http_server.rb:303:in `join'
E, [2013-11-24T18:52:09.649330 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/gems/unicorn-4.7.0/bin/unicorn:126:in `<top (required)>'
E, [2013-11-24T18:52:09.649401 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/bin/unicorn:19:in `load'
E, [2013-11-24T18:52:09.649465 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/bin/unicorn:19:in `<main>'
E, [2013-11-24T18:52:09.649528 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/bin/ruby_executable_hooks:15:in `eval'
E, [2013-11-24T18:52:09.649600 #2355] ERROR -- : /home/group/.rvm/gems/ruby-1.9.3-p448/bin/ruby_executable_hooks:15:in `<main>'
E, [2013-11-24T18:52:40.433860 #2317] ERROR -- : worker=1 PID:2349 timeout (31s > 30s), killing
E, [2013-11-24T18:52:40.434031 #2317] ERROR -- : worker=4 PID:2352 timeout (31s > 30s), killing
E, [2013-11-24T18:52:40.440808 #2317] ERROR -- : reaped #<Process::Status: pid 2349 SIGKILL (signal 9)> worker=1
E, [2013-11-24T18:52:40.440952 #2317] ERROR -- : reaped #<Process::Status: pid 2352 SIGKILL (signal 9)> worker=4
I, [2013-11-24T18:52:40.459634 #2360]  INFO -- : worker=1 ready
I, [2013-11-24T18:52:40.461923 #2363]  INFO -- : worker=4 ready
zangcw #3 2013年11月24日

#1 楼 @linjunhalida 只要一压力就这样，但是平常查询什么的，也不出问题

allenwei #4 2013年11月24日

worker=1 PID:2349 timeout (31s > 30s), killing 超时进程被自动关闭了

需要 登录 后方可回复, 如果你还没有账号请 注册新账号