[Home]

Summary:ASTERISK-17885: Local Channels not passing DTMF Tones properly
Reporter:Daniel Ballenger (dballenger)Labels:
Date Opened:2011-05-18 19:07:45Date Closed:2011-07-26 14:16:47
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_local
Versions:1.6.2.18 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:This appears to be the same (or at least a similar) issue to bug report ASTERISK-17381

When a call goes through a local channels, the DTMF digits don't always get passed reliably.  I don't exactly know what version I first saw the issue on, but I can confirm it is present in 1.6.2.17.2 and 1.6.2.18

Here is a sample dialplan which was used to duplicate the issue for the log entries pasted below:
exten => 601,1,Answer
exten => 601,2,Read(digits)
exten => 601,3,SayDigits(${digits})
exten => 602,1,Dial(Local/601@mcid19-outgoing/n)

Calling 601 directly yields the proper results (all pressed DTMF digits are properly read back out), but when calling 602, DTMF digit recognition is sporadic at best (pressing 1,2,3,4,5,6,7,8,9 yielded "1,4,7")

DTMF log when directly dialing extension:
2011-05-18T23:57:39+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '1' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:39+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '1' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:39+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '1' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '2' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '2' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '2' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '3' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '3' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '3' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '4' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '4' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '4' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '5' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '5' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:40+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '5' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '6' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '6' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '6' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '7' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '7' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '7' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '8' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '8' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:41+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '8' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '9' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '9' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '9' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '#' received on SCCP/mcid19-dballenger-line1-00000010, duration 0 ms
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '#' on SCCP/mcid19-dballenger-line1-00000010
2011-05-18T23:57:42+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '#' on SCCP/mcid19-dballenger-line1-00000010

DTMF log when going through Local channel:
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '1' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin emulation of '1' with duration 100 queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end emulation of '1' queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '2' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '2' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '2' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '3' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '3' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '3' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin '1' received on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin ignored '1' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '1' received on Local/601@mcid19-outgoing-e40a;2, duration 100 ms
2011-05-18T23:58:30+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '1' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '4' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin emulation of '4' with duration 100 queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end emulation of '4' queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '5' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '5' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '5' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin '4' received on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin ignored '4' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '4' received on Local/601@mcid19-outgoing-e40a;2, duration 100 ms
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '4' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '6' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '6' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '6' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '7' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin emulation of '7' with duration 100 queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:31+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end emulation of '7' queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '8' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '8' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '8' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin '7' received on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin ignored '7' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '7' received on Local/601@mcid19-outgoing-e40a;2, duration 100 ms
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '7' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '9' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end accepted without begin '9' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '9' on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '#' received on SCCP/mcid19-dballenger-line1-00000011, duration 0 ms
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin emulation of '#' with duration 100 queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end emulation of '#' queued on SCCP/mcid19-dballenger-line1-00000011
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin '#' received on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF begin ignored '#' on Local/601@mcid19-outgoing-e40a;2
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end '#' received on Local/601@mcid19-outgoing-e40a;2, duration 100 ms
2011-05-18T23:58:32+00:00 dl0002 asterisk[38696]: DTMF[38696]: DTMF end passthrough '#' on Local/601@mcid19-outgoing-e40a;2
Comments:By: Leif Madsen (lmadsen) 2011-05-19 14:27:29

Can you reproduce this on Asterisk 1.8?

~~~~~

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch.

For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions
By: Daniel Ballenger (dballenger) 2011-05-19 14:35:40

I can't run Asterisk 1.8 (I use the chan_sccp-b driver).  I'm guessing I'll need to patch/fix this myself since support has ended?
By: Daniel Ballenger (dballenger) 2011-05-19 14:53:30

Since it looks like this issue was related to the features code, I changed featuredigittimeout = 500 to featuredigittimeout = 5
I don't make use of the feature codes at the moment anyways, and this seems to have resolved the issue for now.  I just wanted to document the work around incase anyone else runs into this and can't upgrade.
By: Chris Baker (cmbaker82) 2011-06-02 16:02:10

I'm not sure if this is exactly the same but outbound dtmf is giving us issues on 1.8.4.1

In the log below, the digit 5 was ignored

[Jun  2 16:54:34] DTMF[9050]: channel.c:3985 __ast_read: DTMF begin '4' received on SIP/2710-0000011e
[Jun  2 16:54:34] DTMF[9050]: channel.c:3995 __ast_read: DTMF begin passthrough '4' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3900 __ast_read: DTMF end '4' received on SIP/2710-0000011e, duration 190 ms
[Jun  2 16:54:35] DTMF[9050]: channel.c:3940 __ast_read: DTMF end accepted with begin '4' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3969 __ast_read: DTMF end passthrough '4' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[29812]: channel.c:3985 __ast_read: DTMF begin '5' received on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[29812]: channel.c:3989 __ast_read: DTMF begin ignored '5' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[29812]: channel.c:3900 __ast_read: DTMF end '5' received on SIP/2710-0000011e, duration 130 ms
[Jun  2 16:54:35] DTMF[29812]: channel.c:3969 __ast_read: DTMF end passthrough '5' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3985 __ast_read: DTMF begin '6' received on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3995 __ast_read: DTMF begin passthrough '6' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3900 __ast_read: DTMF end '6' received on SIP/2710-0000011e, duration 110 ms
[Jun  2 16:54:35] DTMF[9050]: channel.c:3940 __ast_read: DTMF end accepted with begin '6' on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3955 __ast_read: DTMF end '6' detected to have actual duration 60 on the wire, emulation will be triggered on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:3962 __ast_read: DTMF end '6' has duration 60 but want minimum 80, emulating on SIP/2710-0000011e
[Jun  2 16:54:35] DTMF[9050]: channel.c:4018 __ast_read: DTMF end emulation of '6' queued on SIP/2710-0000011e
By: Russell Bryant (russell) 2011-07-26 14:16:39.890-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions