[Home]

Summary:ASTERISK-17381: Local channel DTMF detection broken by 17370
Reporter:rsw686 (rsw686)Labels:
Date Opened:2011-02-10 09:40:39.000-0600Date Closed:2011-05-19 14:27:05
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:The patch for issue 17370 has broken DTMF detection when calling through a local channel. Here is a dialplan to quickly reproduce this. Dial 3350 enter 4567 and you will hear goodbye. Dial 3351 and you will hit invalid every time. Revert the patch for 17370 and dialing 3351 works.

exten => 3350,1,Goto(loopdtmf,s,1)
exten => 3351,1,Dial(Local/3350@from-internal,300,TW)

[loopdtmf]
exten => s,1,Answer
exten => s,n(repeat),Read(LOOPNUM,beep,,,,)
exten => s,n,GotoIf($[${LOOPNUM} = 4567]?good)
exten => s,n,Playback(invalid)
exten => s,n,Goto(repeat)
exten => s,n(good),Playback(goodbye)
exten => s,n,Hangup
Comments:By: Ronald Chan (loloski) 2011-02-10 10:11:49.000-0600

0017130: voicemail blasting to users with voicemail as an email does not seem to be working,

this issue was suspended! and no patch has been attached.


By: rsw686 (rsw686) 2011-02-10 10:14:19.000-0600

I'm sorry it was issue 17370. If somebody could edit the above that would be great.


By: Leif Madsen (lmadsen) 2011-02-10 11:57:32.000-0600

OK, I just talked to Qwell about this and he doesn't see how ASTERISK-16124 could affect this issue. I guess he just added a silence generator to the channel, and isn't sure how this would affect DTMF.
By: Jason Parker (jparker) 2011-02-10 11:58:08.000-0600

Could you add dialplan output from when this happens?  I'd like to see if any digits are being read.
By: Leif Madsen (lmadsen) 2011-02-10 12:02:19.000-0600

Include DTMF level logging as well. (logger.conf)
By: rsw686 (rsw686) 2011-02-10 12:25:04.000-0600

Output from dialplan

   -- Executing [3351@from-internal:1] Dial("SIP/2002-00000004", "Local/3350@from-internal,300,TW") in new stack
   -- Called 3350@from-internal
   -- Executing [3350@from-internal:1] Goto("Local/3350@from-internal-ad30;2", "loopdtmf,s,1") in new stack
   -- Goto (loopdtmf,s,1)
   -- Executing [s@loopdtmf:1] Answer("Local/3350@from-internal-ad30;2", "") in new stack
   -- Local/3350@from-internal-ad30;1 answered SIP/2002-00000004
   -- Executing [s@loopdtmf:2] Read("Local/3350@from-internal-ad30;2", "LOOPNUM,beep,,,,") in new stack
   -- <Local/3350@from-internal-ad30;2> Playing 'beep.ulaw' (language 'en')
   -- User entered nothing.
[Feb 10 13:21:05] WARNING[4633]: ast_expr2.fl:468 ast_yyerror: ast_yyerror():  syntax error: syntax error, unexpected '=', expecting $end; Input:
= 4567
^
[Feb 10 13:21:05] WARNING[4633]: ast_expr2.fl:472 ast_yyerror: If you have questions, please refer to doc/tex/channelvariables.tex.
   -- Executing [s@loopdtmf:3] GotoIf("Local/3350@from-internal-ad30;2", "?good") in new stack
   -- Executing [s@loopdtmf:4] Playback("Local/3350@from-internal-ad30;2", "invalid") in new stack
   -- <Local/3350@from-internal-ad30;2> Playing 'invalid.ulaw' (language 'en')
   -- Executing [s@loopdtmf:5] Goto("Local/3350@from-internal-ad30;2", "repeat") in new stack
   -- Goto (loopdtmf,s,2)
   -- Executing [s@loopdtmf:2] Read("Local/3350@from-internal-ad30;2", "LOOPNUM,beep,,,,") in new stack
   -- <Local/3350@from-internal-ad30;2> Playing 'beep.ulaw' (language 'en')
   -- Executing [h@from-internal:1] Macro("SIP/2002-00000004", "hangupcall") in new stack
   -- Executing [s@macro-hangupcall:1] GotoIf("SIP/2002-00000004", "1?skiprg") in new stack
   -- Goto (macro-hangupcall,s,4)
   -- Executing [s@macro-hangupcall:4] GotoIf("SIP/2002-00000004", "1?skipblkvm") in new stack
   -- Goto (macro-hangupcall,s,7)
   -- Executing [s@macro-hangupcall:7] GotoIf("SIP/2002-00000004", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,9)
   -- Executing [s@macro-hangupcall:9] Hangup("SIP/2002-00000004", "") in new stack
 == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/2002-00000004' in macro 'hangupcall'
   -- User disconnected
 == Spawn extension (from-internal, 3351, 1) exited non-zero on 'SIP/2002-00000004'
