| Summary: | ASTERISK-04539: [patch] RTP rfc2833 out of sequence problem | ||
| Reporter: | John Riordan (john) | Labels: | |
| Date Opened: | 2005-07-08 11:44:45 | Date Closed: | 2008-01-15 15:41:24.000-0600 |
| Priority: | Minor | Regression? | No |
| Status: | Closed/Complete | Components: | Core/General |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ( 0) ast_rtp_senddigit.diff ( 1) full-sip-debug.txt ( 2) rfc2833_patch_stable.diff ( 3) rfc2833_patch_ver2.diff | |
| Description: | If rtp rfc2833 packets arrive out of sequence for a single DTMF event, Asterisk may report double or triple digits received. This occurs when Asterisk HEAD/Stable is communicating with Asterisk HEAD/Stable. Six rtp packets are sent via ast_rtp_sendigit() - the first packet has the marker bit set and the last three have the end bit set. If one for the last three packets (with the end bit set) arrives before all of the first three packets arrive a duplicate send_dtmf() occurs for the event. For example, this is the debug channel output for a single DTMF event corresponding to receiving the digit '1' in the case where the forth rtp packet (the first packet with the end bit set) is received second. The result is Asterisk reads two DTMF events instead of one. local*CLI> debug channel SIP/john-5d4d Debugging enabled on channel SIP/john-5d4d << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/john-5d4d] << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/john-5d4d] << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/john-5d4d] << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/john-5d4d] << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/john-5d4d] << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/john-5d4d] The sequence numbers of the rtp packets in the following example are 52924 52925 52926 52927 52928 52929. Asterisk sends them in this order, but by the time the receiving Asterisk gets them, they arrive in the order 52924 52927 52925 52926 52929 52928. This is reasonable and not surprising. This is a tcpdump of the same event: # tcpdump -T rtp -vvv host remote and less 100 tcpdump: listening on eth1, link-type EN10MB (Ethernet), capture size 96 bytes 11:31:06.327425 IP (tos 0x0, ttl 49, id 565, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 * 52924 90280 1440528472 11:31:06.327930 IP (tos 0x0, ttl 49, id 568, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 52927 90280 1440528472 11:31:06.328451 IP (tos 0x0, ttl 49, id 566, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 52925 90280 1440528472 11:31:06.329064 IP (tos 0x0, ttl 49, id 567, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 52926 90280 1440528472 11:31:06.329582 IP (tos 0x0, ttl 49, id 570, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 52929 90280 1440528472 11:31:06.330529 IP (tos 0x0, ttl 49, id 569, offset 0, flags [DF], \ proto 17, length: 44) remote.19392 > local.16224: \ udp/rtp 4 c101 52928 90280 1440528472 If, in this example, the packets happened to arrive in the order 52924 52927 52925 52928 52926 52929, Asterisk would report receiving three DTMF digits. While I took the time last night to read rfc2833, I was unfortunately unable to figure out exactly what is supposed to be sent. So assuming the ast_rtp_senddigit() is doing something considered correct, it appears that receiving side needs to be modified to correctly handle the case where packets arrive out of sequence. One change that may fix the problem (at least in the cases I could think of) is to restrict the processing of rfc2833 packets to those whose sequence number is greater than or equal to the most recently processed rfc2833 packet. I think this can be done by modifying ast_rtp_read() line 480 (in HEAD) from: if (rtp->lasteventseqn <= seqno || rtp->resp == 0 || (rtp->lasteventseqn >= 65530 && seqno <= 6)) { to: if (rtp->lasteventseqn <= seqno || (rtp->lasteventseqn >= 65530 && seqno <= 6)) { Disclaimer: I read the Bug Guidelines and I understand that I may need to submit a disclaimer for suggesting the removal of approx 20 chars from an if statement and I would be happy to do so if it required in this case. If the above needs to be submitted in patch form, I would be happy to submit it in that form as well. I apologize in advance if I have violated the Guidelines with this posting. | ||
| Comments: | By: Michael Jerris (mikej) 2005-07-08 12:13:05 For reference, recent changes to rfc2833 behavior in ASTERISK-3820 and ASTERISK-3595. Another reference ASTERISK-3269. By: Michael Jerris (mikej) 2005-07-08 12:13:46 can we have a full sip debug of this as well please. (from both sides of the conversation if possible) By: John Riordan (john) 2005-07-08 14:51:25 uploaded full sip debug of both sides of the conversation - as requested By: Brian West (bkw918) 2005-07-08 15:53:58 need an rtp debug.. this does me no good to point it out! /b By: John Riordan (john) 2005-07-09 07:58:55 Sorry about not including this in the initial report. I thought the tcpdump -T rtp output might provide enough information to illustrate the problem. Here is the rtp debug of the event with some additional rtp packets to provide context. Thinking it might help clarify things, I've also included the channel debug as well It is a new capture so it doesn't line up with the initial report, but illustrates the problem just as well. Also, the initial report was HEAD -> Stable and this is HEAD -> HEAD. The Stable version I have (1.0.8) doesn't have the cli command rtp debug, so I used tcpdump to capture the RTP packets in the prior example. One sub-bug: in the rtp debug output on the sending side ('remote' in this case), the sequence numbers have been incremented by one before the debug message is printed for the rfc2833 packets. In ast_rtp_senddigit() line 1079 there is an rtp->seqno++ when the sequence number is set in the packet and the debug message gets printed out a handfull of lines later - line 1091 - so what is reported is seqno+1. Likewise, seqno++ is done again one line 1096 before the debug output. Furthermore, as a seqno++ is done in the last iteration of the loop therein, a packet with seqno 42775 is never sent. Basically a seqno is skipped after every rfc2833 event. This is probably a bug? I checked an older version of rtp.c and there used to be a check to make sure the seqno++ was only done for the first 5 iterations of the loop, but that was removed as somepoint. I'd be happy to submit a patch for it (the incorrect debug output and the skipped seqno) if you agree that it is a bug. So, in any event, the sequence numbers are off by one in debug output of the sending and receiving side for just the rfc2833 packets and seqno 42775 is never actually sent, but I think one can still see what is going on. In this example, a single DTMF event for the digit '1' is sent from remote to local. The sequence number of the packets making up this event are 42769, 42770, 42771, 42772, 42773, 42774. The are transmitted in order from 'remote'. By the time they reach the 'local' they are ordered 42769, 42770, 42772, 42771, 42774, 42773. As can be seen, an rtp rfc2833 packet with the end bit set, seqno 42772, is received prior to the all of the first three rtp rfc2833 packets being received (seqno 42769, 42770, and 42771). So what happens is process_rfc2833() is called at this point and it recognizes the end bit, does a send_dtmf(), and resets the DTMF state (rtp->resp = 0). Now the packet with seqno 42771 comes along and process_rfc2833() is called again and it is the beginning of a new DTMF event as far as Asterisk is concerned. Then seqno 42774 shows up with an end bit set, process_rfc2833() is called and a second event is reported instead. But, alas, only one event should have been reported. remote*CLI> debug channel SIP/john-8500 remote*CLI> rtp debug ip local ... Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42763, ts 2064288, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42764, ts 2064448, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42765, ts 2064608, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42766, ts 2064768, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42767, ts 2064928, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42768, ts 2065088, len 160) >> [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/john-8500] Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42770, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42771, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42772, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42773, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42774, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 101, seq 42775, ts 2065248, len 4) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42776, ts 2066528, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42777, ts 2066688, len 160) Sent RTP packet to 66.0.2.1:11700 (type 0, seq 42778, ts 2066848, len 160) local*CLI> debug channel SIP/66.0.0.11-08ae4740 local*CLI> rtp debug ip remote ... Got RTP packet from 66.0.0.1:13776 (type 0, seq 42763, ts 2064448, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42764, ts 2064608, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42765, ts 2064768, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42766, ts 2064928, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42767, ts 2065088, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42768, ts 2065248, len 160) Got RTP packet from 66.0.0.1:13776 (type 101, seq 42769, ts 2065248, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 101, seq 42770, ts 2065248, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 101, seq 42772, ts 2065248, len 4) << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 101, seq 42771, ts 2065248, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 101, seq 42774, ts 2065248, len 4) << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 101, seq 42773, ts 2065248, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:13776 (type 0, seq 42776, ts 2066528, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42777, ts 2066688, len 160) Got RTP packet from 66.0.0.1:13776 (type 0, seq 42778, ts 2066848, len 160) Just for some fun and to further illustrate the problem by example with a little ascii table, here are some more permutations of how packet arrival order of a single DTMF event is effecting the number of DTMF events Asterisk reports. 6 RTP RFC2833 packets are sent for a single DTMF event - the Send column. The sequence numbers of the packets are 1-6 and the end bit is set on the packets with sequence numbers 4-6. Each Recv column indicates the order packets are received with row 1 being the first received and row 6 being the last. The number DTMF events Asterisk reports in each case is shown in the last tally row. It should always report 1, but it doesn't. Send Recv Recv Recv Recv Recv Recv Recv seqno 1 1 1 1 1 1 3 2 seqno 2 2 2 4 4 5 2 1 seqno 3 3 4 2 2 3 1 3 seqno 4 4 3 3 5 6 6 4 seqno 5 5 5 5 3 2 5 5 seqno 6 6 6 6 6 4 4 6 DTMF Events 1 2 2 3 3 1 1 Correct * * * Incorrect * * * * By: John Riordan (john) 2005-07-09 08:06:05 Ah, my little ascii table did not come out so well. Sigh... By: John Riordan (john) 2005-07-09 13:58:52 Here is another example. The last one actually has an 'ts' error in it due to something else I was mucking with - sorry. It didn't impact the issue at all, but here is a clean one for the sake of correctness. seqno of rfc2833 pkts in order sent - 19628, 19629, 19630, 19631, 19632, 19633 seqno of rfc2833 pkts in order recv - 19628, 19631, 19629, 19630, 19632, 19633 and the result is Asterisk reports 2 DTMF events when there was only one. Just the channel and rtp debug: remote*CLI> debug channel SIP/john-8500 remote*CLI> rtp debug ip local ... Sent RTP packet to 66.0.2.1:16642 (type 0, seq 19625, ts 1849600, len 160) Sent RTP packet to 66.0.2.1:16642 (type 0, seq 19626, ts 1849760, len 160) Sent RTP packet to 66.0.2.1:16642 (type 0, seq 19627, ts 1849920, len 160) >> [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/john-c896] Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19629, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19630, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19631, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19632, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19633, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 101, seq 19634, ts 1849920, len 4) Sent RTP packet to 66.0.2.1:16642 (type 0, seq 19635, ts 1850400, len 160) Sent RTP packet to 66.0.2.1:16642 (type 0, seq 19636, ts 1850560, len 160) local*CLI> debug channel SIP/66.0.0.1-08ae4740 local*CLI> rtp debug ip remote ... Got RTP packet from 66.0.0.1:16930 (type 0, seq 19625, ts 1849600, len 160) Got RTP packet from 66.0.0.1:16930 (type 0, seq 19626, ts 1849760, len 160) Got RTP packet from 66.0.0.1:16930 (type 0, seq 19627, ts 1849920, len 160) Got RTP packet from 66.0.0.1:16930 (type 101, seq 19628, ts 1849920, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:16930 (type 101, seq 19631, ts 1849920, len 4) << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/66.0.0.1-08ae4740] Sent RTP packet to 66.0.0.1:16930 (type 0, seq 47367, ts 1843016, len 160) Got RTP packet from 66.0.0.1:16930 (type 101, seq 19629, ts 1849920, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:16930 (type 101, seq 19630, ts 1849920, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:16930 (type 101, seq 19632, ts 1849920, len 4) << [ TYPE: DTMF (1) SUBCLASS: 1 (49) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:16930 (type 101, seq 19633, ts 1849920, len 4) << [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [SIP/66.0.0.1-08ae4740] Got RTP packet from 66.0.0.1:16930 (type 0, seq 19635, ts 1850400, len 160) Got RTP packet from 66.0.0.1:16930 (type 0, seq 19636, ts 1850560, len 160) By: John Riordan (john) 2005-07-09 14:01:54 Also, my suggested fix doesn't work. Seems rather obvious to me now. When the seqno rolls over it would likely be less than lasteventseqn and my suggestion would cause new events to be missed. Thus, a rather poor suggestion for a fix. By: Brian West (bkw918) 2005-07-09 15:49:26 Actually asterisk is still doing this totally wrong. We shouldn't increment the sequence number for the first three packets of the events sent.. This is a proper way the rfc2833 should look: RTP packet from 10.0.1.2:16452 (type 101, seq 12489, ts 420538817, len 4) RTP packet from 10.0.1.2:16452 (type 101, seq 12489, ts 420538817, len 4) RTP packet from 10.0.1.2:16452 (type 101, seq 12489, ts 420538817, len 4) RTP packet from 10.0.1.2:16452 (type 101, seq 12490, ts 420538817, len 4) RTP packet from 10.0.1.2:16452 (type 101, seq 12491, ts 420538817, len 4) This is how asterisk is sending it: RTP packet to 10.0.1.5:16410 (type 101, seq 19910, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19911, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19912, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19913, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19914, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19915, ts 0, len 4) It should read something like: RTP packet to 10.0.1.5:16410 (type 101, seq 19910, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19910, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19910, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19911, ts 0, len 4) RTP packet to 10.0.1.5:16410 (type 101, seq 19912, ts 0, len 4) When testing this you compare how other deivces send it... ie. cisco and sipura.. those devices send it properly we however do it wrong still! The order in which it arrives is irrelevant since we are dealing with RTP... we should send the event 3 times with the same seq,ts to make it work right. The ts on the otherhand can be the same from start to finish of the call.. it can be zero or the ts of the first event and should NOT increment during the same DTMF event.... It can however increment from one dtmf event to the next without much problem but some gateways barf when you do that ie TNT. I have spent many hours trying to determin what the RFC says and when you read that you'll find it confuses the hell out of ya. This is why you should compare what other devices do in order to fix the problem in some sort of compatible way. But then again I think I recall something about sending the first and last packets of the event three times. /b By: John Riordan (john) 2005-07-09 15:53:17 Uploaded patch for ast_rtp_senddigit() sequence number debug output and increment bug outlined above. In summary, the debug output of seqno is off by one and seqno gets incremented one too many times. This does not fix the original problem. Also faxed the disclaimer. By: John Riordan (john) 2005-07-10 09:32:49 Here are two examples of how Eyebeam sends it. Both examples are a single DTMF event for the digit '1'. The difference is in the duration of the event. Eyebeam appears to start sending when the key is pressed and stops sending when the key is released. (I have no relationship with the Eyebeam people beyond the fact that I bought a copy of their softphone). I've added a line of debug output to show the event, end bit, and duration of each RFC 2833 packet. Eyebeam example 1: (short click) Got RTP packet from eyebeam:10070 (type 3, mark 0, seq 10461, ts 6777120, len 33) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 10462, ts 6777280, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 160 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 10463, ts 6777280, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 320 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 10464, ts 6777280, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 320 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 10464, ts 6777280, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 320 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 10464, ts 6777280, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 320 len: 4) Sent RTP packet to eyebeam:10070 (type 3, seq 16488, ts 658288, len 33) Eyebeam example 2: (long click) Got RTP packet from eyebeam:10070 (type 3, mark 0, seq 1574, ts 2222560, len 33) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1575, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 160 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1576, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 320 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1577, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 480 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1578, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 640 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1579, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 800 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1580, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 960 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1581, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1120 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1582, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1280 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1583, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1440 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1584, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1600 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1585, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1760 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1586, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 1920 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1587, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2080 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1588, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2240 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1589, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2400 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1590, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2560 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1591, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2720 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1592, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 2880 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1593, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 3040 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1594, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 3200 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1595, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 3360 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1596, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 3520 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1597, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 3680 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1598, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 3680 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1598, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 3680 len: 4) Got RTP packet from eyebeam:10070 (type 101, mark 0, seq 1598, ts 2222720, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 3680 len: 4) Got RTP packet from eyebeam:10070 (type 3, mark 0, seq 1599, ts 2226400, len 33) By: Brian West (bkw918) 2005-07-10 12:39:04 The arrival out of order shoudn't matter because that can happen. If asterisk will just send them correctly with the last three packets with the same seq and end bit it should play nice. My sipura sents the digits like I outlined... your eyebeam sents it 1, 2, 3x3(with end mark set) which seems to jive with the RFC. Now if asterisk can send them just like that.. it would be fine. See if you can make it do that. /b By: John Riordan (john) 2005-07-11 11:54:57 Taking bkw's suggestion, I've uploaded a new patch which does the following: 1) sends the last three packets with the same sequence number and end bit 2) corrects the rtp debug output in ast_rtp_senddigit 3) eliminates the extra sequence number increment in ast_rtp_senddigit 4) making use of item 1, fixes my initial problem with duplicate DTMF events This patch replaces the previous patch. I agree with bkw. The packets with the end bit set should all have the same sequence number. This seems to agree with the RFC: "If there has been no new event in the last interval, the event SHOULD be retransmitted three times or until the next event is recognized. This ensures that the duration of the event can be recognized correctly even if the last packet for an event is lost." So, the last packet should be retransmitted three times and a retransmission of a RTP packet should have the same sequence number as the original packet. For good measure, I tested a couple of other implementations and they are implemented in the above manner. For example, here is the debug from my Sipura 3000 (I have no relationship with Sipura other than I bought their ata). Again, I've included an extra line of debug output for the sake of clarity. Got RTP packet from sipura:16420 (type 0, mark 0, seq 9177, ts 102219041, len 240) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9178, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 240 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9178, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 240 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9178, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 240 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9179, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 480 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9180, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 720 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9181, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 0 duration: 960 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9182, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 1040 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9182, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 1040 len: 4) Got RTP packet from sipura:16420 (type 101, mark 1, seq 9182, ts 102219201, len 4) RTP RFC 2833 event packet (event: 00000001 end: 1 duration: 1040 len: 4) Got RTP packet from sipura:16420 (type 0, mark 0, seq 9183, ts 102220401, len 240) By: Paul Belanger (pabelanger) 2005-07-11 14:24:47 I don't mean to talk over your issue, but would this issue cause asterisk to not properly transmit DTMF to a UA? IE: UA does not get all the DTMF digits passed by asterisk? By: Brian West (bkw918) 2005-07-11 16:35:54 I think you're getting close! And yes it was asterisk sending the dtmf wrongly! :P /b By: Kevin P. Fleming (kpfleming) 2005-07-11 21:55:40 This patch does look correct, and I don't remember how or why the seqno was getting incremented during the last three packets... it clearly should not be. john, your Mantis username is too generic for me to match it up to your disclaimer, so please email me directly at kpfleming@digium.com your proper name and any associated company name so I can locate the disclaimer tomorrow. By: Kevin P. Fleming (kpfleming) 2005-07-12 19:28:06 Committed to CVS HEAD, thanks! By: John Riordan (john) 2005-07-14 10:02:14 Thanks for applying the patch, but... It looks like you made a small modification to my patch before you applied it. + /* Sequence number of last two end packets does not get incremented */ + if (x != 3 && x != 4) + rtp->seqno++; became + /* Sequence number of last two end packets does not get incremented */ + if (x < 3) + rtp->seqno++; The problem with the change is that seqno needs to be incremented on the last iteration of the loop. The change introduces a new bug - the next rtp packet sent after the last rfc2833 packet sent in the loop has the same seqno as said packet. An alternative would be to increment the seqno after to loop is finished. By: John Riordan (john) 2005-07-14 12:40:59 Also, I uploaded a complimentary patch for the stable branch. By: Kevin P. Fleming (kpfleming) 2005-07-14 19:52:26 It made more sense to increment the seqno after exiting the loop, so that's done in CVS HEAD now. Thanks for the eagle eyes :-) By: Digium Subversion (svnbot) 2008-01-15 15:41:13.000-0600 Repository: asterisk Revision: 6116 U trunk/rtp.c ------------------------------------------------------------------------ r6116 | kpfleming | 2008-01-15 15:41:13 -0600 (Tue, 15 Jan 2008) | 3 lines send final 3 RFC2833 packets with same seqno (bug ASTERISK-4539) don't reprocess incoming RFC2833 event when packets received out of order (bug ASTERISK-4539) ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=6116 By: Digium Subversion (svnbot) 2008-01-15 15:41:24.000-0600 Repository: asterisk Revision: 6129 U trunk/rtp.c ------------------------------------------------------------------------ r6129 | kpfleming | 2008-01-15 15:41:24 -0600 (Tue, 15 Jan 2008) | 2 lines ensure we record the last seqno we transmitted (bug ASTERISK-4539) ------------------------------------------------------------------------ http://svn.digium.com/view/asterisk?view=rev&revision=6129 | ||