Florian Hackenberger
2008-Jul-07 12:48 UTC
[asterisk-users] DTMF on iax channel is not interpreted by asterisk
Hi!
I'm using asterisk 1.4.17 with twinkle and a custom phone based on
iaxclient 2.0.2 and I'm struggling a bit with DTMF and features.conf.
While the twinkle client is able to initiate an attended transfer using
*2 (as configured in features.conf), the iax client is not. I can see
the DTMF messages showing up on the asterisk console, but asterisk does
not invoke the features interpreter (ast_feature_interpret is not
called). Below is a snippet from the asterisk console log with
debugging enabled. The first part (before the two === lines) is the iax
client trying to do a transfer and the seconds part is the SIP client
(twinkle) initiating a transfer. Any ideas why asterisk ignored the
DTMF coming from the iax client? I'm passing t and T as options to the
Dial application BTW. And it does not matter which user is calling, the
result is always the same.
Cheers,
Florian
hacki-mobile*CLI>
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 012 Type: DTMF_E Subclass: *
Timestamp: 27464ms SCall: 08434 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:41:11] DEBUG[1261]: chan_iax2.c:7016 socket_process: Received
packet 8, (1, 42)
Tx-Frame Retry[-01] -- OSeqno: 012 ISeqno: 009 Type: IAX Subclass:
ACK
Timestamp: 27464ms SCall: 00002 DCall: 08434 [127.0.0.1:40310]
[Jul 7 14:41:11] DEBUG[1261]: chan_iax2.c:8273 socket_process: For
call=2, set last=27464
[Jul 7 14:41:11] DTMF[9852]: channel.c:2400 __ast_read: DTMF end '*'
received on IAX2/6001-2, duration 0 ms
[Jul 7 14:41:11] DTMF[9852]: channel.c:2436 __ast_read: DTMF begin
emulation of '*' with duration 100 queued on IAX2/6001-2
[Jul 7 14:41:11] DEBUG[9852]: channel.c:4163 ast_generic_bridge: Got
DTMF begin on channel (IAX2/6001-2)
[Jul 7 14:41:11] DEBUG[9852]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 012 Type: DTMF_E Subclass: 2
Timestamp: 27467ms SCall: 08434 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:41:11] DEBUG[1268]: chan_iax2.c:7016 socket_process: Received
packet 9, (1, 50)
Tx-Frame Retry[-01] -- OSeqno: 012 ISeqno: 010 Type: IAX Subclass:
ACK
Timestamp: 27467ms SCall: 00002 DCall: 08434 [127.0.0.1:40310]
[Jul 7 14:41:11] DEBUG[1268]: chan_iax2.c:8273 socket_process: For
call=2, set last=27467
[Jul 7 14:41:11] DTMF[9852]: channel.c:2400 __ast_read: DTMF end '2'
received on IAX2/6001-2, duration 0 ms
[Jul 7 14:41:11] DTMF[9852]: channel.c:2406 __ast_read: DTMF end '2'
put into dtmf queue on IAX2/6001-2
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 010 Type: IAX Subclass:
LAGRQ
Timestamp: 30014ms SCall: 00002 DCall: 08434 [127.0.0.1:40310]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 013 Type: IAX Subclass:
ACK
Timestamp: 30014ms SCall: 08434 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:41:13] DEBUG[1266]: chan_iax2.c:7016 socket_process: Received
packet 10, (6, 4)
[Jul 7 14:41:13] DEBUG[1266]: chan_iax2.c:7123 socket_process:
Cancelling transmission of packet 12
[Jul 7 14:41:13] DEBUG[1266]: chan_iax2.c:7243 socket_process: IAX
subclass 4 received
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 013 Type: IAX Subclass:
LAGRP
Timestamp: 30014ms SCall: 08434 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:41:14] DEBUG[1263]: chan_iax2.c:7016 socket_process: Received
packet 10, (6, 12)
[Jul 7 14:41:14] DEBUG[1263]: chan_iax2.c:7243 socket_process: IAX
subclass 12 received
[Jul 7 14:41:14] DEBUG[1263]: chan_iax2.c:7747 socket_process: Peer
127.0.0.1 lag measured as 164ms
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 011 Type: IAX Subclass:
ACK
Timestamp: 30014ms SCall: 00002 DCall: 08434 [127.0.0.1:40310]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 013 Type: IAX Subclass:
HANGUP
Timestamp: 30584ms SCall: 08434 DCall: 00002 [127.0.0.1:40310]
CAUSE : Dumped Call
[Jul 7 14:41:14] DEBUG[1264]: chan_iax2.c:7016 socket_process: Received
packet 11, (6, 5)
[Jul 7 14:41:14] DEBUG[1264]: chan_iax2.c:7243 socket_process: IAX
subclass 5 received
[Jul 7 14:41:14] DEBUG[1264]: chan_iax2.c:7252 socket_process: For
call=2, set last=30584
[Jul 7 14:41:14] DEBUG[1264]: chan_iax2.c:7543 socket_process:
Immediately destroying 2, having received hangup
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 012 Type: IAX Subclass:
ACK
==============================================================================================
hacki-mobile*CLI>
[Jul 7 14:42:54] DEBUG[9968]: rtp.c:879 ast_rtcp_read: Got RTCP report
of 108 bytes
[Jul 7 14:42:54] DEBUG[9968]: rtp.c:626 send_dtmf: Sending dtmf: 42
(*), at 10.241.85.100
[Jul 7 14:42:54] DTMF[9968]: channel.c:2463 __ast_read: DTMF begin '*'
received on SIP/6002-08383a78
[Jul 7 14:42:54] DTMF[9968]: channel.c:2473 __ast_read: DTMF begin
passthrough '*' on SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4163 ast_generic_bridge: Got
DTMF begin on channel (SIP/6002-08383a78)
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: rtp.c:626 send_dtmf: Sending dtmf: 42
(*), at 10.241.85.100
[Jul 7 14:42:54] DTMF[9968]: channel.c:2400 __ast_read: DTMF end '*'
received on SIP/6002-08383a78, duration 100 ms
[Jul 7 14:42:54] DTMF[9968]: channel.c:2441 __ast_read: DTMF end
accepted with begin '*' on SIP/6002-08383a78
[Jul 7 14:42:54] DTMF[9968]: channel.c:2457 __ast_read: DTMF end
passthrough '*' on SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4163 ast_generic_bridge: Got
DTMF end on channel (SIP/6002-08383a78)
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: res_features.c:1144
ast_feature_interpret: Feature interpret: chan=IAX2/6001-2,
peer=SIP/6002-08383a78, sense=2, features=2 dynamic=(null), code=*
[Jul 7 14:42:54] DEBUG[9968]: res_features.c:1638 ast_bridge_call: Set
time limit to 500
[Jul 7 14:42:54] DEBUG[9968]: rtp.c:626 send_dtmf: Sending dtmf: 48
(0), at 10.241.85.100
[Jul 7 14:42:54] DTMF[9968]: channel.c:2463 __ast_read: DTMF begin '0'
received on SIP/6002-08383a78
[Jul 7 14:42:54] DTMF[9968]: channel.c:2473 __ast_read: DTMF begin
passthrough '0' on SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4163 ast_generic_bridge: Got
DTMF begin on channel (SIP/6002-08383a78)
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: rtp.c:626 send_dtmf: Sending dtmf: 48
(0), at 10.241.85.100
[Jul 7 14:42:54] DTMF[9968]: channel.c:2400 __ast_read: DTMF end '0'
received on SIP/6002-08383a78, duration 100 ms
[Jul 7 14:42:54] DTMF[9968]: channel.c:2441 __ast_read: DTMF end
accepted with begin '0' on SIP/6002-08383a78
[Jul 7 14:42:54] DTMF[9968]: channel.c:2457 __ast_read: DTMF end
passthrough '0' on SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4163 ast_generic_bridge: Got
DTMF end on channel (SIP/6002-08383a78)
[Jul 7 14:42:54] DEBUG[9968]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
[Jul 7 14:42:54] DEBUG[9968]: res_features.c:1144
ast_feature_interpret: Feature interpret: chan=IAX2/6001-2,
peer=SIP/6002-08383a78, sense=2, features=2 dynamic=(null), code=*0
Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 008 Type: DTMF_B Subclass: *
Timestamp: 24153ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Tx-Frame Retry[001] -- OSeqno: 012 ISeqno: 008 Type: DTMF_B Subclass: *
Timestamp: 24153ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Tx-Frame Retry[000] -- OSeqno: 013 ISeqno: 008 Type: DTMF_E Subclass: *
Timestamp: 24156ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 013 Type: IAX Subclass:
ACK
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 014 Type: IAX Subclass:
ACK
Timestamp: 24153ms SCall: 08437 DCall: 00002 [127.0.0.1:40310]
Timestamp: 24156ms SCall: 08437 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:42:54] DEBUG[1262]: chan_iax2.c:7016 socket_process: Received
packet 8, (6, 4)
[Jul 7 14:42:54] DEBUG[1262]: chan_iax2.c:7123 socket_process:
Cancelling transmission of packet 12
[Jul 7 14:42:54] DEBUG[1262]: chan_iax2.c:7243 socket_process: IAX
subclass 4 received
[Jul 7 14:42:54] DEBUG[1265]: chan_iax2.c:7016 socket_process: Received
packet 8, (6, 4)
[Jul 7 14:42:54] DEBUG[1265]: chan_iax2.c:7123 socket_process:
Cancelling transmission of packet 13
[Jul 7 14:42:54] DEBUG[1265]: chan_iax2.c:7243 socket_process: IAX
subclass 4 received
Tx-Frame Retry[000] -- OSeqno: 014 ISeqno: 008 Type: DTMF_B Subclass: 0
Timestamp: 24353ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Tx-Frame Retry[001] -- OSeqno: 014 ISeqno: 008 Type: DTMF_B Subclass: 0
Timestamp: 24353ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Tx-Frame Retry[000] -- OSeqno: 015 ISeqno: 008 Type: DTMF_E Subclass: 0
Timestamp: 24356ms SCall: 00002 DCall: 08437 [127.0.0.1:40310]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 015 Type: IAX Subclass:
ACK
Timestamp: 24353ms SCall: 08437 DCall: 00002 [127.0.0.1:40310]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 016 Type: IAX Subclass:
ACK
Timestamp: 24356ms SCall: 08437 DCall: 00002 [127.0.0.1:40310]
[Jul 7 14:42:54] DEBUG[1259]: chan_iax2.c:7016 socket_process: Received
packet 8, (6, 4)
[Jul 7 14:42:54] DEBUG[1259]: chan_iax2.c:7123 socket_process:
Cancelling transmission of packet 14
[Jul 7 14:42:54] DEBUG[1259]: chan_iax2.c:7243 socket_process: IAX
subclass 4 received
[Jul 7 14:42:54] DEBUG[1266]: chan_iax2.c:7016 socket_process: Received
packet 8, (6, 4)
[Jul 7 14:42:54] DEBUG[1266]: chan_iax2.c:7123 socket_process:
Cancelling transmission of packet 15
[Jul 7 14:42:54] DEBUG[1266]: chan_iax2.c:7243 socket_process: IAX
subclass 4 received
[Jul 7 14:42:56] DEBUG[9968]: channel.c:4117 ast_generic_bridge: Didn't
get a frame from channel: SIP/6002-08383a78
[Jul 7 14:42:56] DEBUG[9968]: channel.c:4446 ast_channel_bridge: Bridge
stops bridging channels IAX2/6001-2 and SIP/6002-08383a78
[Jul 7 14:42:56] DEBUG[9968]: channel.c:1808 ast_hangup: Hanging up
channel 'SIP/6002-08383a78'
[Jul 7 14:42:56] DEBUG[9968]: chan_sip.c:3487 sip_hangup: Hangup call
SIP/6002-08383a78, SIP callid
3e50155c1cd33b4459bd631256f65fe1 at 10.241.85.96)
[Jul 7 14:42:56] DEBUG[9968]: rtp.c:1496 ast_rtp_early_bridge:
Channel 'IAX2/6001-2' has no RTP, not doing anything
[Jul 7 14:42:56] DEBUG[9968]: app_dial.c:1759 dial_exec_full: Exiting
with DIALSTATUS=ANSWER.
[Jul 7 14:42:56] DEBUG[9968]: pbx.c:1680
pbx_substitute_variables_helper_full: Function result is '1'
-- Executing GotoIf("IAX2/6001-2", "1?12")
-- Goto (agents,6002,12)
-- Executing NoOp("IAX2/6001-2", "Agent Dial End: 6002")
== Auto fallthrough, channel 'IAX2/6001-2' status is 'ANSWER'
[Jul 7 14:42:56] DEBUG[9968]: channel.c:1589 ast_softhangup_nolock:
Soft-Hanging up channel 'IAX2/6001-2'
-- Executing NoOp("IAX2/6001-2", "Deleting IGNOREVOICEMAIL
from
DB...")
[Jul 7 14:42:56] DEBUG[9968]: pbx.c:1680
pbx_substitute_variables_helper_full: Function result is '2'
-- Executing NoOp("IAX2/6001-2", "2")
[Jul 7 14:42:56] DEBUG[9968]: channel.c:1808 ast_hangup: Hanging up
channel 'IAX2/6001-2'
[Jul 7 14:42:56] DEBUG[9968]: chan_iax2.c:3246 iax2_hangup: We're
hanging up IAX2/6001-2 with cause 16 now...
--
DI Florian Hackenberger
florian at hackenberger.at
www.hackenberger.at
Matt Riddell
2008-Jul-07 23:00 UTC
[asterisk-users] DTMF on iax channel is not interpreted by asterisk
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Florian Hackenberger wrote:> Hi! > > I'm using asterisk 1.4.17 with twinkle and a custom phone based on > iaxclient 2.0.2 and I'm struggling a bit with DTMF and features.conf.Maybe the feature digit timeout? - -- Kind Regards, Matt Riddell Director _______________________________________________ http://www.venturevoip.com (Great new VoIP end to end solution) http://www.venturevoip.com/news.php (Daily Asterisk News - html) http://www.venturevoip.com/newrssfeed.php (Daily Asterisk News - rss) -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.7 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFIcqAQDQNt8rg0Kp4RAgvmAJ4wT8iJVTZzt3xdvLUdryATwgr7dgCfRaVB +frz8oSBAhzOYInTCR+Zw8U=TbB7 -----END PGP SIGNATURE-----