voip*CLI>

[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF begin '4' received on SIP/2002-00000004
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF begin passthrough '4' on SIP/2002-00000004
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF end '4' received on SIP/2002-00000004, duration 120 ms
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF end accepted with begin '4' on SIP/2002-00000004
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF end passthrough '4' on SIP/2002-00000004
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF begin '5' received on SIP/2002-00000004
[Feb 10 13:20:55] DTMF[4632] channel.c: DTMF begin passthrough '5' on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end '5' received on SIP/2002-00000004, duration 120 ms
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end accepted with begin '5' on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end passthrough '5' on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF begin '6' received on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF begin passthrough '6' on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end '6' received on SIP/2002-00000004, duration 80 ms
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end accepted with begin '6' on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end '6' detected to have actual duration 59 on the wire, emulation will be triggered on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end '6' has duration 59 but want minimum 80, emulating on SIP/2002-00000004
[Feb 10 13:20:56] DTMF[4632] channel.c: DTMF end emulation of '6' queued on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF begin '7' received on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF begin passthrough '7' on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF end '7' received on SIP/2002-00000004, duration 100 ms
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF end accepted with begin '7' on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF end '7' detected to have actual duration 79 on the wire, emulation will be triggered on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF end '7' has duration 79 but want minimum 80, emulating on SIP/2002-00000004
[Feb 10 13:20:57] DTMF[4632] channel.c: DTMF end emulation of '7' queued on SIP/2002-00000004

Output from dialplan with patch r285745 reverted

 == Using SIP RTP TOS bits 184
 == Using SIP RTP CoS mark 5
   -- Executing [3351@from-internal:1] Dial("SIP/2002-00000000", "Local/3350@from-internal,300,TW") in new stack
   -- Executing [3350@from-internal:1] Goto("Local/3350@from-internal-eed1;2", "loopdtmf,s,1") in new stack
   -- Goto (loopdtmf,s,1)
   -- Executing [s@loopdtmf:1] Answer("Local/3350@from-internal-eed1;2", "") in new stack
   -- Called 3350@from-internal
   -- Local/3350@from-internal-eed1;1 answered SIP/2002-00000000
   -- Executing [s@loopdtmf:2] Read("Local/3350@from-internal-eed1;2", "LOOPNUM,beep,,,,") in new stack
   -- <Local/3350@from-internal-eed1;2> Playing 'beep.ulaw' (language 'en')
   -- User entered '4567'
   -- Executing [s@loopdtmf:3] GotoIf("Local/3350@from-internal-eed1;2", "1?good") in new stack
   -- Goto (loopdtmf,s,6)
   -- Executing [s@loopdtmf:6] Playback("Local/3350@from-internal-eed1;2", "goodbye") in new stack
   -- <Local/3350@from-internal-eed1;2> Playing 'goodbye.ulaw' (language 'en')
   -- Executing [s@loopdtmf:7] Hangup("Local/3350@from-internal-eed1;2", "") in new stack
 == Spawn extension (loopdtmf, s, 7) exited non-zero on 'Local/3350@from-internal-eed1;2'
   -- Executing [h@from-internal:1] Macro("SIP/2002-00000000", "hangupcall") in new stack
   -- Executing [s@macro-hangupcall:1] GotoIf("SIP/2002-00000000", "1?skiprg") in new stack
   -- Goto (macro-hangupcall,s,4)
   -- Executing [s@macro-hangupcall:4] GotoIf("SIP/2002-00000000", "1?skipblkvm") in new stack
   -- Goto (macro-hangupcall,s,7)
   -- Executing [s@macro-hangupcall:7] GotoIf("SIP/2002-00000000", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,9)
   -- Executing [s@macro-hangupcall:9] Hangup("SIP/2002-00000000", "") in new stack
 == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/2002-00000000' in macro 'hangupcall'
 == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/2002-00000000'
 == Spawn extension (from-internal, 3351, 1) exited non-zero on 'SIP/2002-00000000'
   -- Executing [h@from-internal:1] Macro("SIP/2002-00000000", "hangupcall") in new stack
   -- Executing [s@macro-hangupcall:1] GotoIf("SIP/2002-00000000", "1?skiprg") in new stack
   -- Goto (macro-hangupcall,s,4)
   -- Executing [s@macro-hangupcall:4] GotoIf("SIP/2002-00000000", "1?skipblkvm") in new stack
   -- Goto (macro-hangupcall,s,7)
   -- Executing [s@macro-hangupcall:7] GotoIf("SIP/2002-00000000", "1?theend") in new stack
   -- Goto (macro-hangupcall,s,9)
   -- Executing [s@macro-hangupcall:9] Hangup("SIP/2002-00000000", "") in new stack
 == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/2002-00000000' in macro 'hangupcall'
 == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/2002-00000000'

[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin '4' received on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin passthrough '4' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end '4' received on SIP/2002-00000000, duration 100 ms
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end accepted with begin '4' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end passthrough '4' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF begin '4' received on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF begin ignored '4' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF begin '5' received on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF begin ignored '5' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF end '4' received on Local/3350@from-internal-eed1;2, duration 100 ms
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF end passthrough '4' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF end '5' received on SIP/2002-00000000, duration 80 ms
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF end passthrough '5' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end '5' received on SIP/2002-00000000, duration 80 ms
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin emulation of '5' with duration 80 queued on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin '6' received on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin ignored '6' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end emulation of '5' queued on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF end '6' received on SIP/2002-00000000, duration 80 ms
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF end passthrough '6' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF begin '5' received on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF begin ignored '5' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF end '5' received on Local/3350@from-internal-eed1;2, duration 100 ms
[Feb 10 13:23:03] DTMF[5294] channel.c: DTMF end passthrough '5' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF begin '7' received on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5295] channel.c: DTMF begin ignored '7' on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end '6' received on SIP/2002-00000000, duration 80 ms
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF begin emulation of '6' with duration 80 queued on SIP/2002-00000000
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end '7' received on SIP/2002-00000000, duration 100 ms
[Feb 10 13:23:03] DTMF[5293] channel.c: DTMF end emulation of '6' queued on SIP/2002-00000000
[Feb 10 13:23:04] DTMF[5295] channel.c: DTMF end '7' received on SIP/2002-00000000, duration 100 ms
[Feb 10 13:23:04] DTMF[5295] channel.c: DTMF end passthrough '7' on SIP/2002-00000000
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF begin '6' received on Local/3350@from-internal-eed1;2
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF begin ignored '6' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF end '6' received on Local/3350@from-internal-eed1;2, duration 100 ms
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF end passthrough '6' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:04] DTMF[5293] channel.c: DTMF end '7' received on SIP/2002-00000000, duration 100 ms
[Feb 10 13:23:04] DTMF[5293] channel.c: DTMF begin emulation of '7' with duration 100 queued on SIP/2002-00000000
[Feb 10 13:23:04] DTMF[5293] channel.c: DTMF end emulation of '7' queued on SIP/2002-00000000
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF begin '7' received on Local/3350@from-internal-eed1;2
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF begin ignored '7' on Local/3350@from-internal-eed1;2
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF end '7' received on Local/3350@from-internal-eed1;2, duration 100 ms
[Feb 10 13:23:04] DTMF[5294] channel.c: DTMF end passthrough '7' on Local/3350@from-internal-eed1;2


