[Home]

Summary:ASTERISK-13887: [patch] DTMF Appears to be broken from certain sources on asterisk 1.4.24 - double digit.
Reporter:Geoff Mina (geoff2010)Labels:
Date Opened:2009-04-02 15:38:04Date Closed:2009-06-29 13:50:13
Priority:BlockerRegression?Yes
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 14815-moliveras-logging1.patch
( 1) 14815-v0.patch
( 2) 14815-v1.patch
( 3) 2833-constantTone-fail-5-5-09.log
( 4) 2833-noEnd-pass-5-5-09.log
( 5) constant_tone_5-4-09_2.log
( 6) constant_tone_5-4-09.log
( 7) constant_tone_rtp_dtmf_debug.log
( 8) DTMF-FAIL.txt
( 9) DTMF-OK.txt
(10) Issue_14815_Test_Results_20090504_v2.txt
(11) Issue_14815_Test_Results_20090504_v3.txt
(12) Issue_14815_Test_Results_20090504_v4.txt
(13) Issue_14815_Test_Results_20090504.txt
(14) rtp-debug.txt
(15) v1-14815.patch
Description:I am having some trouble with 1.4.24.  This appears to be a regression since 1.4.21.1 as I have just recently upgraded and started to experience the problem.

When calling my asterisk box from a cell phone the system detects double DTMF digits.  When calling from a landline or pure SIP device DTMF detection works fine.  I have determined that the cell phone is sending the RTP DTMF payload about 2x more than the other devices, but as far as I can tell it should still be considered a single digit as per the RFC.

Attached are two TXT files of pcap exports which show the dump for a working DTMF interaction, and one for a failure situation.

Please let me know if I can provide any further information.

Thanks,
Geoff
Comments:By: Geoff Mina (geoff2010) 2009-04-02 15:41:13

Just as a clarification.  The file named DTMF-OK.txt is from a land line, and the file named DTMF-FAIL.txt is from a cell phone.  I have tested with 3 different cell phones on the t-mobile network and all have yielded to the same result.

I was performing my test by attempting to authenticate with VoiceMailMain when the problem occurred.

thanks!
By: Geoff Mina (geoff2010) 2009-04-09 09:43:57

I had done a little work and corrected the issue.  I am not 100% certain what my changes rolled back, but for my environment I have things in working order.  I went back to a 1.21.1 version that I was running and compared the RFC2833 handler code with the 1.4.24 version I am currently running.  I replaced some changed lines and made one modification to support a change in the RTP structure in 1.4.24.

Here is a pastebin for the change I made.  If someone could explain why this fixed things... and what I potentially broke by rolling this back I would greatly appreciate it!

http://pastebin.com/f579f2ecc

thanks,
Geoff
By: Geoff Mina (geoff2010) 2009-04-09 09:45:46

sorry... actual pastebin link here.  I highlighted the areas I updated.

http://pastebin.com/f215738f3
By: Joshua C. Colp (jcolp) 2009-04-23 08:22:40

In order to figure why the RTP stack is doing what it is doing we need to see rtp debug as well as DTMF logging. You can enable DTMF logging by adding dtmf to your console => line in logger.conf
By: Geoff Mina (geoff2010) 2009-04-23 08:29:51

No problem.  I will upload the CLI output later today.  I need to roll-back my temporary changes on my test server to cause the problem to occur.

thanks!
By: Geoff Mina (geoff2010) 2009-04-23 08:42:48

The new file called rtp-debug.txt has been uploaded.  This trace is me calling into my Asterisk box from my cell phone (Blackberry Curve on T-Mobile).  I try to authenticate with 8099 and it fails because digits are duplicated.

Thanks,
Geoff
By: Dmitry Andrianov (dimas) 2009-04-28 15:06:41

I do not really know ins and outs of RTP but from your debug output it seems that your peer sends voice (0) in parallel with DTMF (101) in two "streams" and that timestamms of these streams are not in sync. In fact voice timestamp is increasing while DTMF "stream" timestamp is constant (equals to the timestamp of first DTMF packet).

Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012982, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012982, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02825)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012983, ts 1043004111, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012984, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012984, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02978)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012985, ts 1043004271, len 000160)

