<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
Hello asterisk-users list. <br>
I have been scratching my head for almost a week. We are trying to set
a service with a company (ip=XXX.XXX.XXX.XXX) and dtmf is not working. <br>
In our scenario the SP is sending call to our ser server and ser is
forwarding the call to asterisk. In the asterisk debug I can see the
DTMF keys are coming but ivr does not recognice those keys at all. I
can see this in the debug. We are using ulaw and alaw for codec. <br>
<br>
<b>May 24 20:14:00 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX</b><br>
<br>
<br>
Voice part works great. I mean if I forward that call to asterisk sip
user we can talk. <br>
Every thing is working great with other SP. The only difference I can
see is the rtpmap:101 telephone-event/8000. <br>
With the working SP the rtpmap is rtpmap:100 telephone-event/8000.<br>
<br>
I need solution ASAP, so please give me any hint you can. <br>
<br>
Here is complete debug log for one call. <br>
<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: Allocating new SIP dialog for
9CB80474-<br>
<a class="moz-txt-link-abbreviated" href="mailto:98311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX">98311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX</a> - INVITE (With RTP)<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: **** Received INVITE (5) -
Command in S<br>
IP INVITE<br>
May 24 20:13:47 DEBUG[26583] res_config_mysql.c: MySQL RealTime:
Everything is f<br>
ine.<br>
May 24 20:13:47 DEBUG[26583] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: S<br>
ELECT * FROM cc_sip_buddies WHERE name = '6056911122'<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: Setting NAT on RTP to 0<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: Checking SIP call limits for
device<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: Updating call counter for
incoming call<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: build_route: Record-Route hop:
<<a class="moz-txt-link-freetext" href="sip:209">sip:209</a><br>
.216.2.212;ftag=E3F05090-621;lr=on><br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: build_route: Record-Route hop:
<a class="moz-txt-link-rfc2396E" href="sip:zzz.zzz.zzz.zzz;ftag=E3F05090-621;lr=on"><sip:zzz.zzz.zzz.zzz;ftag=E3F05090-621;lr=on></a><br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: build_route: Record-Route hop:
<a class="moz-txt-link-rfc2396E" href="sip:yy-proxy-ip.yy;lr"><sip:yy-proxy-ip.yy;lr></a><br>
May 24 20:13:47 DEBUG[26574] chan_sip.c: Checking device state for peer
XXX.XXX.XXXX.XXX<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'NoOp'<br>
May 24 20:13:47 DEBUG[26574] devicestate.c: Changing state for
SIP/XXX.XXX.XXX.XXX -<br>
state 2 (In use)<br>
May 24 20:13:47 DEBUG[26804] app_queue.c: Device 'SIP/XXX.XXX.XXX.XXX'
changed to st<br>
ate '2' (In use) but we don't care because they're not a member of any
queue.<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Goto'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Set'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Goto'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Set'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Set'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Answer'<br>
May 24 20:13:47 DEBUG[26803] chan_sip.c:
sip_answer(SIP/XXX.XXX.XXX.XXX-b7b03730)<br>
May 24 20:13:47 DEBUG[26574] chan_sip.c: Checking device state for peer
XXX.XXX.XXXX.XXX<br>
May 24 20:13:47 DEBUG[26574] channel.c: Avoiding initial deadlock for
'SIP/XXX.XXX.XXXX.XXX-b7b03730'<br>
May 24 20:13:47 DEBUG[26803] pbx.c: Launching 'Wait'<br>
May 24 20:13:47 DEBUG[26574] devicestate.c: Changing state for
SIP/XXX.XXX.XXX.XXX -<br>
state 2 (In use)<br>
May 24 20:13:47 DEBUG[26805] app_queue.c: Device 'SIP/XXX.XXX.XXX.XXX'
changed to st<br>
ate '2' (In use) but we don't care because they're not a member of any
queue.<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: = Found Their Call ID:
9CB80474-98311DC<br>
-86A1C9BE-38B97399@XXX.XXX.XXX.XXX Their Tag E3F05090-621 Our tag:
as3becafbb<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: **** Received ACK (6) -
Command in SIP<br>
ACK<br>
May 24 20:13:47 DEBUG[26583] chan_sip.c: Stopping retransmission on
'9CB80474-98<br>
<a class="moz-txt-link-abbreviated" href="mailto:311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX">311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX</a>' of Response 101: Match Found<br>
May 24 20:13:48 DEBUG[26803] pbx.c: Launching 'Set'<br>
May 24 20:13:48 DEBUG[26803] pbx.c: Launching 'Set'<br>
May 24 20:13:48 DEBUG[26803] pbx.c: Launching 'BackGround'<br>
May 24 20:13:48 DEBUG[26803] channel.c: Set channel
SIP/XXX.XXX.XXX.XXX-b7b03730 to<br>
write format slin<br>
May 24 20:13:48 DEBUG[26803] rtp.c: Ooh, format changed from unknown to
ulaw<br>
May 24 20:13:48 DEBUG[26803] channel.c: Scheduling timer at 160 sample
intervals<br>
May 24 20:13:49 DEBUG[26803] rtp.c: Got RTCP report of 132 bytes<br>
May 24 20:13:52 DEBUG[26803] rtp.c: Got RTCP report of 132 bytes<br>
May 24 20:13:53 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:13:58 DEBUG[26803] rtp.c: Got RTCP report of 132 bytes<br>
May 24 20:14:00 DEBUG[26803] channel.c: Scheduling timer at 58 sample
intervals<br>
May 24 20:14:00 DEBUG[26803] channel.c: Scheduling timer at 0 sample
intervals<br>
May 24 20:14:00 DEBUG[26803] channel.c: Scheduling timer at 0 sample
intervals<br>
May 24 20:14:00 DEBUG[26803] channel.c: Set channel
SIP/XXX.XXX.XXX.XXX-b7b03730 to<br>
write format ulaw<br>
May 24 20:14:00 DEBUG[26803] res_config_mysql.c: MySQL RealTime:
Everything is f<br>
ine.<br>
May 24 20:14:00 DEBUG[26803] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: S<br>
ELECT * FROM extensions WHERE exten = 's' AND context = 'ext-local' AND
priority<br>
= '8'<br>
May 24 20:14:00 DEBUG[26803] res_config_mysql.c: MySQL RealTime:
Everything is f<br>
ine.<br>
May 24 20:14:00 DEBUG[26803] res_config_mysql.c: MySQL RealTime:
Retrieve SQL: S<br>
ELECT * FROM extensions WHERE exten LIKE '\\_%' AND context =
'ext-local' AND pr<br>
iority = '8' ORDER BY exten<br>
<b>May 24 20:14:00 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Got RTCP report of 132 bytes<br>
May 24 20:14:01 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:02 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:02 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:02 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:03 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:03 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:03 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:04 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:04 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX<br>
May 24 20:14:04 DEBUG[26803] rtp.c: Sending dtmf: 49 (1), at
XXX.XXX.XXX.XXX</b><br>
May 24 20:14:07 DEBUG[26803] rtp.c: Got RTCP report of 108 bytes<br>
May 24 20:14:09 DEBUG[26803] rtp.c: Got RTCP report of 44 bytes<br>
May 24 20:14:09 DEBUG[26583] chan_sip.c: = Found Their Call ID:
9CB80474-98311DC<br>
-86A1C9BE-38B97399@XXX.XXX.XXX.XXX Their Tag E3F05090-621 Our tag:
as3becafbb<br>
May 24 20:14:09 DEBUG[26583] chan_sip.c: **** Received BYE (8) -
Command in SIP<br>
BYE<br>
May 24 20:14:09 DEBUG[26583] chan_sip.c: Received bye, issuing owner
hangup<br>
.May 24 20:14:09 DEBUG[26803] pbx.c: Launching 'Hangup'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Spawn extension (ivr-2,h,1) exited
non-zero<br>
on 'SIP/XXX.XXX.XXX.XXX-b7b03730'<br>
May 24 20:14:09 DEBUG[26803] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR recor<br>
d.<br>
May 24 20:14:09 DEBUG[26803] cdr_addon_mysql.c: cdr_mysql: SQL command
as follow<br>
s: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,la<br>
stdata,duration,billsec,disposition,amaflags,accountcode) VALUES
('2007-05-24 20<br>
:13:47','6056911122','6056911122','s','ivr-2',
'SIP/XXX.XXX.XXX.XXX-b7b03730','','Ha<br>
ngup','',22,22,'ANSWERED',3,'')<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '6056911122'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '6056911122'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is 's'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is 'ivr-2'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is
'SIP/XXX.XXX.XXX.XXX-b7b03730<br>
'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '(null)'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is 'Hangup'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '(null)'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '2007-05-24
20:13:47'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '2007-05-24
20:13:47'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '2007-05-24
20:14:09'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '22'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '22'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is 'ANSWERED'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is 'DOCUMENTATION'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '(null)'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '1180062827.5'<br>
May 24 20:14:09 DEBUG[26803] pbx.c: Function result is '(null)'<br>
May 24 20:14:09 DEBUG[26803] channel.c: Hanging up channel
'SIP/XXX.XXX.XXX.XXX-b7b0<br>
3730'<br>
May 24 20:14:09 DEBUG[26803] chan_sip.c: Hangup call
SIP/XXX.XXX.XXX.XXX-b7b03730, S<br>
IP callid <a class="moz-txt-link-abbreviated" href="mailto:9CB80474-98311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX">9CB80474-98311DC-86A1C9BE-38B97399@XXX.XXX.XXX.XXX</a>)<br>
May 24 20:14:09 DEBUG[26803] chan_sip.c: update_call_counter() -
decrement call<br>
limit counter<br>
May 24 20:14:09 DEBUG[26803] chan_sip.c: Updating call counter for
incoming call<br>
May 24 20:14:09 DEBUG[26574] chan_sip.c: Checking device state for peer
XXX.XXX.XXXX.XXX<br>
May 24 20:14:09 DEBUG[26574] devicestate.c: Changing state for
SIP/XXX.XXX.XXX.XXX -<br>
state 1 (Not in use)<br>
May 24 20:14:09 DEBUG[26809] app_queue.c: Device 'SIP/XXX.XXX.XXX.XXX'
changed to st<br>
ate '1' (Not in use) but we don't care because they're not a member of
any queue<br>
<br>
<br>
<br>
</body>
</html>