[Home]

Summary:ASTERISK-08360: SIP, dtmf-relay, feature key presses being ignored
Reporter:Russell Brown (ruffle)Labels:
Date Opened:2006-12-15 12:19:10.000-0600Date Closed:2007-01-19 12:06:34.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) ast.conf.tgz
( 1) verbosedebug.txt
Description:During a Sip to Sip Call, Asterisk fails to act on pressing DTMF keys that correspond to features.

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

Here's the o/p from feature show:

asterisk*CLI> feature show
Builtin Feature           Default Current
---------------           ------- -------
Pickup                    *8      *8    
Blind Transfer            #       #      
Attended Transfer                 *2    
One Touch Monitor                 *1    
Disconnect Call           *       *      
Park Call                         ASTERISK-68    

Dynamic Feature           Default Current
---------------           ------- -------
testfeature               no def  ASTERISK-5    

Call parking
------------
Parking extension   :   700
Parking context     :   parkedcalls
Parked call extensions: 701-720

asterisk*CLI>

... and if I press * during a Sip-Sip Call here's the console debug (the
call remains up)

[Dec 15 18:16:13] DTMF[20535]: channel.c:2128 __ast_read: DTMF end '1' received on SIP/112-00704f60
[Dec 15 18:16:13] DTMF[20535]: channel.c:2128 __ast_read: DTMF end '1' received on SIP/112-00704f60
[Dec 15 18:16:13] DTMF[20535]: channel.c:2128 __ast_read: DTMF end '4' received on SIP/112-00704f60
[Dec 15 18:16:17] DEBUG[20535]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/112-00704f60
[Dec 15 18:16:17] DEBUG[20535]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/112-00704f60 and SIP/114-0070afb0
 == Spawn extension (macro-stdsip, s, 1) exited non-zero on 'SIP/112-00704f60' in macro 'stdsip'
 == Spawn extension (macro-stdsip, s, 1) exited non-zero on 'SIP/112-00704f60'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Russell Brown" <01780471802>'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '01780471802'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '114'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'from-sip'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/112-00704f60'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/114-0070afb0'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Sip/114"|10|Trt'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-15 18:04:03'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-15 18:04:06'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-15 18:16:17'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '734'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '731'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1166205843.0'
[Dec 15 18:16:17] DEBUG[20535]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
   -- Executing [114@from-sip:1] Macro("SIP/112-00715510", "stdsip||"Sip/114"") in new stack
   -- Executing [s@macro-stdsip:1] Dial("SIP/112-00715510", ""Sip/114"|10|Trt") in new stack
   -- Called 114
   -- SIP/114-0070da30 is ringing
   -- SIP/114-0070da30 is ringing
   -- SIP/114-0070da30 answered SIP/112-00715510
[Dec 15 18:16:26] DTMF[20552]: channel.c:2128 __ast_read: DTMF end '*' received on SIP/112-00715510
[Dec 15 18:16:26] DEBUG[20552]: channel.c:3726 ast_generic_bridge: Got DTMF begin on channel (SIP/112-00715510)
[Dec 15 18:16:26] DEBUG[20552]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/112-00715510 and SIP/114-0070da30
asterisk*CLI>

Comments:By: Serge Vecher (serge-v) 2006-12-15 13:32:56.000-0600

Can you please redo SIP debug as per following:
1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterisk with the following command:
  'asterisk -Tvvvvvdddddgc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
5) Trim startup information and attach verbosedebug.txt to the issue.
By: Joshua C. Colp (jcolp) 2006-12-18 11:32:41.000-0600

I spent some time trying to lab this issue up and was unable to. Basically tried both INFO based DTMF and RFC2833, and everything worked fine. Can you provide your configuration information? Thanks.
By: Russell Brown (ruffle) 2006-12-19 12:38:51.000-0600

Certainly,  what config info would you like?
By: Joshua C. Colp (jcolp) 2006-12-19 14:49:00.000-0600

sip.conf and features.conf - also be sure to try latest 1.4
By: Russell Brown (ruffle) 2006-12-20 12:05:17.000-0600

OK, I've uploaded ast.conf.tgz which contains /etc/asterisk from my
test system with the failing case.

I've tried Asterisk 1.4.0-beta4 and there's no difference.

FYI, the machine is a x86_64 (Intel Core 2) based box, running Ubuntu on
a 2.6.17-10 kernel.

The SIP Phones being used are Snom 360, 300 & 190

Anything else I can supply to help track this down?
By: Joshua C. Colp (jcolp) 2006-12-22 11:25:45.000-0600

I've looked over the configurations and everything seems fine. What should be happening is this:

1. chan_sip receives an INFO
2. chan_sip queues up a DTMF_END to the core
3. core compensates by sending DTMF_BEGIN
4. core sends DTMF_END 500ms later

By any chance are you using vad or silence suppression on the phones?
By: Phoebe Anderson (phoebe) 2006-12-26 18:40:53.000-0600

I have the same issues with my 1.4.0 test box.  

Setting canreinvite=no in sip.conf is a workaround that resolves the problem.  

I have replicated the results with the following SIP devices: Polycom IP501, Grandstream 101 and PAP-2.
By: Christian Dannemann (wilderbeest) 2006-12-28 07:44:41.000-0600

Just to confirm that I encounter the same problem. All is fine using 1.2.14, when I switch to 1.4 all stuff in features.conf isn't recognized. DTMF as such works, as I can use DTMF tones for voicemail, Dictate(), etc.

Only stuff in features.conf doesn't work any more, such as transfers, recording calls etc.

Kind Regards,

Christian
By: Serge Vecher (serge-v) 2006-12-28 09:03:28.000-0600

guys, can you please produce a sip debug trace as per 0056481 with and without canreinvite set to 'no'?
By: Russell Bryant (russell) 2007-01-17 16:13:55.000-0600

There is a branch now available that should fix the issue reported here when using SIP INFO dtmf with Asterisk 1.4.  Please try this branch if you are having problems:

svn co http://svn.digium.com/svn/asterisk/team/group/vldtmf_fixup
By: pj (pj) 2007-01-18 02:14:08.000-0600

can it relate to bugreport 0008815?
I have problem with recognizing dtmf digits from chan_h323, digits must be typed slowly (about 1sec delay) to be recognized correctly.
By: Russell Bryant (russell) 2007-01-19 12:06:33.000-0600

This should be fixed in the 1.4 branch in revision 51311 and the trunk in revision 51314.