[Home]

Summary:ASTERISK-09261: SIP - Bridge Call - Not all DTMF tones send when multiple digits are needed.
Reporter:Erik Sundberg (sunder)Labels:
Date Opened:2007-04-13 13:55:50Date Closed:2007-08-03 09:56:30
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/CodecHandling
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) Capture_from_span_the_port_that_the_phone_is_one.pcap
( 1) Out_side_of_our_pbx_to_sip_provider.pcap
Description:Issue
--------
Not all of the DTMF tone are being sent when a SIP call is bridge through the system. And you are required to hit multiple digits in a row. When you have to hit a single digit it works fine.


Systems Setup
----------------------

Asterisk 1.2.17
SIP Trunk with CBeyond
They use a broadsoft SIP Proxy at CBeyond
DTMF is set to INBAND
All codecs are ULAW
Canreinvite is set to no for both peers.

From my cell phone call our customer is works with no problems.

I have used the following phones to verify this
Hitcachi IP 4000
Polycom 501
Polcyom 601
Polycom 4000
Aastra 480i

I have tried inband and rfc2833 with the same results on the phones.
The SIP trunk to the provider is ULAW and inband DTMF


The setup
---------------
SIP Phone ------ Our PBX --------sip trunk ------------ CBeyond Internet/VoIP -----------sip trunk------------customer pbx

The process to reproduce
------------------------------------
We call from our office to our customer
There pbx pickups up
Press 1 for the company directory
Press 2 for a directory by last name
Enter the last name of the person who I am calling Gordon 467
Our pbx see 467 from the phone
But only send 4 to the Provider
Then I hang-up the call.


What Happens
---------------------

Between the phone and the PBX there is DTMF 467 and the PBX see this.


Between our pbx and the SIP provider  when the audio stream goes back out there is only 4 not the 67


So think there is a dtmf issue when bridging calls.






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

System Calling from (Our office)
----------------------------------------------


