[Home]

Summary:ASTERISK-17598: IAX2 wont start ring back early media
Reporter:Rodrigo Graeff (delphus)Labels:
Date Opened:2011-03-24 04:49:58Date Closed:2017-12-19 07:00:13.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:1.4.40 Frequency of
Occurrence
Related
Issues:
is the original version of this clone:ASTERISK-18234 IAX2 wont start ring back
is duplicated byASTERISK-18235 IAX2 wont start ring back early media
Environment:Attachments:
Description:IAX2 channels wont start ring back early media at all.
I've called from IAX2 to SIP local extensions, it doesn't work. From IAX to IAX local extensions, it doesn't work. From IAX to another SIP/IAX via IAX trunk (different asterisk servers) and it doesn't work.
I've also fixed all possible codecs and it doesn't work. I've tried several IAX clients like zoiper, kiax, Loudhush... it doesn't matter. No ringback at all.

From SIP to IAX local extensions it work, via IAX trunk works as well.


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

iax2 debug info:
[Mar 24 09:48:00] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
[Mar 24 09:48:00]    Timestamp: 00011ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:00]    AUTHMETHODS     : 3
[Mar 24 09:48:00]    CHALLENGE       : 347635954
[Mar 24 09:48:00]    USERNAME        : 302
[Mar 24 09:48:00]
[Mar 24 09:48:00] Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
[Mar 24 09:48:00]    Timestamp: 00004ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:00]    MD5 RESULT      : 4c26b30752a2260ca7f9eaf056559fac
[Mar 24 09:48:00]
[Mar 24 09:48:00]     -- Accepting AUTHENTICATED call from 10.0.1.10:
      > requested format = alaw,
      > requested prefs = (),
      > actual format = alaw,
      > host prefs = (ilbc|alaw|g729|gsm|ulaw),
      > priority = mine
[Mar 24 09:48:00]     -- Executing [320@outgoing:1] NoOp("IAX2/302-13779", "LOCAL CALL from 302 TO 320") in new stack
[Mar 24 09:48:00]     -- Executing [320@outgoing:2] Set("IAX2/302-13779", "DIALED=320") in new stack
[Mar 24 09:48:00]     -- Executing [320@outgoing:3] Dial("IAX2/302-13779", "SIP/320|45|tTr") in new stack
[Mar 24 09:48:00]     -- Called 320
[Mar 24 09:48:00] Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
[Mar 24 09:48:00]    Timestamp: 00016ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:00]    FORMAT          : 8
[Mar 24 09:48:00]
[Mar 24 09:48:00] Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: RINGING
[Mar 24 09:48:00]    Timestamp: 00019ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:00] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK    
[Mar 24 09:48:00]    Timestamp: 00016ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:00] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK    
[Mar 24 09:48:00]    Timestamp: 00019ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:00]     -- SIP/320-00000023 is ringing
[Mar 24 09:48:00] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: VOICE   Subclass: 8
[Mar 24 09:48:00]    Timestamp: 00080ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:00] Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK    
[Mar 24 09:48:00]    Timestamp: 00080ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:02] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: PING  
[Mar 24 09:48:02]    Timestamp: 02007ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:02] Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: PONG  
[Mar 24 09:48:02]    Timestamp: 02007ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:02]    RR_JITTER       : 13
[Mar 24 09:48:02]    RR_LOSS         : 0
[Mar 24 09:48:02]    RR_PKTS         : 97
[Mar 24 09:48:02]    RR_DELAY        : 65
[Mar 24 09:48:02]    RR_DROPPED      : 0
[Mar 24 09:48:02]    RR_OUTOFORDER   : 0
[Mar 24 09:48:02]
[Mar 24 09:48:02] Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK    
[Mar 24 09:48:02]    Timestamp: 02007ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:05] Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: HANGUP
[Mar 24 09:48:05]    Timestamp: 05091ms  SCall: 17083  DCall: 13779 [10.0.1.10:55667]
[Mar 24 09:48:05]    CAUSE           : Dumped Call
[Mar 24 09:48:05]
[Mar 24 09:48:05] Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK    
[Mar 24 09:48:05]    Timestamp: 05091ms  SCall: 13779  DCall: 17083 [10.0.1.10:55667]
[Mar 24 09:48:05]   == Spawn extension (outgoing, 320, 3) exited non-zero on 'IAX2/302-13779'
[Mar 24 09:48:05]     -- Hungup 'IAX2/302-13779'

my iax.conf

[general]
;iaxcompact=yes
;nochecksum=yes
bandwidth=low
dtmfmode=auto
;dropcount=3
authdebug=yes
delayreject=no
;tos=lowdelay
trunktimestamps=yes
trunkfreq=60

