[Home]

Summary:ASTERISK-20013: Asterisk receiving RFC2833 DTMF with out of order sequence numbers from a Centile IntaSwitch Server results in DTMF digits being dropped
Reporter:David Cunningham (dcunningham)Labels:
Date Opened:2012-06-15 20:27:50Date Closed:2012-06-27 18:57:04
Priority:MajorRegression?
Status:Closed/CompleteComponents:General
Versions:1.8.11.1 Frequency of
Occurrence		Frequent
Related
Issues:
is related toASTERISK-18404 out-of-order RTP causes DTMF loss
Environment:CentOS release 5.6 (Final) Attachments:( 0) dtmf-issues.txt
Description:Asterisk does not always recognise DTMF event when the RFC2833 event is received. Please see the attached trace.
There are 5 DTMF keys pressed. The first two (1 and 0) are recognised, the third (0) is not, and the fourth and fifth (6 and #) are recgonised. The recognised events end up with a line logged "DTMF end 'X' received", whereas the unrecognised one does not.
The lines for the events which are not recognised are:

[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000039, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000039, ts 1188454211, len 000004, mark 1, event 00000001, end 0, duration 00160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:57557 (type 00, seq 064797, ts 018720, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000510, ts 030272, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000040, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000040, ts 1188454211, len 000004, mark 1, event 00000001, end 0, duration 00320)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000511, ts 030432, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:13248 (type 00, seq 064798, ts 018880, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000041, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000041, ts 1188454211, len 000004, mark 1, event 00000001, end 0, duration 00480)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:57557 (type 00, seq 064799, ts 019040, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000512, ts 030592, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000042, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000042, ts 1188454211, len 000004, mark 1, event 00000001, end 0, duration 00640)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000513, ts 030752, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:13248 (type 00, seq 064800, ts 019200, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000514, ts 030912, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000043, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000043, ts 1188454211, len 000004, mark 1, event 00000001, end 1, duration 00800)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:57557 (type 00, seq 064801, ts 019360, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Sent RTP packet to      xx.xx.xx.xx:57557 (type 00, seq 064802, ts 019520, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:13248 (type 00, seq 000515, ts 031072, len 000160)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP packet from    xx.xx.xx.xx:57557 (type 101, seq 000044, ts 1188454211, len 000004)
[Jun 14 18:16:00] VERBOSE[19368] res_rtp_asterisk.c: Got  RTP RFC2833 from   xx.xx.xx.xx:57557 (type 101, seq 000044, ts 1188454211, len 000004, mark 1, event 00000001, end 1, duration 00800)

Thank you.
Comments:By: David Cunningham (dcunningham) 2012-06-15 20:28:37.371-0500

Asterisk log of call.
By: Michael L. Young (elguero) 2012-06-18 12:03:34.708-0500

Out of curiosity, is this 64bit or 32 bit CentOS?

Are you able to reproduce this on the latest version of Asterisk, 1.8.13?
By: David Cunningham (dcunningham) 2012-06-18 19:15:21.861-0500

This is on a 32 bit system.
Do you have a particular reason to recommend 1.8.13? If so we can ask the customer to upgrade, but this is a production system and we try not to make changes unless necessary.
Thanks.

By: Michael L. Young (elguero) 2012-06-18 21:36:58.882-0500

When taking a peak at the code that handles DTMF, I saw that it uses ast_tvdiff_ms() and there was a bug fix that went into 1.8.13 to prevent overflow in calculation in ast_tvdiff_ms on 32-bit machines (http://svnview.digium.com/svn/asterisk?view=revision&revision=364277).  

It is always helpful to test the latest release in a test environment that is setup similar to the production environment in order to determine if the bug still exists or not instead of trying to track down a now non-existent bug.  That is why I was wondering if the latest version had been tested with yet or not.
By: David Cunningham (dcunningham) 2012-06-19 17:45:18.932-0500

Hello,
The customer who's having the issue doesn't have a test system unfortunately, and we haven't had reports from anyone else.
Is there any other way forward, or must we try 1.8.13?

By: Michael L. Young (elguero) 2012-06-19 20:37:09.107-0500

You can always try patching what the customer has if upgrading to 1.8.13 is not an option right now.

From within the same directory where you compiled the 1.8.11.1 version of Asterisk, run this command:

{noformat}wget -q -O - https://issues.asterisk.org/jira/secure/attachment/43471/32-bit-time-overflow-2012-04-27.diff | patch -p0{noformat}

Once the patch has been applied, compile Asterisk and install.  Restart Asterisk.

I was just trying to help help get you a quick resolution, if this is what it is... I am not sure.  Nothing stood out to me upon a quick look at the code except for that one function which I knew affects 32 bit systems.
By: David Cunningham (dcunningham) 2012-06-20 18:09:39.918-0500

We applied this patch on the customer's system and it did not resolve the issue.
Please let us know if you need anything else.
Thanks.

By: Matt Jordan (mjordan) 2012-06-26 09:59:10.137-0500

David:

The DTMF coming from this particular system is a bit interesting.  The reason Asterisk is dropping the particular DTMF digit in the stream you posted is because the sequence numbers for the DTMF digits are bouncing all over the place:

{noformat}
DIGIT   Sequence Start   Sequence End
1       125              130
0       48               52
0       39               44
6       127              131
#       208              212
{noformat}

Asterisk does not support out of order DTMF packets - if it detects that a sequence number has gone backwards, it will do one of two things:
1) If the roll back is less than 50, it will drop the packet as being out of order
2) If the roll back is greater than 50, it will assume that the sequence number has rolled over (the sequence number being a 16-bit unsigned integer), and will use that as the new value.

This is why the second digit '0' - which has a sequence number less than the first digit of '1' - was accepted (Asterisk thought the sequence number must have rolled over) - while the third digit '0' - which had a sequence number indicating that it occurred before the second - was dropped (the delta being less than 50).

I'm fairly confident that RFC 2833 DTMF should *not* be sent in this fashion to Asterisk - the sequence numbers don't just exist to imply an order within a digit, but also between digits.  The fact that these are bouncing all over either means they're arriving to Asterisk extremely out of order, or the system sending the digits has something implemented incorrectly.

By: Matt Jordan (mjordan) 2012-06-26 10:36:26.001-0500

As a follow-up: what device is sending the DTMF to Asterisk?
By: Matt Jordan (mjordan) 2012-06-26 12:43:29.183-0500

I'm going to go out on a limb here and say that this is not an out of order DTMF issue, and that the device thinks its sending the DTMF in order.

That being said, both the timestamps and the sequence numbers in the RTP packets sent from the device are, for lack of a better term, screwy.  The timestamps jump all over the place, as do the sequence numbers.  Even if we viewed the packets as being 'out of order', any attempt to put them back in order would only malform the expected results further.

After reading RFC 3550 some more - which RFC 2833 expects the sequence numbers and timestamps to adhere to - there is no way this is compliant behavior within a single SSRC space.  As such, while I'd like to know what crazy device is sending this RTP, I don't see any effort to try and accommodate this behavior as being worthwhile to attempt.
By: David Cunningham (dcunningham) 2012-06-27 18:40:41.318-0500

The customer advises it's a Centile IntaSwitch Server.

Since this device is at fault, we can close this issue.

By: David Cunningham (dcunningham) 2012-06-27 18:40:55.837-0500

Thanks for your help.

By: Matt Jordan (mjordan) 2012-06-28 08:06:10.898-0500

Thanks for letting us know what device this is!  Hopefully if someone runs into this same issue, they'll come across this :-)