[Home]

Summary:ASTERISK-18404: out-of-order RTP causes DTMF loss
Reporter:Stephane Chazelas (stephane.chazelas)Labels:
Date Opened:2011-09-01 06:15:01Date Closed:2012-07-26 07:25:20
Priority:CriticalRegression?Yes
Status:Closed/CompleteComponents:Core/RTP
Versions:1.8.4 Frequency of
Occurrence		Constant
Related
Issues:
causesASTERISK-20906 DTMF in SIP not working after HOLD / UNHOLD
is related toASTERISK-18147 SIP Phone (Cisco)-> Asterisk 1.4.31 -> IAX-> Asterisk 1.6.2.19 > SIP provider -> PSTN IVR DTMF - DTMF broken after upgrade 1.4 to 1.6 or 1.8
is related toASTERISK-20013 Asterisk receiving RFC2833 DTMF with out of order sequence numbers from a Centile IntaSwitch Server results in DTMF digits being dropped
Environment:debian amd64 {code} # dpkg -l | grep asterisk ii asterisk 1:1.8.4.4~dfsg-2 Open Source Private Branch Exchange (PBX) ii asterisk-config 1:1.8.4.4~dfsg-2 Configuration files for Asterisk ii asterisk-core-sounds-en-gsm 1.4.19-1 asterisk PBX sound files - English/gsm ii asterisk-dahdi 1:1.8.4.4~dfsg-2 DAHDI devices support for the Asterisk PBX ii asterisk-doc 1:1.6.2.9-2+squeeze2 Source code documentation for Asterisk ii asterisk-modules 1:1.8.4.4~dfsg-2 loadable modules for the Asterisk PBX ii asterisk-moh-opsound-gsm 2.03-1 asterisk extra sound files - English/gsm ii asterisk-mysql 1:1.8.4.4~dfsg-2 MySQL database protocol support for the Asterisk PBX ii asterisk-sounds-extra 1.4.9-1 Additional sound files for the Asterisk PBX ii asterisk-voicemail 1:1.8.4.4~dfsg-2 simple voicemail support for the Asterisk PBX ii libasterisk-agi-perl 1.01-2 Collections of Perl modules to be used with Asterisk PBX AGI {code}Attachments:
Description:We're in the process of upgrading our phone system from trixbox 1.4 to 1.8 on debian).

Many DTMF RTP frames from one of our VOIP providers arrive out-of-order. See for instance:

{code}
 3.977152 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF One 1 (end)
 3.977163 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF One 1 (end)
 3.977171 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF One 1
 3.977179 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF One 1 (end)
 4.669046 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Four 4
 4.669056 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Four 4 (end)
 4.669065 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Four 4 (end)
 4.669073 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Four 4 (end)
 5.162105 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Five 5
 5.162132 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Five 5 (end)
 5.162141 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Five 5 (end)
 5.162149 195.189.173.27 -> 80.193.213.24 RTP EVENT Payload type=RTP Event, DTMF Five 5 (end)
{code}

The 4 packets for "1" above arrived in the 3-4-1-2 sequence, and that digit was ignored by asterisk (only 4 and 5 were transmitted which caused the wrong extension to be called.

When that happens the DTMF is just discarded by asterisk (and that also happens for 2-1-3-4 sequences which are more common).

It doesn't occur in trixbox's 1.4.24, so it would be a regression at some point.

Here is the corresponding rtpdebug output

{code}
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025103, ts 027992, len 000004)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025103, ts 027992, len 000004, mark 0, event 00000001, end 1, duration 00800)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025104, ts 027992, len 000004)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025104, ts 027992, len 000004, mark 0, event 00000001, end 1, duration 00800)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025101, ts 027992, len 000004)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025101, ts 027992, len 000004, mark 1, event 00000001, end 0, duration 00000)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025102, ts 027992, len 000004)
[2011-09-01 11:39:41] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025102, ts 027992, len 000004, mark 0, event 00000001, end 1, duration 00800)
[...]
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025128, ts 033032, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025128, ts 033032, len 000004, mark 1, event 00000004, end 0, duration 00000)
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF begin '4' received on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF begin ignored '4' on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025129, ts 033032, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025129, ts 033032, len 000004, mark 0, event 00000004, end 1, duration 00800)
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end '4' received on SIP/voipfone-200-00000002, duration 100 ms
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end passthrough '4' on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025131, ts 033032, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025131, ts 033032, len 000004, mark 0, event 00000004, end 1, duration 00800)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025130, ts 033032, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025130, ts 033032, len 000004, mark 0, event 00000004, end 1, duration 00800)
[...]
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025143, ts 036952, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025143, ts 036952, len 000004, mark 1, event 00000005, end 0, duration 00000)
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF begin '5' received on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF begin passthrough '5' on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025144, ts 036952, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025144, ts 036952, len 000004, mark 0, event 00000005, end 1, duration 00800)
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end '5' received on SIP/voipfone-200-00000002, duration 100 ms
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end accepted with begin '5' on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end '5' detected to have actual duration 0 on the wire, emulation will be triggered on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] DTMF[5944] channel.c: DTMF end '5' has duration 0 but want minimum 80, emulating on SIP/voipfone-200-00000002
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025145, ts 036952, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025145, ts 036952, len 000004, mark 0, event 00000005, end 1, duration 00800)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP packet from    195.189.173.27:28704 (type 101, seq 025146, ts 036952, len 000004)
[2011-09-01 11:39:42] VERBOSE[5944] res_rtp_asterisk.c: Got  RTP RFC2833 from   195.189.173.27:28704 (type 101, seq 025146, ts 036952, len 000004, mark 0, event 00000005, end 1, duration 00800)
[2011-09-01 11:39:43] DTMF[5944] channel.c: DTMF end emulation of '5' queued on SIP/voipfone-200-00000002
{code}