Apr 13 13:37:50 DEBUG[8937] pbx.c: Launching 'Goto'
Apr 13 13:37:50 DEBUG[8937] pbx.c: Launching 'Verbose'
Apr 13 13:37:50 DEBUG[8937] pbx.c: Launching 'Answer'
Apr 13 13:37:50 DEBUG[8937] chan_sip.c: sip_answer(SIP/4808-09866668)
Apr 13 13:37:50 DEBUG[8937] pbx.c: Launching 'Set'
Apr 13 13:37:50 DEBUG[8937] pbx.c: Launching 'Dial'
Apr 13 13:37:50 DEBUG[8937] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Apr 13 13:37:50 DEBUG[8937] chan_sip.c: Setting NAT on RTP to 0
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable STACK-dialtrunk-8735540-4.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable STACK-dialtrunk-8735540-3.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable STACK-dialtrunk-8735540-2.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable STACK-dialtrunk-8735540-1.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable STACK-group1-8735540-1.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable SIPCALLID.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable SIPUSERAGENT.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable SIPDOMAIN.
Apr 13 13:37:50 DEBUG[8937] channel.c: Not copying variable SIPURI.
Apr 13 13:37:50 DEBUG[8937] chan_sip.c: Outgoing Call for 8735540
Apr 13 13:37:50 DEBUG[8937] chan_sip.c: Updating call counter for outgoing call
Apr 13 13:37:51 DEBUG[8937] rtp.c: Ooh, format changed from unknown to ulaw
Apr 13 13:37:51 DEBUG[8937] rtp.c: Got RTCP report of 88 bytes
Apr 13 13:37:52 DEBUG[8937] rtp.c: Ooh, format changed from unknown to ulaw
Apr 13 13:37:56 DEBUG[8937] chan_sip.c: * Detected inband DTMF '1'
Apr 13 13:37:56 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format slin
Apr 13 13:37:56 DEBUG[8937] channel.c: Scheduling timer at 160 sample intervals
Apr 13 13:37:56 DTMF[8937] channel.c: SIP/cbeyond-0985e208 : 1
Apr 13 13:37:56 DEBUG[8937] channel.c: Generator got voice, switching to phase locked mode
Apr 13 13:37:56 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:37:57 DEBUG[8937] rtp.c: Difference is 8000, ms is 1020
Apr 13 13:37:57 DEBUG[8937] channel.c: Auto-deactivating generator
Apr 13 13:37:57 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format ulaw
Apr 13 13:37:57 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:37:59 DEBUG[8937] chan_sip.c: * Detected inband DTMF '2'
Apr 13 13:37:59 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format slin
Apr 13 13:37:59 DEBUG[8937] channel.c: Scheduling timer at 160 sample intervals
Apr 13 13:37:59 DTMF[8937] channel.c: SIP/cbeyond-0985e208 : 2
Apr 13 13:37:59 DEBUG[8937] channel.c: Generator got voice, switching to phase locked mode
Apr 13 13:37:59 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:37:59 DEBUG[8937] channel.c: Auto-deactivating generator
Apr 13 13:37:59 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format ulaw
Apr 13 13:37:59 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:38:01 DEBUG[8937] rtp.c: Got RTCP report of 88 bytes
Apr 13 13:38:03 DEBUG[8937] chan_sip.c: * Detected inband DTMF '4'
Apr 13 13:38:03 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format slin
Apr 13 13:38:03 DEBUG[8937] channel.c: Scheduling timer at 160 sample intervals
Apr 13 13:38:03 DTMF[8937] channel.c: SIP/cbeyond-0985e208 : 4
Apr 13 13:38:03 DEBUG[8937] channel.c: Generator got voice, switching to phase locked mode
Apr 13 13:38:03 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:38:03 DEBUG[8937] chan_sip.c: * Detected inband DTMF '6'
Apr 13 13:38:04 DEBUG[8937] chan_sip.c: * Detected inband DTMF '7'
Apr 13 13:38:06 DEBUG[8937] rtp.c: Difference is 24008, ms is 3021
Apr 13 13:38:06 DEBUG[8937] channel.c: Auto-deactivating generator
Apr 13 13:38:06 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format ulaw
Apr 13 13:38:06 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:38:11 DEBUG[8937] rtp.c: Got RTCP report of 88 bytes
Apr 13 13:38:11 DEBUG[8937] chan_sip.c: * Detected inband DTMF '4'
Apr 13 13:38:11 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format slin
Apr 13 13:38:11 DEBUG[8937] channel.c: Scheduling timer at 160 sample intervals
Apr 13 13:38:11 DTMF[8937] channel.c: SIP/cbeyond-0985e208 : 4
Apr 13 13:38:11 DEBUG[8937] channel.c: Generator got voice, switching to phase locked mode
Apr 13 13:38:11 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:38:12 DEBUG[8937] chan_sip.c: * Detected inband DTMF '6'
Apr 13 13:38:12 DEBUG[8937] chan_sip.c: * Detected inband DTMF '7'
Apr 13 13:38:14 DEBUG[8937] rtp.c: Difference is 23848, ms is 3001
Apr 13 13:38:14 DEBUG[8937] channel.c: Auto-deactivating generator
Apr 13 13:38:14 DEBUG[8937] channel.c: Set channel SIP/cbeyond-0985e208 to write format ulaw
Apr 13 13:38:14 DEBUG[8937] channel.c: Scheduling timer at 0 sample intervals
Apr 13 13:38:18 DEBUG[8937] channel.c: Didn't get a frame from channel: SIP/4808-09866668
Apr 13 13:38:18 DEBUG[8937] channel.c: Bridge stops bridging channels SIP/4808-09866668 and SIP/cbeyond-0985e208
Apr 13 13:38:18 DEBUG[8937] channel.c: Hanging up channel 'SIP/cbeyond-0985e208'
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: Hangup call SIP/cbeyond-0985e208, SIP callid 0df62b717c11ead026af93ab6b7c51da@sipconnect.chi0.cbeyond.net)
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: update_call_counter(8735540) - decrement call limit counter
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: Updating call counter for outgoing call
Apr 13 13:38:18 DEBUG[8937] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 13 13:38:18 DEBUG[8937] pbx.c: Spawn extension (dialtrunk,8735540,4) exited non-zero on 'SIP/4808-09866668'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '"E. Sundberg" <7084684800>'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '7084684800'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '8735540'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'dialtrunk'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'SIP/4808-09866668'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'SIP/cbeyond-0985e208'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'Dial'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'SIP/cbeyond/8735540|60'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '2007-04-13 13:37:50'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '2007-04-13 13:37:50'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '2007-04-13 13:38:18'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '28'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '28'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'ANSWERED'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is 'DOCUMENTATION'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '(null)'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '1176489470.1278'
Apr 13 13:38:18 DEBUG[8937] pbx.c: Function result is '(null)'
Apr 13 13:38:18 DEBUG[8937] channel.c: Hanging up channel 'SIP/4808-09866668'
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: Hangup call SIP/4808-09866668, SIP callid 58e263c7-bea5e321-5872b140@10.10.0.197)
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: update_call_counter(4808) - decrement call limit counter
Apr 13 13:38:18 DEBUG[8937] chan_sip.c: Updating call counter for incoming call



Our Customers PBX
-----------------------------
What our customer PBX sees

