Punchblock::Translator::Asterisk crashes with NoMethodError

[fwoeck]

Now and then I see this error during load testing. The version is current dev-branch of punchblock.
If helpful, I can easily add a debug log & sip-pcaps. Logically, I'm not so sure, why this happens - it's hard to reproduce reliably:

@40000000542e5db019e284ac [2014-10-03 08:26:14.431] ERROR Celluloid: Punchblock::Translator::Asterisk crashed!
@40000000542e5db019e30d64 NoMethodError: undefined method `find' for nil:NilClass
@40000000542e5db019e328bc       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/has-guarded-handlers-1.6.0/lib/has_guarded_handlers.rb:149:in `guarded?'
@40000000542e5db019e3385c       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/has-guarded-handlers-1.6.0/lib/has_guarded_handlers.rb:92:in `trigger_handler'
@40000000542e5db019e3579c       org/jruby/RubyKernel.java:1264:in `catch'
@40000000542e5db019e36f0c       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/has-guarded-handlers-1.6.0/lib/has_guarded_handlers.rb:91:in `trigger_handler'
@40000000542e5db019e38e4c       org/jruby/RubyEnumerable.java:592:in `find'
@40000000542e5db019e3a9a4       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/has-guarded-handlers-1.6.0/lib/has_guarded_handlers.rb:89:in `trigger_handler'
@40000000542e5db019e3c114       org/jruby/RubyKernel.java:1264:in `catch'
@40000000542e5db019e3cccc       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/has-guarded-handlers-1.6.0/lib/has_guarded_handlers.rb:88:in `trigger_handler'
@40000000542e5db019e3e054       /opt/voice-ahn/vendor/bundle/jruby/1.9/bundler/gems/punchblock-c26a249bbc6c/lib/punchblock/translator/asterisk/call.rb:159:in `process_ami_event'
@40000000542e5db019e4037c       /opt/voice-ahn/vendor/bundle/jruby/1.9/bundler/gems/punchblock-c26a249bbc6c/lib/punchblock/translator/asterisk.rb:209:in `ami_dispatch_to_or_create_call'
@40000000542e5db019e41704       org/jruby/RubyHash.java:1366:in `each_pair'
@40000000542e5db019e422bc       /opt/voice-ahn/vendor/bundle/jruby/1.9/bundler/gems/punchblock-c26a249bbc6c/lib/punchblock/translator/asterisk.rb:207:in `ami_dispatch_to_or_create_call'
@40000000542e5db019e4325c       /opt/voice-ahn/vendor/bundle/jruby/1.9/bundler/gems/punchblock-c26a249bbc6c/lib/punchblock/translator/asterisk.rb:90:in `handle_ami_event'
@40000000542e5db019e441fc       org/jruby/RubyKernel.java:1952:in `public_send'
@40000000542e5db019e4596c       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
@40000000542e5db019e46cf4       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
@40000000542e5db019e47c94       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `handle_message'
@40000000542e5db019e4901c       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `task'
@40000000542e5db019e49fbc       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `initialize'
@40000000542e5db019e4e60c       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:47:in `initialize'
@40000000542e5db019e59da4       /opt/voice-ahn/vendor/bundle/jruby/1.9/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `create'

[fwoeck]

After I updated has-guarded-handlers to the current dev branch, it seems to be gone. Will close this for now, thanks for your time anyway ;)

[benlangfeld]

As far as I know, HGH 1.6.0 and the dev branch are the same, no?

[ggayan]

This also happened to us yesterday in one of our servers

[fwoeck]

Hmm, indeed the HGH commits from august seem to be unrelated. I this case, I'll better reopen this. Better move the issue there?

[kares]

wanted to fill in some details (for the record at least) related to why this is happening (on JRuby) :

the issue relates to an optimization PB::Asterisk::Call no longer being an actor. Call class includes HasGuardedHandlers. such Call instances during a (call) lifecycle might get accessed concurrently due Celluloid doing message dispatching using Fibers which under JRuby are thread based. so sometimes unregister_handler from punchblock-266cb0230751/lib/punchblock/translator/asterisk/component/stop_by_redirect.rb:21 might happen before an event handler gets fired (event handling is complete) :

  punchblock-266cb0230751/lib/punchblock/translator/asterisk/call.rb:184:in `process_ami_event'
  punchblock-266cb0230751/lib/punchblock/translator/asterisk.rb:230:in `ami_dispatch_to_or_create_call'
  punchblock-266cb0230751/lib/punchblock/translator/asterisk.rb:228:in `each_pair'
  punchblock-266cb0230751/lib/punchblock/translator/asterisk.rb:228:in `ami_dispatch_to_or_create_call'
  punchblock-266cb0230751/lib/punchblock/translator/asterisk.rb:112:in `handle_ami_event'
  celluloid-7af615463b10/lib/celluloid/calls.rb:25:in `public_send'
  celluloid-7af615463b10/lib/celluloid/calls.rb:25:in `dispatch'

there's several approaches getting around the issue (personally believe reverting is not necessary as its a considerable improvement). we ended up making HGH "much-more" thread-safe - handling event de-registration while executing handlers at the same time. which seems like too much and might need a review based on a concrete application but seemed to handle the occasional call failures well enough.