| Summary: | ASTERISK-16774: Dial with use of feature options corrupts rfc2388 DTMF durations | ||||
| Reporter: | Mark Petersen (roadkill) | Labels: | |||
| Date Opened: | 2010-10-06 07:19:25 | Date Closed: | 2013-01-21 06:32:29.000-0600 | ||
| Priority: | Minor | Regression? | No | ||
| Status: | Closed/Complete | Components: | Core/RTP | ||
| Versions: | Frequency of Occurrence | ||||
| Related Issues: |
| ||||
| Environment: | Attachments: | ( 0) dtmf-A1.pcap ( 1) dtmf-B1.pcap | |||
| Description: | if you use Dial with any options that activate features, the duration of all DTMF is changed to 1440 ****** ADDITIONAL INFORMATION ****** -- Executing [200@FromInternal:1] Dial("SIP/snom-0000000a", "SIP/mpe,,Tt") in new stack -- Called mpe -- SIP/mpe-0000000b is ringing -- SIP/mpe-0000000b answered SIP/snom-0000000a [Oct 6 11:50:06] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '1' received on SIP/snom-0000000a [Oct 6 11:50:06] DTMF[22063]: channel.c:3913 __ast_read: DTMF begin passthrough '1' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '1' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3858 __ast_read: DTMF end accepted with begin '1' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '1' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '2' received on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '2' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '2' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '2' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '2' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '3' received on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '3' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '3' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '2' queued on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '3' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '3' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '4' received on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '4' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '4' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '4' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '3' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '3' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '3' queued on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '4' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '4' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '5' received on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '5' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '5' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '5' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '6' received on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '6' on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '4' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:07] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '4' with duration 80 queued on SIP/snom-0000000a [Oct 6 11:50:07] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '4' queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '5' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '5' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '6' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '6' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '7' received on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '7' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '7' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '7' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '5' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '5' queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '6' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '6' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '7' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '7' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '8' received on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '8' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '8' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '9' received on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '9' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '9' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '9' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '6' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '6' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '6' queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '7' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '7' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '8' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '9' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '9' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '0' received on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '0' on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '7' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:08] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '7' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:08] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '7' queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '8' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '9' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '9' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '0' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '0' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '8' with duration 80 queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '8' queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '9' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '9' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '0' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '0' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '9' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '9' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '9' queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '0' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '0' on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '0' received on SIP/snom-0000000a, duration 100 ms [Oct 6 11:50:09] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '0' with duration 100 queued on SIP/snom-0000000a [Oct 6 11:50:09] DTMF[22063]: channel.c:3980 __ast_read: DTMF end emulation of '0' queued on SIP/snom-0000000a [Oct 6 11:50:12] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '1' received on SIP/snom-0000000a [Oct 6 11:50:12] DTMF[22063]: channel.c:3913 __ast_read: DTMF begin passthrough '1' on SIP/snom-0000000a [Oct 6 11:50:13] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '1' received on SIP/snom-0000000a, duration 1460 ms [Oct 6 11:50:13] DTMF[22063]: channel.c:3858 __ast_read: DTMF end accepted with begin '1' on SIP/snom-0000000a [Oct 6 11:50:13] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '1' on SIP/snom-0000000a [Oct 6 11:50:15] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '2' received on SIP/snom-0000000a [Oct 6 11:50:15] DTMF[22063]: channel.c:3913 __ast_read: DTMF begin passthrough '2' on SIP/snom-0000000a [Oct 6 11:50:17] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '2' received on SIP/snom-0000000a, duration 1860 ms [Oct 6 11:50:17] DTMF[22063]: channel.c:3858 __ast_read: DTMF end accepted with begin '2' on SIP/snom-0000000a [Oct 6 11:50:17] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '2' on SIP/snom-0000000a [Oct 6 11:50:18] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '3' received on SIP/snom-0000000a [Oct 6 11:50:18] DTMF[22063]: channel.c:3913 __ast_read: DTMF begin passthrough '3' on SIP/snom-0000000a [Oct 6 11:50:22] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '3' received on SIP/snom-0000000a, duration 4940 ms [Oct 6 11:50:22] DTMF[22063]: channel.c:3858 __ast_read: DTMF end accepted with begin '3' on SIP/snom-0000000a [Oct 6 11:50:22] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '3' on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '5' received on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3913 __ast_read: DTMF begin passthrough '5' on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '5' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:31] DTMF[22063]: channel.c:3858 __ast_read: DTMF end accepted with begin '5' on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3873 __ast_read: DTMF end '5' detected to have actual duration 71 on the wire, emulation will be triggered on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3880 __ast_read: DTMF end '5' has duration 71 but want minimum 80, emulating on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3936 __ast_read: DTMF end emulation of '5' queued on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3903 __ast_read: DTMF begin '8' received on SIP/snom-0000000a [Oct 6 11:50:31] DTMF[22063]: channel.c:3907 __ast_read: DTMF begin ignored '8' on SIP/snom-0000000a [Oct 6 11:50:32] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:32] DTMF[22063]: channel.c:3887 __ast_read: DTMF end passthrough '8' on SIP/snom-0000000a [Oct 6 11:50:32] DTMF[22063]: channel.c:3818 __ast_read: DTMF end '8' received on SIP/snom-0000000a, duration 80 ms [Oct 6 11:50:32] DTMF[22063]: channel.c:3844 __ast_read: DTMF begin emulation of '8' with duration 80 queued on SIP/snom-0000000a [Oct 6 11:50:32] DTMF[22063]: channel.c:3980 __ast_read: DTMF end emulation of '8' queued on SIP/snom-0000000a == Spawn extension (FromInternal, 200, 1) exited non-zero on 'SIP/snom-0000000a' | ||||
| Comments: | By: Mark Petersen (roadkill) 2010-10-06 07:25:58 I have atached 2 tcpdump's with a test call dtmf-A1 is from phone1 to Asterisk dtmf-B1 is from Asterisk to phone2 (snom 370 fw 8.4.18) By: Mark Petersen (roadkill) 2010-10-06 09:06:34 may be relatet to https://reviewboard.asterisk.org/r/957/ By: Mark Petersen (roadkill) 2010-10-06 09:16:42 trace from the pcap DTMF - A-Duration - B-Duration 1 - 800 - 1280 2 - 640 - 1440 3 - 800 - 1440 4 - 640 - 1600 5 - 640 - 1440 6 - 800 - 1440 7 - 640 - 1440 8 - 800 - 1440 9 - 800 - 1600 0 - 800 - 1440 1 -8000 - 1440 2 - 480 - 1440 (no end packet from A) 5 - 800 - 1280 (no end packet from A) 8 -1440 - 1280 0 - 800 - 1440 5 - 640 - 1440 2 - 320 - 1120 (no end packet from A) 8 -1120 - 1440 0 - 800 - 1760 if you also compare the output for the console all duration are a mess By: Mark Petersen (roadkill) 2010-10-06 09:53:47 this is a major problem if you are connectet to a Cisco SDP (Indband->rcf2388) as it send DTMF that can be as low as "1" RTP Event, DTMF *, Event Duration 1 RTP Event, DTMF *, Event Duration 41 RTP Event, DTMF *, Event Duration 81 RTP Event, DTMF *, Event Duration 240 END RTP Event, DTMF *, Event Duration 240 END RTP Event, DTMF *, Event Duration 240 END acording the the rfc any DTMF that has a duration that is less than 40ms must be ignored, but asterisk will react to any rfc2388 packets it resive, and change it to 1440 By: Olle Johansson (oej) 2011-02-14 07:10:27.000-0600 This is an issue I found out and fixed while working with ASTERISK-17329 By: Matt Jordan (mjordan) 2013-01-15 11:13:59.999-0600 There's a lot of these issues open. This is obviously a prevalent problem, but we don't do ourselves any favors by having 50 paper trails. As such, I'm going to ahead and close this issue out as a duplicate of ASTERISK-17329. | ||||