Apr 13 12:37:34 DEBUG[28943] channel.c: Scheduling timer at 58 sample intervals
Apr 13 12:37:34 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:34 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:34 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:37:34 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:37:34 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals
Apr 13 12:37:34 DEBUG[28943] chan_sip.c: * Detected inband DTMF '1'
Apr 13 12:37:34 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:34 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:37:34 DEBUG[28943] pbx.c: Oooh, got something to jump out with ('1')!
Apr 13 12:37:34 DEBUG[28943] pbx.c: Launching 'Goto'
Apr 13 12:37:34 DEBUG[28943] pbx.c: Launching 'NoOp'
Apr 13 12:37:34 DEBUG[28943] pbx.c: Launching 'Answer'
Apr 13 12:37:34 DEBUG[28943] pbx.c: Launching 'Wait'
Apr 13 12:37:35 DEBUG[28943] pbx.c: Launching 'BackGround'
Apr 13 12:37:35 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:37:35 DEBUG[28943] rtp.c: Difference is 7880, ms is 1005
Apr 13 12:37:35 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals
Apr 13 12:37:45 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:45 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:45 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:37:45 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:37:45 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals
Apr 13 12:37:48 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:48 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:48 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:37:48 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:37:48 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals

#2 for last name directory

Apr 13 12:37:56 DEBUG[28943] chan_sip.c: * Detected inband DTMF '2'
Apr 13 12:37:56 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:37:56 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:37:56 DEBUG[28943] pbx.c: Oooh, got something to jump out with ('2')!
Apr 13 12:37:56 DEBUG[28943] pbx.c: Launching 'NoOp'
Apr 13 12:37:56 DEBUG[28943] pbx.c: Launching 'Directory'
Apr 13 12:37:56 DEBUG[28943] config.c: Parsing /etc/asterisk/voicemail.conf
Apr 13 12:37:56 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:37:56 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals

#Please enter the first 3 letter of your parties last name
#Entering 467 for Gordon
#System only sees the number 4 pressed

Apr 13 12:38:05 DEBUG[28943] chan_sip.c: * Detected inband DTMF '4'
Apr 13 12:38:05 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:05 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:38:08 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:38:08 DEBUG[28943] rtp.c: Difference is 23872, ms is 3004
Apr 13 12:38:08 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals
Apr 13 12:38:10 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:10 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:10 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:38:10 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:38:10 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals

# sorry

Apr 13 12:38:15 DEBUG[28943] chan_sip.c: * Detected inband DTMF '4'
Apr 13 12:38:15 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:15 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:38:18 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:38:18 DEBUG[28943] rtp.c: Difference is 23952, ms is 3014
Apr 13 12:38:18 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals
Apr 13 12:38:20 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:20 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:20 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:38:20 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format gsm
Apr 13 12:38:20 DEBUG[28943] channel.c: Scheduling timer at 160 sample intervals

#sorry
# I hangup

Apr 13 12:38:31 DEBUG[28943] channel.c: Scheduling timer at 0 sample intervals
Apr 13 12:38:31 DEBUG[28943] channel.c: Set channel SIP/7084684269-b7ca10b0 to write format ulaw
Apr 13 12:38:31 DEBUG[28943] pbx.c: Spawn extension (ivr-directory,2,2) exited non-zero on 'SIP/7084684269-b7ca10b0'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '"NR-Cipher Consulting Group" <7084684800>'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '7084684800'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '2'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'ivr-directory'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'SIP/7084684269-b7ca10b0'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '(null)'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'Directory'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'default|extensions'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '2007-04-13 12:37:07'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '2007-04-13 12:37:07'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '2007-04-13 12:38:31'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '84'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '84'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'ANSWERED'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is 'DOCUMENTATION'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '(null)'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '1176485827.11791'
Apr 13 12:38:31 DEBUG[28943] pbx.c: Function result is '(null)'
Apr 13 12:38:31 DEBUG[28943] channel.c: Hanging up channel 'SIP/7084684269-b7ca10b0'
Apr 13 12:38:31 DEBUG[28943] chan_sip.c: Hangup call SIP/7084684269-b7ca10b0, SIP callid BW133707090130407-590672023@bwas1-vir.atl0.cbeyond.net)
Apr 13 12:38:31 DEBUG[28943] chan_sip.c: update_call_counter(7084684269) - decrement call limit counter
Apr 13 12:38:31 DEBUG[28943] chan_sip.c: Updating call counter for incoming call



Comments:By: Erik Sundberg (sunder) 2007-04-13 15:01:47

logs and captures are from different calls around the same time, but they all have the same results
Someone please change the bug type i put the wrong on in.
By: Erik Sundberg (sunder) 2007-04-13 15:03:09

I have also seen this on the following versions of asterisk: BE-1.3, 1.2.9.1, 1.2.12.1, 1.2.13 1.2.15, 1.2.16, 1.2.17
By: Joshua C. Colp (jcolp) 2007-05-17 10:44:10

DTMF in Asterisk 1.2 isn't that good... so much in fact that we rewrote it in Asterisk 1.4. If you try Asterisk 1.4 from SVN does it improve the situation?
By: Joshua C. Colp (jcolp) 2007-08-03 09:56:30

1.2 has now entered a security fixes only state. If this is still an issue under 1.4 please reopen.