Zachary Kotlarek
2007-Apr-03 17:08 UTC
[asterisk-users] DTMF via IAX ignored after a few seconds
I'm new to this list, and I apologize if this is an already answered
question, but my Google-fu was not strong enough to find the answer if
it was.
I'm having a problem with DTMF on incoming IAX calls. For the first few
seconds of the call (between maybe 1 and 15, it varies from call to
call) everything works fine. After that I continue get DTMF_E messages
from the remote IAX server and continue to send back ACKs, but the tones
stop being processed.
Everything seems to work fine from my internal SIP phones as well as on
inbound calls if I switch inbound routing to SIP. I can make SIP work if
I need to, but I'd like to use IAX for a number of reasons, and at the
very least I'd like to understand the problem before I give up and switch.
Here's an excerpt from my console log showing the working and
non-working DTMF_E messages, which look identical to me. The complete
log for the call follows for context. If there's some other bit of
logging I could turn on that might show me what happens to the tones
after they're acknowledged I'd be glad to know.
Zach
#==================================================================
-- Goto (cynic-closed,s,1)
-- Executing [s@cynic-closed:1]
BackGround("IAX2/vitel-inbound-1",
"normalized/technical-support&normalized/is-curntly-unavail") in
new stack
-- <IAX2/vitel-inbound-1> Playing
'normalized/technical-support'
(language 'en')
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF_E Subclass: 4
Timestamp: 05403ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK
Timestamp: 05403ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: DTMF_E Subclass: 1
Timestamp: 05623ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX Subclass: ACK
Timestamp: 05623ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: DTMF_E Subclass: 1
Timestamp: 05783ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX Subclass: ACK
Timestamp: 05783ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
#==================================================================The tones for
411 above work fine and call is routed to the directory app
== CDR updated on IAX2/vitel-inbound-1
-- Executing [411@cynic-closed:1]
Directory("IAX2/vitel-inbound-1",
"default|cynic-main") in new stack
== Parsing '/etc/asterisk/voicemail.conf': Found
-- <IAX2/vitel-inbound-1> Playing 'dir-intro' (language
'en')
Timestamp: 10027ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 006 Type: DTMF_E Subclass: 8
Timestamp: 11683ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 009 Type: IAX Subclass: ACK
Timestamp: 11683ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 006 Type: DTMF_E Subclass: 7
Timestamp: 11963ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 010 Type: IAX Subclass: ACK
Timestamp: 11963ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 006 Type: DTMF_E Subclass: 2
Timestamp: 12263ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 011 Type: IAX Subclass: ACK
Timestamp: 12263ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
-- <IAX2/vitel-inbound-1> Playing 'dir-nomatch' (language
'en')
#==================================================================DTMF starts
to fail somewhere after 8 and before 2. The playback was
interrupted when I pressed 8, but 872 should match, so it didn't get all
the way to 2. All further DTMF in the call was likewise ignored and I
was unable to even interrupt playback with further key presses.
#==================================================================#==================================================================#
Complete call
#==================================================================#==================================================================
spaceheater*CLI> iax2 set debug
IAX2 Debugging Enabled
Really destroying SIP dialog
'06e0ca31050c087136d88dc53b5f6b16@172.23.1.2' Method: NOTIFY
Really destroying SIP dialog
'78ef0c7201a4be132eec112b633aa83d@172.23.1.2' Method: OPTIONS
Really destroying SIP dialog
'384bda743e0b28f40c9519275ee86ffd@172.23.1.2' Method: OPTIONS
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00013ms SCall: 00023 DCall: 00000 [64.2.142.31:4569]
VERSION : 2
CALLED NUMBER : XXXXXXXXXX
CODEC_PREFS : (gsm|ulaw|speex|ilbc|alaw|g729)
CALLING NUMBER : XXXXXXXXXX
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : XXXXXXXXXX
LANGUAGE : en
USERNAME : inbound
FORMAT : 4
CAPABILITY : 65535
ADSICPE : 2
DATE TIME : 2007-04-03 17:37:06
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass:
AUTHREQ
Timestamp: 00018ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
AUTHMETHODS : 3
CHALLENGE : 71596033
USERNAME : inbound
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass:
AUTHREP
Timestamp: 00092ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
MD5 RESULT : 89ec600c9d101a3619ac686cd22aabd7
-- Accepting AUTHENTICATED call from 64.2.142.31:
> requested format = ulaw,
> requested prefs = (gsm|ulaw|speex|ilbc|alaw|g729),
> actual format = gsm,
> host prefs = (),
> priority = caller
-- Executing [XXXXXXXXXX@inbound:1] Goto("IAX2/inbound-1",
"cynic-main|s|1") in new stack
-- Goto (cynic-main,s,1)
-- Executing [s@cynic-main:1] Answer("IAX2/inbound-1",
"") in new stack
-- Executing [s@cynic-main:2] Set("IAX2/inbound-1",
"TIMEOUT(digit)=5") in new stack
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass:
ACCEPT
-- Digit timeout set to 5
Timestamp: 00100ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
-- Executing [s@cynic-main:3] Set("IAX2/inbound-1",
"TIMEOUT(response)=5") in new stack
-- Response timeout set to 5
FORMAT : 2
-- Executing [s@cynic-main:4] Wait("IAX2/inbound-1",
"1") in new stack
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass:
ANSWER
Timestamp: 00103ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00100ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK
Timestamp: 00103ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: VOICE Subclass: 2
Timestamp: 00440ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX Subclass: ACK
Timestamp: 00440ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Really destroying SIP dialog
'24f5667d24acbb871f82d4ce64cd1bda@172.23.1.2' Method: NOTIFY
-- Executing [s@cynic-main:5] BackGround("IAX2/inbound-1",
"/etc/asterisk/sounds/intro") in new stack
-- <IAX2/inbound-1> Playing '/etc/asterisk/sounds/intro'
(language
'en')
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: VOICE Subclass: 2
Timestamp: 01120ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX Subclass: ACK
Timestamp: 01120ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
-- Executing [s@cynic-main:6] Goto("IAX2/inbound-1",
"cynic-menu|s|1") in new stack
-- Goto (cynic-menu,s,1)
-- Executing [s@cynic-menu:1] BackGround("IAX2/inbound-1",
"silence/1") in new stack
-- <IAX2/inbound-1> Playing 'silence/1' (language
'en')
-- Executing [s@cynic-menu:2] GotoIfTime("IAX2/inbound-1",
"18:00-06:59|mon-fri|*|*?cynic-closed|s|1") in new stack
-- Goto (cynic-closed,s,1)
-- Executing [s@cynic-closed:1] BackGround("IAX2/inbound-1",
"normalized/technical-support&normalized/is-curntly-unavail") in
new stack
-- <IAX2/inbound-1> Playing 'normalized/technical-support'
(language 'en')
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF_E Subclass: 4
Timestamp: 05403ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK
Timestamp: 05403ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: DTMF_E Subclass: 1
Timestamp: 05623ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX Subclass: ACK
Timestamp: 05623ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: DTMF_E Subclass: 1
Timestamp: 05783ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 006 Type: IAX Subclass: ACK
Timestamp: 05783ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
== CDR updated on IAX2/inbound-1
-- Executing [411@cynic-closed:1] Directory("IAX2/inbound-1",
"default|cynic-main") in new stack
== Parsing '/etc/asterisk/voicemail.conf': Found
-- <IAX2/inbound-1> Playing 'dir-intro' (language
'en')
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 004 Type: IAX Subclass: LAGRQ
Timestamp: 10011ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 007 Type: IAX Subclass: LAGRP
Timestamp: 10011ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 007 Type: IAX Subclass: LAGRQ
Timestamp: 10027ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 005 Type: IAX Subclass: ACK
Timestamp: 10011ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 006 Type: IAX Subclass: LAGRP
Timestamp: 10027ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 008 Type: IAX Subclass: ACK
Timestamp: 10027ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 006 Type: DTMF_E Subclass: 8
Timestamp: 11683ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 009 Type: IAX Subclass: ACK
Timestamp: 11683ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 006 Type: DTMF_E Subclass: 7
Timestamp: 11963ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 010 Type: IAX Subclass: ACK
Timestamp: 11963ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 006 Type: DTMF_E Subclass: 2
Timestamp: 12263ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 011 Type: IAX Subclass: ACK
Timestamp: 12263ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
-- <IAX2/inbound-1> Playing 'dir-nomatch' (language
'en')
-- <IAX2/inbound-1> Playing 'dir-intro' (language
'en')
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 006 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 012 Type: IAX Subclass: PONG
Timestamp: 20010ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 006 Type: IAX Subclass: LAGRQ
RR_JITTER : 0
Timestamp: 20013ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
RR_LOSS : 0
RR_PKTS : 1
RR_DELAY : 40
RR_DROPPED : 0
RR_OUTOFORDER : 0
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 013 Type: IAX Subclass: LAGRP
Timestamp: 20013ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 013 Type: IAX Subclass: LAGRQ
Timestamp: 20041ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 013 Type: IAX Subclass: PING
Timestamp: 20044ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 007 Type: IAX Subclass: ACK
Timestamp: 20010ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 008 Type: IAX Subclass: ACK
Timestamp: 20013ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 009 Type: IAX Subclass: LAGRP
Timestamp: 20041ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 014 Type: IAX Subclass: ACK
Timestamp: 20041ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 010 Type: IAX Subclass: PONG
Timestamp: 20044ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
RR_JITTER : 0
RR_LOSS : 0
RR_PKTS : 1
RR_DELAY : 40
RR_DROPPED : 0
RR_OUTOFORDER : 0
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 015 Type: IAX Subclass: ACK
Timestamp: 20044ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 010 Type: DTMF_E Subclass: 8
Timestamp: 20143ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 016 Type: IAX Subclass: ACK
Timestamp: 20143ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 016 ISeqno: 010 Type: DTMF_E Subclass: 7
Timestamp: 20403ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 017 Type: IAX Subclass: ACK
Timestamp: 20403ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 010 Type: DTMF_E Subclass: 2
Timestamp: 20976ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 018 Type: IAX Subclass: ACK
Timestamp: 20976ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
Really destroying SIP dialog
'330138bb49a22d7039b0530134f5c870@172.23.1.2' Method: NOTIFY
Rx-Frame Retry[ No] -- OSeqno: 018 ISeqno: 010 Type: IAX Subclass:
HANGUP
Timestamp: 28862ms SCall: 00023 DCall: 00001 [64.2.142.31:4569]
CAUSE CODE : 16
Tx-Frame Retry[-01] -- OSeqno: 010 ISeqno: 019 Type: IAX Subclass: ACK
Timestamp: 28862ms SCall: 00001 DCall: 00023 [64.2.142.31:4569]
== Spawn extension (cynic-closed, 411, 1) exited non-zero on
'IAX2/inbound-1'
-- Hungup 'IAX2/inbound-1'
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass:
REGREQ
Timestamp: 00005ms SCall: 00002 DCall: 00000 [64.2.142.31:4569]
USERNAME : profplump
REFRESH : 60
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass:
REGREQ
Timestamp: 00005ms SCall: 00006 DCall: 00000 [64.2.142.31:4569]
USERNAME : cynicbytrade
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass:
REGAUTH
Timestamp: 00007ms SCall: 00003 DCall: 00002 [64.2.142.31:4569]
AUTHMETHODS : 3
CHALLENGE : 204017331
USERNAME : profplump
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass:
REGREQ
Timestamp: 00092ms SCall: 00002 DCall: 00003 [64.2.142.31:4569]
USERNAME : profplump
REFRESH : 60
MD5 RESULT : 6e80df0f729a8d4a79cf2b67418d2f4c
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass:
REGAUTH
Timestamp: 00006ms SCall: 00032 DCall: 00006 [64.2.142.31:4569]
AUTHMETHODS : 3
CHALLENGE : 932866663
USERNAME : cynicbytrade
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass:
REGREQ
Timestamp: 00094ms SCall: 00006 DCall: 00032 [64.2.142.31:4569]
USERNAME : cynicbytrade
REFRESH : 60
MD5 RESULT : d3b5dd93dada458e5a8b582744f4e6ee
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass:
REGACK
Timestamp: 00088ms SCall: 00003 DCall: 00002 [64.2.142.31:4569]
USERNAME : profplump
DATE TIME : 2007-04-03 17:37:36
REFRESH : 60
APPARENT ADDRES : IPV4 XXXXXXXXXX:4569
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00088ms SCall: 00002 DCall: 00003 [64.2.142.31:4569]
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass:
REGACK
Timestamp: 00089ms SCall: 00032 DCall: 00006 [64.2.142.31:4569]
USERNAME : cynicbytrade
DATE TIME : 2007-04-03 17:37:36
REFRESH : 60
APPARENT ADDRES : IPV4 XXXXXXXXXX:4569
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00089ms SCall: 00006 DCall: 00032 [64.2.142.31:4569]
Really destroying SIP dialog
'4e95774e5077c0582078f08073853d39@172.23.1.2' Method: NOTIFY
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/x-pkcs7-signature
Size: 3035 bytes
Desc: S/MIME Cryptographic Signature
Url :
http://lists.digium.com/pipermail/asterisk-users/attachments/20070403/9c79f1e2/smime-0001.bin
Possibly Parallel Threads
Wisdom of the Ancients
