Re: DTMF Tones Dropped Sporadically In ask method

[Douglas Seifert]

Forgot to paste the full log, it is available here:

https://gist.github.com/3678778

Thanks, 

Doug Seifert

On Saturday, September 8, 2012 12:27:53 PM UTC-7, Douglas Seifert wrote:

All,

I am developing an application that talks to remote devices using a DTMF touch tone protocol.  I am using the ask method with a :terminator option to receive data from the device calling the server.  My stack is as follows

adhearsion 2.1.0

adhearsion-asterisk 1.2.1

asterisk 1.8.10.1~dfsg-1ubuntu1

OS: ubuntu 64 bit running linux 3.2.0

DTMF mode: rfc2833

At times, tones never make it into the result returned from the ask method.  One example of this can be seen in the below referenced log [1].

My adhearsion server has called the following method:

result = ask :terminator => '*'

The device sends the following DTMF sequence #4* 0015 #5*.  However, the ask call returns "#40015#5".  I see the below sequence in the log which seems to indicate the first * makes it into the adhearsion stack.  However, the ask method does not return until the second * is received.

I did not have trace level logging on when I ran across this, but have since turned on trace logging and hopefully can give you a trace log soon.

In the mean time, am I doing something obviously wrong here?

Thanks,

Doug Seifert

Log excerpt:

[2012-09-08 07:04:24] DEBUG Celluloid: [RECV] Event: DTMF

Privilege: dtmf,all

Channel: SIP/telepacific-00000114

Uniqueid: 1347113036.276

Digit: *

Direction: Received

Begin: Yes

End: No

Event: DTMF

Privilege: dtmf,all

Channel: SIP/telepacific-00000114

Uniqueid: 1347113036.276

Digit: *

Direction: Received

Begin: No

End: Yes

[2012-09-08 07:04:24] DEBUG Celluloid: [RECV] #<RubyAMI::Event name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/telepacific-00000114", "Uniqueid"=>"1347113036.276", "Digit"=>"*", "Direction"=>"Received", "Begin"=>"Yes", "End"=>"No"}, text_body=nil, events=nil, action=nil>

[2012-09-08 07:04:24] DEBUG Celluloid: [RECV] #<RubyAMI::Event name="DTMF", headers={"Privilege"=>"dtmf,all", "Channel"=>"SIP/telepacific-00000114", "Uniqueid"=>"1347113036.276", "Digit"=>"*", "Direction"=>"Received", "Begin"=>"No", "End"=>"Yes"}, text_body=nil, events=nil, action=nil>

[2012-09-08 07:04:24] DEBUG Adhearsion::Call: 004e1225-d5ed-4f02-8109-5331a8879bf7: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="DTMF", attributes_hash={:privilege=>"dtmf,all", :channel=>"SIP/telepacific-00000114", :uniqueid=>"1347113036.276", :digit=>"*", :direction=>"Received", :begin=>"Yes", :end=>"No"}, target_call_id="004e1225-d5ed-4f02-8109-5331a8879bf7", component_id=nil, target_mixer_name=nil>

[2012-09-08 07:04:24] DEBUG Adhearsion::Call: 004e1225-d5ed-4f02-8109-5331a8879bf7: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event name="DTMF", attributes_hash={:privilege=>"dtmf,all", :channel=>"SIP/telepacific-00000114", :uniqueid=>"1347113036.276", :digit=>"*", :direction=>"Received", :begin=>"No", :end=>"Yes"}, target_call_id="004e1225-d5ed-4f02-8109-5331a8879bf7", component_id=nil, target_mixer_name=nil>

[Ben Langfeld]

Nothing obviously wrong there. Full logs would be most helpful, as would confirming the content of your Gemfile.lock.

Regards,

Ben Langfeld

--
AdhearsionConf 2012 is coming!
Palo Alto - Training October 19 - Presentations October 20/21
http://adhearsionconf.com
 
 

[Douglas Seifert]

On Saturday, September 8, 2012 1:01:53 PM UTC-7, Ben Langfeld wrote:

Nothing obviously wrong there. Full logs would be most helpful, as would confirming the content of your Gemfile.lock.

Gemfile.lock here: https://gist.github.com/3679286

I noticed shortly after posting this that adhearsion 2.1.1 had been released.  So I upgraded and am running with trace logging on.  I noticed previously that I start getting these kind of drops after the server has been running for a while (after about 1.5 hours).  Next time I get one of these, I will paste a trace log.

Thanks,

Doug Seifert

[Douglas Seifert]

I was able to capture this problem again while logging at Trace level.  This occurred after upgrading to adhearsion 2.1.1, so the gist with the Gemfile.lock represents my running environment.

I updated the original gist here:

https://gist.github.com/3678778

Look for the string 'ANNOTATION' in the log file.  I added notes about what was going on in the adhearsion code.  I can see a * DTMF tone come in that should have terminated the ask call, but for some reason, it doesn't.

This log exhibits nearly the same sequence as in my original post.  The incoming caller is sending this sequence of tones:

#4* 0014 #5*

The adhearsion code is calling

ask :terminator => '*'

The ask method should return after reading the #4*, but instead it returns with the following result:

#40014#5

(See the INFO logs from my application code)

Thanks for any help ...

-Doug 

 

[Ben Langfeld]

Please file an issue on github. Please also try to produce a minimal reproduction app and publish that also.

Regards,
Ben Langfeld

--

[Ben Klang]

Hi Doug,

From the logs I can't see anything that jumps out at me.  There is a known issue with Adhearsion at TRACE level logs on Asterisk which is documented here: (I'll have to send the link out when Github returns from its outage).  But if this is the issue that is biting you, you should be able to work around it by entering DTMF slowly.  Also, the problem should disappear at INFO level logging.

Would you confirm if that makes a difference for you or whether we are looking at a different issue?

/BAK/

-- 

Ben Klang

Principal/Technology Strategist, Mojo Lingo

bkl...@mojolingo.com

+1.404.475.4841

Mojo Lingo -- Voice applications that work like magic

http://mojolingo.com

Twitter: @MojoLingo

[Ben Klang]

The issue to which I referred earlier is here: https://github.com/adhearsion/adhearsion/issues/181

I'd like to know if you think this is related to the issue you saw.

/BAK/

[Douglas Seifert]

Ben,

Thanks for keeping an eye on this.  I don't think my issue is related to the other one because I see my problem even with the logging level set to :info.  I only turned on debug/trace level logging to capture logs for my post to this list;  I had found the issue in :info log level orginally.

I plan on posting a bug on the issue tracker after (hopefully) being able to reproduce the issue using a small test app.  I think it only happens after the code has been running a while.

I have no control over how fast the touch tones come in by the way -- I am coding for some legacy devices that are already in the wild -- only the server piece is being swapped out for an asterisk/adhearsion solution.  I also don't think the tones are being dropped because I see in my trace logs that Punchblock (or some layer below adhearsion) is receiving events for all tones sent by the device -- it's just that they don't make it into the adhearsion layer and are not returned by the 'ask' method call for some reason.  See my ANNOTATION comments in the logs I posted in my gist.  It may be a leak of some type.  I have been able to mitigate the problem by frequently (every 2 hours) restarting the adhearsion server, but towards the end of the 2 hours, the frequency of the problem steps up.

-Doug

[Ben Klang]

Hi Doug,

I'm going to try to reproduce this.  I'm sorry you're having trouble and needing to restart Asterisk on a regular interval.  We have an Adhearsion 2 app that is getting ready to go into production with Asterisk and we have not experienced this issue, despite the application having been run for days (weeks?) at a time without restarting.  At this moment I'm not sure what the difference is but we are committed to finding and fixing it.  I agree that it sounds like a leak of some kind and we want to resolve that.

I'm reviewing your annotations and digging back through this thread.  I'll update you as I find anything, but please let me know if you see anything new that may help discover the cause.

One question (and apologies if you've already answered this and I missed it): when Adhearsion slows down, do you see any corresponding rise in the amount of CPU and/or memory consumed by Adhearsion? It would be especially helpful to know if rise in CPU usage is relatively consistent (burning 50% of the CPU whether or not a call is active) or if the CPU burn is spikey/tied to call activity.

Thanks for your help and patience,

[Douglas Seifert]

Ben,

Thanks for taking a look.  Another data point that might be of use: the devices seem to send 100 ms tones with a 50 ms silence.  The trace logs seem to indicate that at least Punchblock/Celluloid/RubyAMI::Client receive the terminator digit, but the ask method that has been called with :terminator => '*' does not return until the next '*' is sent by the device.

Another observation: it is not necessarily the amount of time the server is up, but rather the number of inbound calls serviced that seems to lead to the issue.  

 

One question (and apologies if you've already answered this and I missed it): when Adhearsion slows down, do you see any corresponding rise in the amount of CPU and/or memory consumed by Adhearsion? It would be especially helpful to know if rise in CPU usage is relatively consistent (burning 50% of the CPU whether or not a call is active) or if the CPU burn is spikey/tied to call activity.

I have logged into the box and run top when calls are experiencing this issue and the memory use and CPU use are very low (during testing, the code would handle up to 6 concurrent calls every 20-30 minutes). And again, it is not that adhearsion slows down, it's just that the ask method invocation doesn't seem to terminate when lower layers seem to have received the DTMF tone it is waiting for.  Other calls can come in concurrent to the call where the problem happens and they can be just fine.  I have not noticed concurrent calls receive extra DTMF tones either.

My thought on trying to reproduce this is to set up a test app with a couple of call controllers that just send tones 12789#* back and forth N times using an ask invocation with :terminator => '*' and see if after M calls, I can see the terminator get dropped.

Thanks again for taking a look.

-Doug

[Ben Langfeld]

Doug,

I'll hit this tomorrow and see if I can track it down. That reproduction would be very useful if you get time to put it together before then.

Ben Langfeld

Enviado via iPad

--

[Ben Langfeld]

So, the problem appears to be a race condition. What happens is that Adhearsion has a state machine which evaluates matches. The transitions *should* occur as a result of DTMF events. Unfortunately, Rayo does not yet support DTMF events, so what we do is set up a single digit DTMF listener after each state transition. This leaves a small window open where we're not listening. That appears to be where your digits are vanishing to.

Potential solutions:

* Move matching logic to the engine by preparing a single GRXML document and bypassing adhearsion's state machine. The gotcha here is that #ask allows for a block to be called each time a digit is added to the buffer in order to perform complex validations. Also, this approach would severely restrict the types of things we could match in #menu (no more regexes, unless we can reliably translate them to GRXML).

* Add DTMF event support to Rayo, have Voxeo implement this in rayo-server and we will implement it for ahn/freeswitch in Punchblock. We then need to switch adhearsion to use a single DTMF listener.

* You could use a punchblock input component manually with a single GRXML document similar to the first option. This is a bandaid and by no means a long-term solution, but the fastest one to deploy.

My main concern is that these are all relatively time consuming, and I am unsure who will fund this work.

Regards,
Ben Langfeld

[JasonGoecke]

But Doug is using Asterisk, not Rayo.

[JasonGoecke]

Ok, I get it, the feature currently in Rayo-Server is considered a work around:

***

dtmf events are generated on input ( I dont know, perhaps we are talking about different scenarios ). In fact there is functional tests which guarantee that the feature is on every release ( https://github.com/rayo/rayo-functional-tests/blob/develop/src/test/java/com/rayo/functional/InputTest.java#L66 ). 

The syntax is this ( taken from here https://github.com/rayo/rayo-server/wiki/Sending-DTMF ):

<!-- DTMF event -->

<presence id='1235' to='16...@app.rayo.net/1' from='9f0...@call.rayo.net/1'>

  <dtmf xmlns="urn:xmpp:rayo:1" signal="1"/>

</presence>

***

and not party of the Rayo spec yet, and therefore not in Punchblock/Adhearsion yet. I will chase to see where we are on this. 

On Monday, September 17, 2012 4:29:23 AM UTC-7, Ben Langfeld wrote:

[Ben Langfeld]

So, we had a discussion about this with Voxeo yesterday. We have a plan for including DTMF events in the Rayo spec, and we should have that in the spec by the end of this week. Voxeo will then implement in their rayo-server based on PRISM. Meanwhile, we will implement this change in Punchblock for Asterisk and FreeSWITCH. We then need to modify Adhearsion to take advantage of this, and line up the release to avoid compatibility issues.

Hopefully I will get some time later this week to begin this work, but you'll have to run from feature branches. Of course, the alternative is to take approach #3 for your app. Let me know if you need help with that.

Ben Langfeld

[Douglas Seifert]

Hopefully I will get some time later this week to begin this work, but you'll have to run from feature branches. Of course, the alternative is to take approach #3 for your app. Let me know if you need help with that.

I assume you are referring to this:

> You could use a punchblock input component manually with a single GRXML document similar to the first option. This is a bandaid and by no means a long-term solution, but the fastest one to deploy. 

Any help you can give me putting something like this in would be great.  Currently running the app in a field test mode with a limited number of devices calling in, but the app is slated to go full production pretty soon.  We get the odd dropped digit that normally leads to the device retrying, but there are cases where bad data can be  read.  With a much larger population of incoming calls, I would expect this problem to only increase, so a band aid until a full solution is available would be great.

doug AT dseifert DOT net

if you want to take that discussion offline.

Thanks again for keeping going with this.

-Doug Seifert

[Ben Langfeld]

Apologies for taking so long to get back to you Doug. This is the sort of thing you'll need to do:

grammar = RubySpeech::GRXML.draw mode: 'dtmf', root: 'inputdigits' do

  rule id: 'inputdigits', scope: 'public' do

    item repeat: '2' do

      ruleref uri: '#numeric_digit'

    end

    item { '*' }

  end

  rule id: 'numeric_digit', scope: 'private' do

    one_of do

      0.upto(9) { |d| item { d.to_s } }

    end

  end

end

input_component = Punchblock::Component::Input.new mode: :dtmf, grammar: { value: grammar }

execute_component_and_await_completion input_component

reason = input_component.complete_event.reason

logger.info reason.inspect

This grammar matches two numeric digits followed by an asterisk. You should tweak accordingly. Let me know if you have any problems.

Regards,

Ben Langfeld

--

[david ryder]

Could this be applicable to ahn1.x as well?

[Ben Langfeld]

Yes, but it won't be fixed in ahn 1

Enviado via iPad

[Ben Klang]

Let me clarify Ben's response:

David, if you are asking whether GRXML could be applied to Adhearsion 1, yes, but it would require a lot of manual use of the Asterisk recognizer applications like https://wiki.asterisk.org/wiki/display/AST/Application_SpeechStart.  If you are asking whether the DTMF recognizer race condition exists in Adhearsion 1, yes, but experience has shown that it is less likely to be triggered, even with fast DTMF (there are technical reasons for this, mostly to do with less work being done in between digits).  As Ben mentioned, we won't be fixing it in Adhearsion 1, but will definitely be fixing it in Adhearsion 2 once we can fix it for all 3 platforms.  Ben L is out of the office this week but we'll do our best to get it fixed as quickly as possible.

/BAK/

-- 

Ben Klang

Principal/Technology Strategist, Mojo Lingo

bkl...@mojolingo.com

+1.404.475.4841

Mojo Lingo -- Voice applications that work like magic

http://mojolingo.com

Twitter: @MojoLingo

[Douglas Seifert]

I think this would work except for one case.  For one of the ask calls, I am waiting for # followed by 1 or 2 digits followed by *.  Is it possible to create a grammar that has an optional number of digits?

-Doug

[Douglas Seifert]

On Friday, September 28, 2012 10:05:09 PM UTC-7, Douglas Seifert wrote:

I think this would work except for one case.  For one of the ask calls, I am waiting for # followed by 1 or 2 digits followed by *.  Is it possible to create a grammar that has an optional number of digits?

-Doug

Answering my own question: yes, like so:

item :repeat => '1-2' do

          ruleref :uri => '#numeric_digit'

        end