ERROR Celluloid: Punchblock::Translator::Asterisk crashed (DTMF?)

[Andrius Kairiukstis]

I do have latest stable Adhearsion with some IVR, on asterisk 13. 

On regular basis, getting following error, it seems, that it happening during DTMF processing.

Most of time the app working well, it is random error, however after this user have to restart whole adhearsion, it do not process further calls

Any idea how I debug it?

Regards

[2017-03-24 15:24:28.246] ERROR Celluloid: Punchblock::Translator::Asterisk crashed!

RubyAMI::Error: RubyAMI::Error

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/responses.rb:29:in `value'

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:92:in `value'

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/proxies/sync_proxy.rb:33:in `method_missing'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/connection/asterisk.rb:66:in `method_missing'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `block in send_ami_action'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/ami_error_converter.rb:8:in `convert'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `send_ami_action'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:322:in `redirect_back'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/stop_by_redirect.rb:24:in `stop_by_redirect'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/output.rb:93:in `stop_by_redirect'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:44:in `process_dtmf'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:62:in `block in register_dtmf_event_handler'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:162:in `call_handler'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:141:in `block (3 levels) in trigger_handler'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `catch'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:136:in `block (2 levels) in trigger_handler'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `each'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `find'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:134:in `block in trigger_handler'

[08:37]  

[2017-03-24 14:43:13.412] ERROR Celluloid: Punchblock::Translator::Asterisk crashed!

RubyAMI::Error: RubyAMI::Error

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/responses.rb:29:in `value'

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:92:in `value'

       /usr/lib/ruby/gems/2.3.0/gems/celluloid-0.15.2/lib/celluloid/proxies/sync_proxy.rb:33:in `method_missing'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/connection/asterisk.rb:66:in `method_missing'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `block in send_ami_action'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/ami_error_converter.rb:8:in `convert'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `send_ami_action'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:322:in `redirect_back'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/stop_by_redirect.rb:24:in `stop_by_redirect'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/output.rb:93:in `stop_by_redirect'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:44:in `process_dtmf'

       /usr/lib/ruby/gems/2.3.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:62:in `block in register_dtmf_event_handler'

       /usr/lib/ruby/gems/2.3.0/gems/has-guarded-handlers-1.6.3/lib/has_guarded_handlers.rb:162:in `call_handler'

[Luca Pradovera]

Hello,

do you have a trace log of that? Did it happen when you pressed a DTMF key?

Best regards,

Luca

--
You received this message because you are subscribed to the Google Groups "Adhearsion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to adhearsion+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Andrius Kairiukstis]

Unfortunately, not – it works well and only sometimes I am received this error. For example, last issue happened on March 7 – but today already 4x times

I can try to turn on trace but afraid, there will be a lot of logs

To unsubscribe from this group and stop receiving emails from it, send an email to adhearsion+...@googlegroups.com.

[Ben Klang]

Don’t forget: you can toggle TRACE logging without restarting Adhearsion by sending SIGALRM

http://adhearsion.com/docs/best-practices/sysadmin

/BAK/

[Stephen F. George]

There may already be a fix for this very problem.  I too had encountered DTMF recognizer crashes, which occurred when a DTMF key press was occurring at nearly the same time as the no input timeout; one thread was trying to trigger the guard in has_guarded_handlers, while the other thread was removing it.

@kares resolved the issue in #5 and #6, which are merged into the develop branch of has_guarded_handlers.  I'd recommend setting your Gemfile to temporarily use the develop branch of has_guarded_handlers.  And please report back as to whether this resolves the issue or not.

Stephen

[Andrius Kairiukstis]

Thank you, it working well for about 24 hours already

[Stephen F. George]

Thank you Andrius, that's great news!  That's for sharing how that's going.

Ben and Ben, I'm thinking we should we cut a new release of has_guarded_handlers soon, what do you think? 

- Stephen
​

[Ben Langfeld]

Sure. Let me know what permissions you're missing to do so and I'll get you set up.

Ben

Enviado do meu iPhone

--

[gmkun...@gmail.com]

I have a same problem.
When DTMF Start and DTMF End event is received at the same time, Adhearsion crashed and no answer from this.
I use has-guarded-handlers-1.6.3 with patches issue in #5 and #6.
Anyone can help? Thanks.