;rtautoclear=yes
;rtcachefriends=yes

context=incoming

disallow=all
allow=g729
allow=gsm
allow=ilbc
allow=alaw
allow=ulaw

jitterbuffer=yes
forcejitterbuffer=yes
maxjitterbuffer=200
autokill=yes

encryption = yes
auth=md5
;forceencryption = yes
calltokenoptional=0.0.0.0/0.0.0.0

[302]
type=friend
secret=fxjfpgtb
qualify=yes
transfer=no
mailbox=302
host=dynamic
context=outgoing
callerid=302
requirecalltoken=no
allow=g729
allow=gsm
allow=ulaw

Comments:By: Rodrigo Graeff (delphus) 2011-03-24 05:00:43

Follows debug 9 of another call with no ringback at all.

[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: Allocating new SIP dialog for 386786072050774-376771130038040@10.0.1.26 - REGISTER (No RTP)
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: = Found Their Call ID: 386786072050774-376771130038040@10.0.1.26 Their Tag 4577742609 Our tag: as593efe9c
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Mar 24 09:58:08] DEBUG[22465] devicestate.c: Notification of state change to be queued on device/channel SIP/322
[Mar 24 09:58:08] DEBUG[22465] devicestate.c: No provider found, checking channel drivers for SIP - 322
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: Checking device state for peer 322
[Mar 24 09:58:08] DEBUG[22465] devicestate.c: Changing state for SIP/322 - state 1 (Not in use)
[Mar 24 09:58:08] DEBUG[22465] app_queue.c: Device 'SIP/322' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: = Found Their Call ID: 3f3eebaa780c6b68260b44d453cdd148@10.0.1.254 Their Tag  Our tag: as39142bd9
[Mar 24 09:58:08] DEBUG[22465] chan_sip.c: Stopping retransmission on '3f3eebaa780c6b68260b44d453cdd148@10.0.1.254' of Request 102: Match Found
[Mar 24 09:58:10] DEBUG[22465] chan_iax2.c: Determining if address 10.0.1.10 with username 302 requires calltoken validation.  Optional = 1  calltoken_required = 3
[Mar 24 09:58:10] DEBUG[22465] chan_iax2.c: ip callno count incremented to 7 for 10.0.1.10
[Mar 24 09:58:10] DEBUG[22465] pbx.c: Function result is '302'
[Mar 24 09:58:10] DEBUG[22465] pbx.c: Launching 'NoOp'
[Mar 24 09:58:10] DEBUG[22465] pbx.c: Function result is '320'
[Mar 24 09:58:10] DEBUG[22465] pbx.c: Launching 'Set'
[Mar 24 09:58:10] DEBUG[22465] pbx.c: Launching 'Dial'
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Setting NAT on RTP to On
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: *** Our native formats are 0x100 (g729)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: *** Our capabilities are 0x50e (gsm|ulaw|alaw|g729|ilbc)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: This channel will not be able to handle video.
[Mar 24 09:58:10] DEBUG[22465] rtp.c: Channel 'IAX2/302-14746' has no RTP, not doing anything
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable DIALEDTIME.
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable ANSWEREDTIME.
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable DIALEDPEERNAME.
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable DIALEDPEERNUMBER.
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable DIALSTATUS.
[Mar 24 09:58:10] DEBUG[22465] channel.c: Not copying variable DIALED.
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Outgoing Call for 320
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Updating call counter for outgoing call
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: ** Our capability: 0x50e (gsm|ulaw|alaw|g729|ilbc) Video flag: False
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: -- Done with adding codecs to SDP
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Done building SDP. Settling with this capability: 0x50e (gsm|ulaw|alaw|g729|ilbc)
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: = Found Their Call ID: 589675a02ca3744e551f27a932d754c0@10.0.1.254 Their Tag  Our tag: as4b84ee5c
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '589675a02ca3744e551f27a932d754c0@10.0.1.254' Request 102: Found
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: SIP response 100 to standard invite
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: = Found Their Call ID: 589675a02ca3744e551f27a932d754c0@10.0.1.254 Their Tag  Our tag: as4b84ee5c
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '589675a02ca3744e551f27a932d754c0@10.0.1.254' Request 102: Found
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: SIP response 180 to standard invite
[Mar 24 09:58:10] DEBUG[22465] devicestate.c: Notification of state change to be queued on device/channel SIP/320
[Mar 24 09:58:10] DEBUG[22465] devicestate.c: No provider found, checking channel drivers for SIP - 320
[Mar 24 09:58:10] DEBUG[22465] chan_sip.c: Checking device state for peer 320
[Mar 24 09:58:10] DEBUG[22465] devicestate.c: Changing state for SIP/320 - state 1 (Not in use)
[Mar 24 09:58:10] DEBUG[22465] app_queue.c: Device 'SIP/320' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 24 09:58:10] DEBUG[22465] chan_iax2.c: Ooh, voice format changed to 8
[Mar 24 09:58:10] DEBUG[22465] chan_iax2.c: ip callno count decremented to 6 for 10.0.1.10
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: = Found Their Call ID: 60e68a505656a7c06e728a820bb084a9@10.0.1.254 Their Tag  Our tag: as3712e423
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Stopping retransmission on '60e68a505656a7c06e728a820bb084a9@10.0.1.254' of Request 102: Match Found
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: Immediately destroying 14746, having received hangup
[Mar 24 09:58:13] DEBUG[22465] rtp.c: Channel 'IAX2/302-14746' has no RTP, not doing anything
[Mar 24 09:58:13] DEBUG[22465] channel.c: Hanging up channel 'SIP/320-00000025'
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Hangup call SIP/320-00000025, SIP callid 589675a02ca3744e551f27a932d754c0@10.0.1.254)
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Hanging up channel in state Ringing (not UP)
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '589675a02ca3744e551f27a932d754c0@10.0.1.254' Request 102: Found
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: Notification of state change to be queued on device/channel SIP/320
[Mar 24 09:58:13] DEBUG[22465] app_dial.c: Exiting with DIALSTATUS=CANCEL.
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: No provider found, checking channel drivers for SIP - 320
[Mar 24 09:58:13] DEBUG[22465] pbx.c: Spawn extension (outgoing,320,3) exited non-zero on 'IAX2/302-14746'
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Checking device state for peer 320
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: Changing state for SIP/320 - state 1 (Not in use)
[Mar 24 09:58:13] DEBUG[22465] channel.c: Soft-Hanging up channel 'IAX2/302-14746'
[Mar 24 09:58:13] DEBUG[22465] app_queue.c: Device 'SIP/320' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 24 09:58:13] DEBUG[22465] channel.c: Hanging up channel 'IAX2/302-14746'
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: We're hanging up IAX2/302-14746 now...
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: Really destroying IAX2/302-14746 now...
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: schedule decrement of callno used for 10.0.1.10 in 60 seconds
[Mar 24 09:58:13] DEBUG[22465] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Mar 24 09:58:13] DEBUG[22465] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2011-03-24 09:58:10','302','302','320','outgoing', 'IAX2/302-14746','SIP/320-00000025','Dial','SIP/320|45|tTr',3,0,'NO ANSWER',3,'','')
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: Notification of state change to be queued on device/channel IAX2/302
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: No provider found, checking channel drivers for IAX2 - 302
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: Checking device state for device 302
[Mar 24 09:58:13] DEBUG[22465] chan_iax2.c: iax2_devicestate: Found peer. What's device state of 302? addr=167837706, defaddr=0 maxms=2000, lastms=1
[Mar 24 09:58:13] DEBUG[22465] devicestate.c: Changing state for IAX2/302 - state 1 (Not in use)
[Mar 24 09:58:13] DEBUG[22465] app_queue.c: Device 'IAX2/302' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: = Found Their Call ID: 589675a02ca3744e551f27a932d754c0@10.0.1.254 Their Tag ee9acb701560a2f1i4 Our tag: as4b84ee5c
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Acked pending invite 102
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Stopping retransmission on '589675a02ca3744e551f27a932d754c0@10.0.1.254' of Request 102: Match Found
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: SIP response 487 to standard invite
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Updating call counter for outgoing call
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Setting SIP_ALREADYGONE on dialog 589675a02ca3744e551f27a932d754c0@10.0.1.254
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: = Found Their Call ID: 589675a02ca3744e551f27a932d754c0@10.0.1.254 Their Tag ee9acb701560a2f1i4 Our tag: as4b84ee5c
[Mar 24 09:58:13] DEBUG[22465] chan_sip.c: Stopping retransmission on '589675a02ca3744e551f27a932d754c0@10.0.1.254' of Request 102: Match Found
By: Joshua C. Colp (jcolp) 2017-12-19 07:00:13.990-0600

I'm suspending this issue as it is against a very old unsupported version of Asterisk and numerous changes have been made since. If this is still a problem you can comment and the issue will automatically reopen.