I believe that because of this the code at the line 1294 of main/rtp.c ("if (rtp->dtmfcount) {") forces end of digit.

I'm curious what kind of equipment produces such a RTP...
Anyway, it is the fix for 14460 which caused this behavior.
By: Geoff Mina (geoff2010) 2009-04-28 15:50:22

@dimas - I believe the fact that the remote equipment is sending inband as well as RFC2833 is not a problem.  My server is set to only do RFC2833, so it will just ignore the inband audio.

The problem only occurs when the RFC2833 event is longer than 200ms (approx).  When I generate DTMF data from my Aastra phone the event is 80ms, when I call from my land line into my asterisk over the PSTN the event is 150ms.  Both of those scenarios work.  When I dial the asterisk box from my cell phone through a Level3 DID the DTMF event is between 400ms and 500ms... when the event is that long, the rfc2833 code will generate multiple internal events for my single external event causing DTMF duplication on read.

As a temporary workaround, I am preventing process_rfc2833() from ever setting rtp->dtmfcount = 0.  I don't know what else that might break, but it seems to have fixed the bug temporarily, and I have been able to continue using 1.4.24 while waiting for a real fix.

Thanks!
By: Geoff Mina (geoff2010) 2009-04-28 15:53:40

You can see very clearly in the following example that asterisk internally decided to terminate the DTMF before the RFC2833 terminated with the end flag.  This caused it to immediately start a new sequence which ended when the original sequence was actually terminated.

Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012948, ts 1043001391, len 000004, mark 1, event 00000008, end 0, duration 00160)
[Apr 23 09:37:54] DTMF[7588]: channel.c:2297 __ast_read: DTMF begin '8' received on SIP/4.68.250.148-ac071000
[Apr 23 09:37:54] DTMF[7588]: channel.c:2301 __ast_read: DTMF begin ignored '8' on SIP/4.68.250.148-ac071000
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012949, ts 1043001391, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012950, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012950, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 00279)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012951, ts 1043001551, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012952, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012952, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 00439)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012953, ts 1043001711, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012954, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012954, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 00596)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012955, ts 1043001871, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012956, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012956, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 00764)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012957, ts 1043002031, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012958, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012958, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 00906)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012959, ts 1043002191, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012960, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012960, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01080)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012961, ts 1043002351, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012962, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012962, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01219)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012963, ts 1043002511, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012964, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012964, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01383)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012965, ts 1043002671, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012966, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012966, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01544)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012967, ts 1043002831, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012968, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012968, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01713)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012969, ts 1043002991, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012970, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012970, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 01861)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012971, ts 1043003151, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012972, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012972, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02019)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012973, ts 1043003311, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012974, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012974, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02180)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012975, ts 1043003471, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012976, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012976, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02356)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012977, ts 1043003631, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012978, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012978, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02518)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012979, ts 1043003791, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012980, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012980, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02676)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012981, ts 1043003951, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012982, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012982, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02825)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012983, ts 1043004111, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012984, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012984, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 02978)
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012985, ts 1043004271, len 000160)
[Apr 23 09:37:54] DTMF[7588]: channel.c:2229 __ast_read: DTMF end '8' received on SIP/4.68.250.148-ac071000, duration 20 ms
[Apr 23 09:37:54] DTMF[7588]: channel.c:2282 __ast_read: DTMF end passthrough '8' on SIP/4.68.250.148-ac071000
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012986, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012986, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 03166)
[Apr 23 09:37:54] DTMF[7588]: channel.c:2297 __ast_read: DTMF begin '8' received on SIP/4.68.250.148-ac071000
[Apr 23 09:37:54] DTMF[7588]: channel.c:2301 __ast_read: DTMF begin ignored '8' on SIP/4.68.250.148-ac071000
Got  RTP packet from    209.244.16.207:60296 (type 00, seq 012987, ts 1043004431, len 000160)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012988, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012988, ts 1043001391, len 000004, mark 0, event 00000008, end 0, duration 03322)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012989, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012989, ts 1043001391, len 000004, mark 0, event 00000008, end 1, duration 03360)
[Apr 23 09:37:54] DTMF[7588]: channel.c:2229 __ast_read: DTMF end '8' received on SIP/4.68.250.148-ac071000, duration 420 ms
[Apr 23 09:37:54] DTMF[7588]: channel.c:2282 __ast_read: DTMF end passthrough '8' on SIP/4.68.250.148-ac071000
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012990, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012990, ts 1043001391, len 000004, mark 0, event 00000008, end 1, duration 03360)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012991, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012991, ts 1043001391, len 000004, mark 0, event 00000008, end 1, duration 03360)
Got  RTP packet from    209.244.16.207:60296 (type 101, seq 012992, ts 1043001391, len 000004)
Got  RTP RFC2833 from   209.244.16.207:60296 (type 101, seq 012992, ts 1043001391, len 000004, mark 0, event 00000008, end 1, duration 03360)
By: Dmitry Andrianov (dimas) 2009-04-28 16:17:20

The problem is not inband tones. The problem is completely different timestamps of voice RTP versus DTMF RTP in the same "stream".

Asterisk looks at delta between timestamps to see how much time passed and decrements DTMF timeout (rtp->dtmfcount).

               rtp->dtmfcount -= (timestamp - rtp->lastrxts);

dtmfcount starts with 3 seconds. When it reaches zero, Asterisk considers that is infinite DTMF and forces its finish. Normally "timestamp - rtp->lastrxts" gives you just how much time has passed since the last packet. But when your timestamps jump back and forth, this value is bogus, so dtmfcount timeout quickly runs out and Asterisk forces DMTF end.


By: Geoff Mina (geoff2010) 2009-04-28 16:45:00

ah that makes perfect sense.  The RTP stream is totally within spec though, because voice timestamps need to continue to increment even thought the ts for the RFC2833 packet needs to remain static.

I see what you are saying now, and that definitely explains why my hack of always setting rtp->dtmfcount=dtmftimeout fixes the issue...

Now that you see what the issue is, can you suggest a real fix as opposed by my "lets just try things to see if they work" approach? :)

thanks.
By: Dmitry Andrianov (dimas) 2009-04-28 16:54:56

No I do not have a solution. First of all because as I said I'm not RTP guru - I did not even know that "The RTP stream is totally within spec though, because voice timestamps need to continue to increment even thought the ts for the RFC2833 packet needs to remain static" :)

I someone make me fix it quickly, I would probably use following approach:
1. rename dtmfcount to dtmfstartts (timestamp)
2. change "rtp->dtmfcount = dtmftimeout;" in process_rfc2833 to "rtp->dtmfcount = timestamp"
3. fixed

       if (rtp->dtmfcount) {
               rtp->dtmfcount -= (timestamp - rtp->lastrxts);

               if (rtp->dtmfcount < 0) {
                       rtp->dtmfcount = 0;
               }

code to be something like

 if (rtp->dtmfstartts && dtmfstartts + dtmftimeout < timestamp) {
   rtp->dtmfstartts = 0;
...

4. And searched for all occurenses of dtmfcount and patched the code appropriately.

However this is just a theory....


By: Leif Madsen (lmadsen) 2009-04-28 17:16:41

Looks like some progress has been made here, so perhaps my assigning this issue to file will cause it to get some progress :)
By: Matt Riddell (zx81) 2009-04-28 19:06:05

Could you write up the fix as a quick hack patch?
By: Geoff Mina (geoff2010) 2009-04-28 19:48:45

If you want a quick workaround for this problem you can take a look at what I did on my systems.  I never had the original continuous tone problem, so this didn't cause any negative side effects.  Here is my pastebin link.

http://pastebin.com/f215738f3

thanks.
By: Matt Riddell (zx81) 2009-04-28 19:57:06

Yeah, that one didn't work for me.  I've ended up putting a wait(1) between questions in the survey which successfully gobbles up the extras.
By: Mike Oliveras (moliveras) 2009-04-28 22:26:14

I opened up bug 14460 and the "fix" never solved the problem I reported. Since it seems to break something else, can it simply be removed?
By: Dmitry Andrianov (dimas) 2009-04-28 23:26:41

After looking more carefully at rtp.c I think it should be patched a little bit different: dtmfcount should be replaced with field like "dtmf_end_ts" which should be initialized with current timestamp + duration from DTMF start packet (or some default if none). It should also be updated with following DTMF packets. When current timestamp exceeds dtmf_end_ts, Asterisk should forcibly end DTMF. Something like that.... But have to look at least once into RTP specs though ;)

