[Home]

Summary:ASTERISK-17962: a patch to fix bug 18130 breaks sequential emulated rfc2833 dtmf
Reporter:sdolloff (sdolloff)Labels:
Date Opened:2011-06-03 16:10:00Date Closed:2012-05-30 16:05:54
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/Channels
Versions:Frequency of
Occurrence
Related
Issues:
is related toASTERISK-17640 [patch] Enabled dynamic features swallow DTMF codes (even if no match)
Environment:Attachments:
Description:starting in version 1.6.2.17, if you try to send multiple dtmf digits quickly, every other tone is received but not send to the bridged channel.

reversion of this patch fixes the problem:


2011-01-12 18:11 +0000 [r301503]  Jeff Peeler <jpeeler@digium.com>

* main/channel.c, /: Merged revisions 301502 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4 ........
 r301502 | jpeeler | 2011-01-12 12:10:42 -0600 (Wed, 12 Jan 2011)
 | 12 lines Fix CPU spike when pressing DTMF after agent login.
 The problem here is that DTMF was being continuously deferred and
 requeued since ast_safe_sleep is called in a loop. There are
 serveral other places in the code that sleeps and then loops in a
 similar fashion. Because of this fact I opted to not defer DTMF
 any more, which will not affect the original fix:
 https://reviewboard.asterisk.org/r/674 (closes issue ASTERISK-16804)
 Reported by: rgj ........

to fix the problem, but i have no idea what impact this has on either of the original bugs:

--- main/channel.c.orig 2011-05-25 10:09:21.000000000 -0500
+++ main/channel.c  2011-06-03 13:46:31.000000000 -0500
@@ -1372,13 +1372,13 @@
    * be queued up or not.
    */
   switch (frame->frametype) {
+   case AST_FRAME_DTMF_END:
   case AST_FRAME_CONTROL:
   case AST_FRAME_TEXT:
   case AST_FRAME_IMAGE:
   case AST_FRAME_HTML:
       return 1;

-   case AST_FRAME_DTMF_END:
   case AST_FRAME_DTMF_BEGIN:
   case AST_FRAME_VOICE:
   case AST_FRAME_VIDEO:
@@ -5449,8 +5449,8 @@




****** ADDITIONAL INFORMATION ******

this is was the dtmf debug looks like with 1.6.2.17 and later:

every other digit is not emulated

[Jun  3 16:04:42] DTMF[4488]: channel.c:3051 __ast_read: DTMF begin '1' received on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:3061 __ast_read: DTMF begin passthrough '1' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:2966 __ast_read: DTMF end '1' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:42] DTMF[4488]: channel.c:3006 __ast_read: DTMF end accepted with begin '1' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:3035 __ast_read: DTMF end passthrough '1' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '2' received on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '2' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[12542]: channel.c:2966 __ast_read: DTMF end '2' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:42] DTMF[12542]: channel.c:3035 __ast_read: DTMF end passthrough '2' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:3051 __ast_read: DTMF begin '3' received on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:3061 __ast_read: DTMF begin passthrough '3' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:2966 __ast_read: DTMF end '3' received on SIP/256-00002f5f, duration 100 ms
[Jun  3 16:04:42] DTMF[4488]: channel.c:3006 __ast_read: DTMF end accepted with begin '3' on SIP/256-00002f5f
[Jun  3 16:04:42] DTMF[4488]: channel.c:3035 __ast_read: DTMF end passthrough '3' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '4' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '4' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:2966 __ast_read: DTMF end '4' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:43] DTMF[12542]: channel.c:3035 __ast_read: DTMF end passthrough '4' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '5' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '5' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:2966 __ast_read: DTMF end '5' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:43] DTMF[4488]: channel.c:2992 __ast_read: DTMF begin emulation of '5' with duration 80 queued on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3128 __ast_read: DTMF end emulation of '5' queued on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '6' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '6' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:2966 __ast_read: DTMF end '6' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:43] DTMF[12542]: channel.c:3035 __ast_read: DTMF end passthrough '6' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '7' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '7' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:2966 __ast_read: DTMF end '7' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:43] DTMF[12542]: channel.c:3035 __ast_read: DTMF end passthrough '7' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3051 __ast_read: DTMF begin '8' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3061 __ast_read: DTMF begin passthrough '8' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:2966 __ast_read: DTMF end '8' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:43] DTMF[4488]: channel.c:3006 __ast_read: DTMF end accepted with begin '8' on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3021 __ast_read: DTMF end '8' detected to have actual duration 79 on the wire, emulation will be triggered on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3028 __ast_read: DTMF end '8' has duration 79 but want minimum 80, emulating on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[4488]: channel.c:3084 __ast_read: DTMF end emulation of '8' queued on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3051 __ast_read: DTMF begin '9' received on SIP/256-00002f5f
[Jun  3 16:04:43] DTMF[12542]: channel.c:3055 __ast_read: DTMF begin ignored '9' on SIP/256-00002f5f
[Jun  3 16:04:44] DTMF[12542]: channel.c:2966 __ast_read: DTMF end '9' received on SIP/256-00002f5f, duration 80 ms
[Jun  3 16:04:44] DTMF[12542]: channel.c:3035 __ast_read: DTMF end passthrough '9' on SIP/256-00002f5f

