[asterisk-users] DTMF on iax channel is not interpreted by asterisk

Florian Hackenberger f.hackenberger at chello.at
Mon Jul 7 07:48:15 CDT 2008


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



More information about the asterisk-users mailing list