moliveras,
can you provide log similar to the one geoff2010 did? (containing both rtp debug and dtmf debug)
If you you are hitting exactly the same issue, I could try creating a patch. Wil take couple of days - kind of busy now...
By: Mike Oliveras (moliveras) 2009-04-30 08:43:25

I am attaching the log file now.  Once the problem occurs, asterisk stops sending RTP towards the phone and instead keeps sending 2833 packets (with incrementing durations), and I just hear a constant tone.

192.168.196.40 is an SBC, and 192.168.196.170 is the phone I am using.

Thanks for taking a look at this.
By: Dmitry Andrianov (dimas) 2009-05-03 17:44:56

moliveras and geoff2010,
if you are brave enough, try the patch I attached. It should be applied to clean 1.4.24.1.
If it does not work, pleas uncomment log lines the patch adds (the ugly ones starting with "//~"), add rtp debug and provide the log file and explanation what is wrong.

PS: do not try on production. I only tested the code on my virtual machine with two SIP clients...
By: Geoff Mina (geoff2010) 2009-05-04 13:37:04

@dimas - I did some testing with the patch.  Unfortunately, it didn't correct the issue. It actually broke some scenarios which were working under 1.4.24.  I attached a file with DTMF debugging as well as your 'ugly' comments :)  If I need to provide actual RTP debug, let me know... but I am guessing this will suffice.  The overview of the test results are:

****** Test:  #1
****** Result: SUCCESS
****** Phone: Aastra IP phone connected directly to Asterisk
****** DTMF Entered: 123
****** DTMF Recieved by Read application: 123
****** Notes: This scenario worked fine in 1.4.24


****** Test:  #2
****** Result: FAILURE
****** Phone: Landline Home Phone
****** DTMF Entered: 123#
****** DTMF Recieved by Read application: 111222333
****** Notes: This scenario worked fine in 1.4.24 but is now BROKEN in 1.4.24.1 w/ supplied patch


****** Test:  #3
****** Result: FAILURE
****** Phone: Cellular Phone - Blackberry Curve - T-Mobile
****** DTMF Entered: 123#
****** DTMF Recieved by Read application: 1122333
****** Notes: This scenario did NOT work 1.4.24 and is still BROKEN in 1.4.24.1 w/ supplied patch

Thanks!
Geoff
By: Dmitry Andrianov (dimas) 2009-05-04 13:54:44

Are you sure you un-commented all "//~" lines? I'm asking because all pieces of my code which produce DTMF_END also log something and in your log I do not see my lines right before DTMF_END issued. I would guess you still have the "TIMEOUT" line commented. If so please un-comment it.

Regardless of the above, please re-do any failing scenario (2 for example) with RTP debug turned on.

Thanks.
By: Geoff Mina (geoff2010) 2009-05-04 14:35:04

Sorry about that... I missed that one comment.  I corrected the issue and re-tested all three scenarios WITH RTP debug turned on.

Thanks.
By: Dmitry Andrianov (dimas) 2009-05-04 14:51:20

Oops!
Please go to line 1328 of main/rtp.c and change
   rtp->dtmf_timeout > timestamp
to
   rtp->dtmf_timeout < timestamp

(that is greater to less).
And try again.
By: Geoff Mina (geoff2010) 2009-05-04 15:36:46

OK, I have made the requested change and retested scenario #2 and #3, they are more broken now than before.  Please see the _v3 test result TXT file.

p.s... i find it very strange that I just happened to upload all 3 files at :34 minutes past the hour for three hours straight now.  I think I'll play the lottery tomorrow. :)

Issue_14815_Test_Results_20090504.txt [^] (25,710 bytes) 2009-05-04 13:34
Issue_14815_Test_Results_20090504_v2.txt [^] (122,198 bytes) 2009-05-04 14:34
Issue_14815_Test_Results_20090504_v3.txt [^] (114,040 bytes) 2009-05-04 15:34
By: Mike Oliveras (moliveras) 2009-05-04 15:48:04

I also tried the patch (I changed the > to a < as per your note) and continue to see the same behavior... I get a constant tone after receiving a rfc2833 packet with no end.  I will upload the log file
By: Dmitry Andrianov (dimas) 2009-05-04 16:20:18

geoff2010,
Please try another patch. (Should be applied to clean rtp.c so you need to do svn revert main/rtp.c first).

I'm really sorry you have to do all that iterative debugging but I just do not have equipment to do proper tests here. The tests I did already worked fine even with the first patch version...


moliveras,
your log does not provide me any info. Please use another patch and if it still does not work, make sure you also do core set debug 1 and edited /etc/asterisk/logger.conf so debug messages are logged.


By: Mike Oliveras (moliveras) 2009-05-04 17:25:08

I got the same behavior with the latest patch... Uploading the log file (which has more info in it now)
By: Geoff Mina (geoff2010) 2009-05-04 17:53:54

Good News!  The most recent patch seems to have corrected the multiple DTMF bug.  Please review the _v4 debug log I just uploaded to ensure that it is actually doing what you think.  I have re-tested all 3 scenarios to confirm that there was no regression.

Thanks for your efforts!
Geoff
By: Dmitry Andrianov (dimas) 2009-05-04 18:36:59

Geoff,
at the first glance log file looks Ok.

moliveras,
well, my code does its job properly - there are lines in the log saying:

May  4 22:20:59 mikeo_asterisk1 asterisk[32616]: DEBUG[3457]: rtp.c:1329 in ast_rtp_read: TIMEOUT now=2483902209, begin=2483898769, timeout=0
May  4 22:20:59 mikeo_asterisk1 asterisk[32616]: DEBUG[3457]: rtp.c:627 in send_dtmf: Sending dtmf: 53 (5), at 192.168.196.40


which means we did not see DTMF end within specified timeout so we forcing it. However for some reason DTMF END message we sent were not processed by the Asterisk core at all. The only thing I can do here is to add some more logging to other places and ask you to re-run the test.

I will upload new patch for you in 5 minutes. Please apply it and try again. Note: now there is no need to do "rtp debug".
By: Dmitry Andrianov (dimas) 2009-05-04 18:53:23

meanwhile I bet you have wrong dtmfmode for peers....
By: Mike Oliveras (moliveras) 2009-05-05 09:56:27

I retested with your latest patch and am attaching the log.  As far as my dtmfmode, it is not wrong - however I did find an issue.  The SBC has a mode of auto and the phone has a mode of 2833.  We have some carriers who do not support 2833 when G711 is used, so we provision the mode on the SBC as auto and let it negotiate on or off.  The problem is that I am using sipp to play a sample that was captured from a production environment, and my sipp script was not advertising 101 in the sdp.  I have corrected that, and your patch now works for that scenario.   I tried just placing a call between two peers and holding down a key - If I hold it long enough, I am still getting a constant tone.  I will attach a log for the pass and the fail case momentarily.

Thanks
By: Dmitry Andrianov (dimas) 2009-05-05 10:34:17

The duration field of RTP packet can only hold maximum value of 65535 which correspond to approximately 8 seconds. You were definitely holding button for the longer period so overflow occurred in the duration field.