Sequences were:

* '1': 3-4-1-2
* '4': 1-2-4-3
* '5': 1-2-3-4

Although the '5' digit is the only one that was received in order, note the note above about duration 0. In that 4 packet sequence for each digit, the "start" packet has duration 0, and the 3 following end ones have duration 800.


Comments:By: Stephane Chazelas (stephane.chazelas) 2011-09-01 08:23:30.033-0500

OK, I can see the bug. In process_dtmf_rfc2833, dtmf_end are ignored (but rtp->lastevent = seqno is set) unless there has been a begin before. And out of order packets are ignored (without rtp->lastevent = seqno). So, if the begin frame is out of order, following an end one, it will be ignored.

This seems to solve the issue for me:


{code}
--- asterisk-1.8.4.4~dfsg.orig/res/res_rtp_asterisk.c 2010-10-06 05:35:51.000000000 +0100
+++ asterisk-1.8.4.4~dfsg/res/res_rtp_asterisk.c 2011-09-01 13:01:23.653471306 +0100
@@ -1482,6 +1482,10 @@ static void process_dtmf_rfc2833(struct
rtp->resp = 0;
rtp->dtmf_duration = rtp->dtmf_timeout = 0;
AST_LIST_INSERT_TAIL(frames, f, frame_list);
+ } else {
+ /* Discard End events arriving before the Begin
+ */
+ return;
}
} else {
/* Begin/continuation */
{code}

That is, completely ignore "end" packets received before a "begin", don't even set the lastevent.

But I think it's wrong to do that. "end" packets are retransmitted and contain the information, they shouldn't be ignored if the "begin" has failed to make its way through to us.

By: Leif Madsen (lmadsen) 2011-09-14 09:10:48.055-0500

Marking an issue as possibly related.
By: Matt Jordan (mjordan) 2012-07-05 11:47:38.938-0500

Hello!

So, after a lot of analysis and playing around with this issue, we came to the realization that any attempt to handle out of order RFC 2833 DTMF in Asterisk 1.8 would be hugely invasive.  What's more, the preferred mechanism to handle it - a read-side channel jitter buffer - does not really exist in the way it needs to in Asterisk 1.8 (func_jitterbuffer having been introduced in Asterisk 10).

As much as we'd like to fix this for Asterisk 1.8, I think it'd be very risky to attempt to do so, and would either (a) require a lot of backporting, or (b) require significant risk in attempting to re-work the RTP layer, which would potentially be the 'wrong' long term solution.

As such, we went ahead and tried to solve this problem for Asterisk 11.  There is a patch on review board (https://reviewboard.asterisk.org/r/2010) that introduces a DTMF jitter buffer for func_jitterbuffer.  When Asterisk 11 goes into beta, if someone would be willing to test this out on networks that historically have had problems with out of order RFC 2833 DTMF, that'd be fantastic.

Thanks!

Matt
By: Matt Jordan (mjordan) 2012-07-16 13:18:55.618-0500

So... disregard my last comment.  After some conversations with Olle, we figured out a better way of handling this.

There is a patch that should address this kind of out of order DTMF directly in the RTP stack on review board here: https://reviewboard.asterisk.org/r/2033/

If you'd like to try this patch out on the latest and greatest 1.8 and provide feedback, that'd be great.

Thanks!

Matt