By: Jason Parker (jparker) 2011-02-10 12:40:33.000-0600

Could you find the value of ${READSTATUS}?
By: rsw686 (rsw686) 2011-02-10 12:49:48.000-0600

${READSTATUS} has a value of TIMEOUT with and without the patch reverted. I know it seems weird the silence generator affects this. I had to test multiple Asterisk versions and revert various patches to track this down. If you test the sample dialplan you can reproduce this 100% of the time.


By: Leif Madsen (lmadsen) 2011-02-10 12:59:15.000-0600

Are you sure this isn't a regression of ASTERISK-16804 rather than ASTERISK-16124 ?
By: rsw686 (rsw686) 2011-02-10 13:12:34.000-0600

Yes that change went into 1.8.2.3-rc1. I actually have 18130 reverted on my 1.8.2.3-rc1 install as it caused problems. This issue from 17370 is also experienced on a clean 1.8.2.2 install. I tested with 1.8.0 and it happened there as well. When I was narrowing it down it stopped working on version 1.6.2.14 and worked on 1.6.2.13.
By: rsw686 (rsw686) 2011-03-22 23:57:40

This can be closed. It was resolved by revision 310902 for 1.8 "Don't delay DTMF in core bridge while listening for DTMF features".
By: Leif Madsen (lmadsen) 2011-04-19 10:19:12

Closed per rmudgett's comment. Thanks!