I will fix the code later today to handle such a situations.
It should work Ok for hold time less than 8 seconds though....
By: Leif Madsen (lmadsen) 2009-05-05 10:37:12

I'm changing this from marked as a blocker for 1.4.25, to a major issue that is targeted for 1.4.26. This doesn't appear to be a general problem, but rather an issue specifically with your environment and SBC.

Thanks dimas for taking this issue on and moving it along!
By: Geoff Mina (geoff2010) 2009-05-05 10:49:56

@dimas - if you don't mind, once you are done tweaking and removing comments and such, can you please provide a final patch against 1.4.24.1 and 1.4.25 since the changes won't be present until 1.4.26?

Thanks for all your hard work on this one!
Geoff
By: Dmitry Andrianov (dimas) 2009-05-05 10:52:55

lmadsen,
in case of moliveras it is the configuration issue. However in the case of geoff2010 it is not. His case can not be solved by just configuration...


geoff2010,
sure.
By: Leif Madsen (lmadsen) 2009-05-05 11:12:11

If this patch is complete before 1.4.25 is released (perhaps later this week), then it can go in for 1.4.25. I just didn't want this being a blocker for 1.4.25 if it was going to take a couple of weeks to get done, but it looks like you are quite close now.
By: Dmitry Andrianov (dimas) 2009-05-05 11:14:49

will do later today. Hope geoff2010 and moliveras will test it.
By: Dmitry Andrianov (dimas) 2009-05-05 14:03:39

New patch uploaded. Debug logging is removed and code reworked to support event duration wrapping through zero.

Guys, please re-test. (I do not need any logs if it works).

v1-14815.patch


By: Mike Oliveras (moliveras) 2009-05-05 14:38:30

Looks good - I no longer get the constant tone if I hold a digit down for than 8 secs and the "2833 no end" case still works.
By: Geoff Mina (geoff2010) 2009-05-05 15:03:55

I have re-tested all 3 scenarios with the patch against 1.4.24.1.  All three were successful.

Thanks dimas... you are my hero :)
By: Dmitry Andrianov (dimas) 2009-05-05 15:14:28

:)
Great.

ZX81, could you please test the patch as well?

lmadsen,
I guess we are done here. If you could bring more testers, it would benefit all because this is change in a code used in every Asterisk installation... Also, it worth reviewing from people who were closing 14460.
By: Leif Madsen (lmadsen) 2009-05-05 16:22:53

russell: This needs to be reviewed, along with whatever was changed/reverted in 14460.
By: Matt Riddell (zx81) 2009-05-06 18:40:55

Looks good here in minimal testing - I'm back to one DTMF per key press - I only did a couple of calls but with 5 DTMF sequences each - previous versions were sending 2-3 DTMF events to dialplan per key press.
By: Dmitry Andrianov (dimas) 2009-05-06 20:00:19

Thanks.
By: Leif Madsen (lmadsen) 2009-05-07 07:14:25

Moving this back to blocker status as we're so close.
By: Leif Madsen (lmadsen) 2009-05-07 12:05:58

Reassigned this to file to see if he can move it along before Russell gets back next week. If not, then just reassign back to him. Thanks!
By: Digium Subversion (svnbot) 2009-05-13 08:38:08

Repository: asterisk
Revision: 194208

U   branches/1.4/main/rtp.c

------------------------------------------------------------------------
r194208 | file | 2009-05-13 08:38:08 -0500 (Wed, 13 May 2009) | 11 lines

Fix RFC2833 issues with DTMF getting duplicated and with duration wrapping over.

(closes issue ASTERISK-13887)
Reported by: geoff2010
Patches:
     v1-14815.patch uploaded by dimas (license 88)
Tested by: geoff2010, file, dimas, ZX81, moliveras
(closes issue ASTERISK-13564)
Reported by: moliveras
Tested by: moliveras

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=194208
By: Digium Subversion (svnbot) 2009-05-13 08:39:16

Repository: asterisk
Revision: 194209

_U  trunk/
U   trunk/res/res_rtp_asterisk.c

------------------------------------------------------------------------
r194209 | file | 2009-05-13 08:39:15 -0500 (Wed, 13 May 2009) | 18 lines

Merged revisions 194208 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r194208 | file | 2009-05-13 10:38:01 -0300 (Wed, 13 May 2009) | 11 lines
 
 Fix RFC2833 issues with DTMF getting duplicated and with duration wrapping over.
 
 (closes issue ASTERISK-13887)
 Reported by: geoff2010
 Patches:
       v1-14815.patch uploaded by dimas (license 88)
 Tested by: geoff2010, file, dimas, ZX81, moliveras
 (closes issue ASTERISK-13564)
 Reported by: moliveras
 Tested by: moliveras
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=194209
By: Digium Subversion (svnbot) 2009-05-13 08:40:24

Repository: asterisk
Revision: 194211

_U  branches/1.6.0/
U   branches/1.6.0/main/rtp.c

------------------------------------------------------------------------
r194211 | file | 2009-05-13 08:40:24 -0500 (Wed, 13 May 2009) | 25 lines

Merged revisions 194209 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r194209 | file | 2009-05-13 10:39:10 -0300 (Wed, 13 May 2009) | 18 lines
 
 Merged revisions 194208 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r194208 | file | 2009-05-13 10:38:01 -0300 (Wed, 13 May 2009) | 11 lines
   
   Fix RFC2833 issues with DTMF getting duplicated and with duration wrapping over.
   
   (closes issue ASTERISK-13887)
   Reported by: geoff2010
   Patches:
         v1-14815.patch uploaded by dimas (license 88)
   Tested by: geoff2010, file, dimas, ZX81, moliveras
   (closes issue ASTERISK-13564)
   Reported by: moliveras
   Tested by: moliveras
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=194211
By: Digium Subversion (svnbot) 2009-05-13 08:41:34

Repository: asterisk
Revision: 194212

_U  branches/1.6.1/
U   branches/1.6.1/main/rtp.c

------------------------------------------------------------------------
r194212 | file | 2009-05-13 08:41:34 -0500 (Wed, 13 May 2009) | 25 lines

Merged revisions 194209 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r194209 | file | 2009-05-13 10:39:10 -0300 (Wed, 13 May 2009) | 18 lines
 
 Merged revisions 194208 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r194208 | file | 2009-05-13 10:38:01 -0300 (Wed, 13 May 2009) | 11 lines
   
   Fix RFC2833 issues with DTMF getting duplicated and with duration wrapping over.
   
   (closes issue ASTERISK-13887)
   Reported by: geoff2010
   Patches:
         v1-14815.patch uploaded by dimas (license 88)
   Tested by: geoff2010, file, dimas, ZX81, moliveras
   (closes issue ASTERISK-13564)
   Reported by: moliveras
   Tested by: moliveras
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=194212
By: Digium Subversion (svnbot) 2009-05-13 08:42:28

Repository: asterisk
Revision: 194213

_U  branches/1.6.2/
U   branches/1.6.2/main/rtp.c

------------------------------------------------------------------------
r194213 | file | 2009-05-13 08:42:27 -0500 (Wed, 13 May 2009) | 25 lines

Merged revisions 194209 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r194209 | file | 2009-05-13 10:39:10 -0300 (Wed, 13 May 2009) | 18 lines
 
 Merged revisions 194208 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r194208 | file | 2009-05-13 10:38:01 -0300 (Wed, 13 May 2009) | 11 lines
   
   Fix RFC2833 issues with DTMF getting duplicated and with duration wrapping over.
   
   (closes issue ASTERISK-13887)
   Reported by: geoff2010
   Patches:
         v1-14815.patch uploaded by dimas (license 88)
   Tested by: geoff2010, file, dimas, ZX81, moliveras
   (closes issue ASTERISK-13564)
   Reported by: moliveras
   Tested by: moliveras
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=194213