before 1.6.2.17

[Jun  3 16:06:52] DTMF[15735]: channel.c:3076 __ast_read: DTMF begin '1' received on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:3086 __ast_read: DTMF begin passthrough '1' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '1' received on SIP/256-00000005, duration 100 ms
[Jun  3 16:06:52] DTMF[15735]: channel.c:3031 __ast_read: DTMF end accepted with begin '1' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:3060 __ast_read: DTMF end passthrough '1' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '2' received on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '2' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '2' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:52] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '2' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '2' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:52] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '2' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:3076 __ast_read: DTMF begin '3' received on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:3080 __ast_read: DTMF begin ignored '3' on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '2' queued on SIP/256-00000005
[Jun  3 16:06:52] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '3' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:52] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '3' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '4' received on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '4' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '4' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '4' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '3' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '3' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '3' queued on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '4' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '4' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '5' received on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '5' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '5' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '5' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '6' received on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '6' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '6' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '6' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '4' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '4' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '4' queued on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '5' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '5' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '6' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '6' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '7' received on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '7' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '7' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '7' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '8' received on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '8' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '8' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '8' on SIP/256-00000005
[Jun  3 16:06:53] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '5' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:53] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '5' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '5' queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '6' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '6' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '7' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '7' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '8' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '8' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:3076 __ast_read: DTMF begin '9' received on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:3080 __ast_read: DTMF begin ignored '9' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '9' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '9' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '6' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '6' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '6' queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '7' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '7' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '8' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '8' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '9' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '9' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '7' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '7' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '7' queued on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '8' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '8' on SIP/256-00000005
[Jun  3 16:06:54] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '9' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:54] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '9' on SIP/256-00000005
[Jun  3 16:06:55] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '8' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:55] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '8' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:55] DTMF[15735]: channel.c:3109 __ast_read: DTMF end emulation of '8' queued on SIP/256-00000005
[Jun  3 16:06:55] DTMF[15115]: channel.c:2991 __ast_read: DTMF end '9' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:55] DTMF[15115]: channel.c:3060 __ast_read: DTMF end passthrough '9' on SIP/256-00000005
[Jun  3 16:06:55] DTMF[15735]: channel.c:2991 __ast_read: DTMF end '9' received on SIP/256-00000005, duration 80 ms
[Jun  3 16:06:55] DTMF[15735]: channel.c:3017 __ast_read: DTMF begin emulation of '9' with duration 80 queued on SIP/256-00000005
[Jun  3 16:06:55] DTMF[15735]: channel.c:3153 __ast_read: DTMF end emulation of '9' queued on SIP/256-00000005


Comments:By: Gregory Hinton Nietsky (irroot) 2011-06-04 03:57:51

please check / test the patch on ASTERISK-17640 this is duplicate thank you for the info.

By: sdolloff (sdolloff) 2012-05-30 16:05:54.619-0500

we are upgrading to 1.8