[2017-10-24 08:30:42.238] DEBUG Adhearsion::Call: 7f82e812-8504-4848-aa7b-c325356fc66a@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="7f82e812-8504-4848-aa7b-c325356fc66a", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Tue, 24 Oct 2017 08:30:42 +0900, name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/sip.fusioncom.co.jp-000000ac", "Uniqueid"=>"1508801437.172", "Digit"=>"9", "Direction"=>"Received", "Begin"=>"Yes", "End"=>"No"}>
[2017-10-24 08:30:42.912] DEBUG Adhearsion::Call: 7f82e812-8504-4848-aa7b-c325356fc66a@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="7f82e812-8504-4848-aa7b-c325356fc66a", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Tue, 24 Oct 2017 08:30:42 +0900, name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/sip.fusioncom.co.jp-000000ac", "Uniqueid"=>"1508801437.172", "Digit"=>"9", "Direction"=>"Received", "Begin"=>"No", "End"=>"Yes"}>
[2017-10-24 08:30:42.915] DEBUG Adhearsion::Call: 7f82e812-8504-4848-aa7b-c325356fc66a@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="7f82e812-8504-4848-aa7b-c325356fc66a", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Tue, 24 Oct 2017 08:30:42 +0900, name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/sip.fusioncom.co.jp-000000ac", "Uniqueid"=>"1508801437.172", "Digit"=>"2", "Direction"=>"Received", "Begin"=>"Yes", "End"=>"No"}>
[2017-10-24 08:30:42.915] DEBUG Adhearsion::Call: 7f82e812-8504-4848-aa7b-c325356fc66a@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="7f82e812-8504-4848-aa7b-c325356fc66a", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Tue, 24 Oct 2017 08:30:42 +0900, name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/sip.fusioncom.co.jp-000000ac", "Uniqueid"=>"1508801437.172", "Digit"=>"2", "Direction"=>"Received", "Begin"=>"No", "End"=>"Yes"}>
[2017-10-24 08:30:42.929] ERROR Celluloid: Punchblock::Translator::Asterisk crashed!
RubyAMI::Error: RubyAMI::Error
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/responses.rb:29:in `value'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:92:in `value'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/proxies/sync_proxy.rb:33:in `method_missing'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/connection/asterisk.rb:66:in `method_missing'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `block in send_ami_action'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/ami_error_converter.rb:8:in `convert'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:351:in `send_ami_action'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:322:in `redirect_back'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/stop_by_redirect.rb:24:in `stop_by_redirect'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/output.rb:93:in `stop_by_redirect'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:44:in `process_dtmf'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/component/composed_prompt.rb:62:in `block in register_dtmf_event_handler'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:165:in `call_handler'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:144:in `block (3 levels) in trigger_handler'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:137:in `catch'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:137:in `block (2 levels) in trigger_handler'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:135:in `each'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:135:in `find'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:135:in `block in trigger_handler'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:134:in `catch'
        /var/ahn_app/vendor/has-guarded-handlers-1.6.3gm1/lib/has_guarded_handlers.rb:134:in `trigger_handler'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk/call.rb:184:in `process_ami_event'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk.rb:230:in `block in ami_dispatch_to_or_create_call'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk.rb:228:in `each_pair'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk.rb:228:in `ami_dispatch_to_or_create_call'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/punchblock-2.7.5/lib/punchblock/translator/asterisk.rb:112:in `handle_ami_event'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:122:in `dispatch'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
        /var/ahn_app/vendor/bundle/ruby/2.4.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'

[Stephen George]

Good afternoon,

I am sorry to hear that that's affecting you, and glad you are reporting this back.

Also I have to say that while the aforementioned patches to has-guarded-handlers has greatly reduced the prevalence of this issue for my application, it has not entirely solved it for me as well.

Your stack:

• Asterisk
• C-Ruby 
• Punchblock 2.7.5
• Celluloid 0.15.2
• has-guarded-handlers-1.6.3 + #5 + #6
  

My stack:

• Asterisk
• JRuby 
• Punchblock 2.7.5
• Celluloid 0.15.2.1
• has-guarded-handlers-1.6.3 + #5 + #6

As you can see, my stack is nearly the same as yours.  I'm sorry that this is still affecting us both.  My hope is to upgrade to Adhearsion 3 soon - mainly to get to a version compatible with at least celluloid 0.16.x.  That alone may make a difference in further reducing the issue, but I'm speculating without evidence.

Currently, this issue occurs for us after a few million calls with DTMF IVRs.  Out of curiosity, can you share your experience with how frequent of an issue this is for you?

Stephen

[gmkun...@gmail.com]

 Thanks for your reply.

Ok, I look forward to Adhearsion 3.
I encounterd this problem 4 times in 4000 calls since June this year.

[Stephen George]

Good afternoon,

I am really sorry to hear that you are experiencing this as frequently as 1 in every 1,000 calls.  That is actually a surprisingly high number and much higher than I have been experiencing.

For the time being, I wanted to share 2 strategies for mitigating the issue - the first being the easiest.

1. Review your Asterisk's manager.conf configuration

As mentioned in the Adhearsion docs, it's very important that your Aadhearsion AMI user have at least these 2 filters for dropping some of the AMI events that are not useful to Adhearsion:

eventfilter = !Event: RTCP*
eventfilter = !Variable: RTPAUDIOQOS*

All AMI events end up being published as has_guarded_handlers ami events.  So reducing the chatter there not only improves performance, but also reduces the likelihood of this sensitive race condition that leads to the ComposedPrompt crash.

2. Scale horizontally if possible

If you can add additional Adhearsion boxes behind a common SIP proxy you'll of course reduce the magnitude of concurrency and with it, reduce the likelihood of the aforementioned issue.  This assumes you can afford the money and time to provision additional systems, so it's not as easy of a fix as #1.

I hope these help a little bit in the meantime while we try to squash this issue.

Thanks for your feedback on how this is affecting you.

- Stephen

[Luca Pradovera]

Hello,

adding the filter greatly reduced the incidence of similar errors in our testing too.

As an aside, I would also advise whoever is in position of doing so to try out Adhearsion 3. The newer Celluloid version really makes a difference.

Best regards,

Luca

--
You received this message because you are subscribed to the Google Groups "Adhearsion" group.

To unsubscribe from this group and stop receiving emails from it, send an email to adhearsion+unsubscribe@googlegroups.com.

[Neko Gmkun]

ok, I try to set eventfilter.

I will report results someday. Thanks.

2017/11/10 午前5:16 "Stephen George" <sfge...@gmail.com>: