Techioz Blog

Rails アプリが #<ArgumentError: uncaught throw {:recursive_key=>true, 20687660=>true}> でクラッシュしました

概要

nginx とパッセンジャーを実行する 3 つの Web ノードで、非常に多くのリクエスト (1 分あたり 400 リクエスト) の Rails アプリを実行しています。

しかし、ここ数日、500 エラーによるクラッシュが数回発生しました。 nginx エラー ログには何も見つかりません。 Rails ログにはあまり説明のないエラーメッセージが表示されます。これを追跡するのに協力していただけると幸いです。

ArgumentError: uncaught throw {:__recursive_key__=>true, 20687660=>true}

スタックトレース：

/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:57:in `block in nary'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:57:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:57:in `nary'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `block in visit_Array'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `visit_Array'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:146:in `visit_Arel_Nodes_SelectCore'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `block in visit_Array'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:169:in `visit_Array'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:153:in `visit_Arel_Nodes_SelectStatement'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:29:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/depth_first.rb:12:in `visit'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:9:in `accept'
/var/www/app/shared/bundle/ruby/2.1.0/gems/arel-6.0.3/lib/arel/nodes/node.rb:56:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/calculations.rb:210:in `grep'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/calculations.rb:210:in `perform_calculation'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/calculations.rb:127:in `calculate'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/calculations.rb:42:in `count'
/var/www/app/releases/20160607074820/app/models/webshop.rb:135:in `show_custom_pickup_identifier?'
/var/www/app/releases/20160607074820/app/controllers/standard/shopify_controller.rb:176:in `block (2 levels) in shop_shipping'
/var/www/app/releases/20160607074820/app/controllers/standard/shopify_controller.rb:173:in `each'
/var/www/app/releases/20160607074820/app/controllers/standard/shopify_controller.rb:173:in `block in shop_shipping'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/delegation.rb:46:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/relation/delegation.rb:46:in `each'
/var/www/app/releases/20160607074820/app/controllers/standard/shopify_controller.rb:157:in `shop_shipping'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/base.rb:198:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/rendering.rb:10:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:117:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:117:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:505:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:505:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:81:in `run_callbacks'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/callbacks.rb:19:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/rescue.rb:29:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications.rb:164:in `block in instrument'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications.rb:164:in `instrument'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/base.rb:137:in `process'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionview-4.2.4/lib/action_view/rendering.rb:30:in `process'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal.rb:196:in `dispatch'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_controller/metal.rb:237:in `block in action'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/routing/route_set.rb:76:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/routing/route_set.rb:76:in `dispatch'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/routing/route_set.rb:45:in `serve'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/journey/router.rb:43:in `block in serve'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/journey/router.rb:30:in `each'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/journey/router.rb:30:in `serve'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/routing/route_set.rb:821:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/etag.rb:24:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/conditionalget.rb:38:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/flash.rb:260:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:225:in `context'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:220:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/cookies.rb:560:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/query_cache.rb:36:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:81:in `run_callbacks'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/rack/logger.rb:38:in `call_app'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/rack/logger.rb:20:in `block in call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/tagged_logging.rb:68:in `block in tagged'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/tagged_logging.rb:26:in `tagged'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/tagged_logging.rb:68:in `tagged'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/rack/logger.rb:20:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/action_dispatch/middleware/request_id.rb:21:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/runtime.rb:18:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/engine.rb:518:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/application.rb:165:in `call'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/railtie.rb:194:in `public_send'
/var/www/app/shared/bundle/ruby/2.1.0/gems/railties-4.2.4/lib/rails/railtie.rb:194: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:160: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'

データベースクエリが必要ない場合を除いて、アプリ内のあらゆる場所で発生しているようです。ただし、データベースは健全で、接続、メモリ、CPU の点で十分な容量があるようです。

誰かがこれを解決する方法についてのヒントを与えてくれることを願っています。

ありがとう ：-）

解決策

ご提案ありがとうございます:-)

例外は定期的にスローされますが、データベース呼び出しのみのようです (- show_custom_pickup_identifier? では、単純な AR クエリのみが作成されます)。そこで私はそれを追跡しました - そして、問題は AWS RDS IOPS 制限にあると考えられます。より多くのストレージを適用した後 (したがって IOPS が増加しました)、それは解消されたようです - 少なくとも今日:-) Amazon が IOPS が不足していることを示す明確な指標を持っていれば良いのですが (!!).

したがって、今のところ、これで問題が永久に解決されることを祈ります :-)