[asterisk-bugs] [JIRA] (ASTERISK-21193) IAX/2 fails to destroy channel on max retransmits exceeded

Thu Feb 28 14:41:18 CST 2013

     [ https://issues.asterisk.org/jira/browse/ASTERISK-21193?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Richard Mudgett updated ASTERISK-21193:
---------------------------------------

    Description: 
Hi,

Every now and again an IAX/2 channel will get locked up, with the following being sent to the CLI and logs repeatedly:
{noformat}
[Feb 28 21:38:47] WARNING[23040]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17269334, seqno=249)
[Feb 28 21:38:57] WARNING[23045]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17279334, seqno=250)
[Feb 28 21:39:00] WARNING[23047]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 2, ts=17282693, seqno=251)
[Feb 28 21:39:07] WARNING[23039]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17289333, seqno=252)
{noformat}

Currently running iax2 show peer arctica shows the following:

{noformat}
morpheus*CLI> iax2 show peer arctica 

  * Name       : arctica
  Description  : 
  Secret       : <Set>
  Context      : uls-from-trunk
  Parking lot  : 
  Mailbox      : 
  Dynamic      : Yes
  Callnum limit: 1024
  Calltoken req: Yes
  Trunk        : Yes
  Encryption   : No
  Callerid     : "" <>
  Expire       : 3212988
  ACL          : No
  Addr->IP     : 105.236.192.85 Port 4569
  Defaddr->IP  : 0.0.0.0 Port 4569
  Username     : ulsvoip
  Codecs       : (gsm|g729)
  Codec Order  : (g729|gsm)
  Status       : OK (9 ms)
  Qualify      : every 60000ms when OK, every 10000ms when UNREACHABLE (sample smoothing Off)
{noformat}

The specific channel from core show channels concise:

{noformat}
IAX2/arctica-3307!uls-from-trunk!0761916763!9!Ring!Dial!Local/0799048876 at uls-place-call/n!0873514879!arctica!!2!17643!(None)!morpheus-1362063026.53899
{noformat}

Some logs from the channel creation (came in from remote peer, I did filter for the string arctica and then worked from there - there is a LOT of information in the logs around this, total log is about 270M atm):

{noformat}
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:1] NoCDR("IAX2/arctica-3307", "") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:2] Set("IAX2/arctica-3307", "_BLINDTRANSFER=") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:3] GotoIf("IAX2/arctica-3307", "0?godial") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:4] Set("IAX2/arctica-3307", "_reqip=105.236.192.85") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:5] Set("IAX2/arctica-3307", "_callref=") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:6] GotoIf("IAX2/arctica-3307", "1?godial") in new stack
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-from-trunk:9] Dial("IAX2/arctica-3307", "Local/0761916763 at uls-place-call/n") in new stack
[Feb 28 16:50:26] VERBOSE[2712][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-place-call:1] NoOp("Local/0761916763 at uls-place-call-0000377b;2", "Trunk call request from "" <0873514879> to 0761916763 (RDNIS=, BLINDTRANSFER=, realuser=arctica)") in new stack
[Feb 28 16:50:26] VERBOSE[2712][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-place-call:2] GotoIf("Local/0761916763 at uls-place-call-0000377b;2", "1?loaduser") in new stack
{noformat}

... more dialplan ... lot's of it ... and off to just before the max retransmits ...

{noformat}
[Feb 28 16:50:26] VERBOSE[2712][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-callprovider:19] Set("Local/0761916763 at uls-place-call-0000377b;2", "c=1") in new stack
[Feb 28 16:50:26] VERBOSE[2712][C-0000317a] pbx.c:     -- Executing [0761916763 at uls-callprovider:20] Dial("Local/0761916763 at uls-place-call-0000377b;2", "IAX2/uls-node-r2d2/prov*is*0761916763,,") in new stack
[Feb 28 16:50:26] VERBOSE[2712][C-0000317a] app_dial.c:     -- IAX2/uls-node-r2d2-17667 is making progress passing it to Local/0761916763 at uls-place-call-0000377b;2
[Feb 28 16:50:26] VERBOSE[2711][C-0000317a] app_dial.c:     -- Local/0761916763 at uls-place-call-0000377b;1 is making progress passing it to IAX2/arctica-3307
[Feb 28 16:50:31] VERBOSE[2723] chan_iax2.c:     -- Seeding 'arctica' at 105.236.192.85:4569 for 60
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Registered extension context 'dial-trunk-arctica'; registrar: pbx_config
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension '_X!' priority 1 to dial-trunk-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension '_X!' priority 2 to dial-trunk-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Registered extension context 'speeddial-tr-arctica'; registrar: pbx_config
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Including context 'speeddial-cl-ULS-A13' in context 'speeddial-tr-arctica'
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Registered extension context 'chanvars-arctica'; registrar: pbx_config
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 1 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 2 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 3 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 4 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 5 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 6 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 7 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 's' priority 8 to chanvars-arctica
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Registered extension context 'cli-arctica-client'; registrar: pbx_config
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Including context 'cli-arctica-global' in context 'cli-arctica-client'
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Registered extension context 'cli-arctica-global'; registrar: pbx_config
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension '0873534134' priority 1 to cli-arctica-global
[Feb 28 16:50:31] VERBOSE[2723] pbx.c:     -- Added extension 'arctica' priority 1 to uls-trunks
[Feb 28 16:50:33] WARNING[23039] channel.c: Exceptionally long voice queue length queuing to IAX2/arctica-3307
[Feb 28 16:50:33] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:34] WARNING[23037] channel.c: Exceptionally long voice queue length queuing to IAX2/arctica-3307
[Feb 28 16:50:34] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:35] WARNING[23039] channel.c: Exceptionally long voice queue length queuing to IAX2/arctica-3307
[Feb 28 16:50:35] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:36] WARNING[23041] channel.c: Exceptionally long voice queue length queuing to IAX2/arctica-3307
[Feb 28 16:50:36] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:36] VERBOSE[2712][C-0000317a] app_dial.c:     -- IAX2/uls-node-r2d2-17667 answered Local/0761916763 at uls-place-call-0000377b;2
[Feb 28 16:50:38] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:39] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:40] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:42] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:43] WARNING[2712][C-0000317a] channel.c: Exceptionally long voice queue length queuing to Local/0761916763 at uls-place-call-0000377b;1
[Feb 28 16:50:44] NOTICE[2712][C-0000317a] src/cdr_uls.C: cdr_uls: cdr entry: clid=0873514879,src=0873514879,dst=0761916763,dcontext=uls-callprovider,channel=Local/0761916763 at uls-place-call-0000377b;2,dstchannel=IAX2/uls-node-r2d2-17667,lastapp=Dial,lastdata=IAX2/uls-node-r2d2/prov*is*0761916763,,,start=2013-02-28 16:50:26,answer=2013-02-28 16:50:36,end=2013-02-28 16:50:44,duration=18,billsec=8,disposition=ANSWERED,amaflags=DOCUMENTATION,accountcode=arctica,uniqueid=morpheus-1362063026.53901,userfield=0873534134,dialed=0761916763,ulstype=normal,peerip=105.236.192.85,destnetwork=Vodacom (Pty) Ltd,calldesc=Vodacom (Pty) Ltd,circuit=quality,provider=is,cli=yes,dialed=0761916763,ulstype=normal,peerip=105.236.192.85
{noformat}

... This indicates that the call got hung up ...

{noformat}
[Feb 28 16:50:44] VERBOSE[2712][C-0000317a] pbx.c:   == Spawn extension (uls-callprovider, 0761916763, 20) exited non-zero on 'Local/0761916763 at uls-place-call-0000377b;2'
[Feb 28 16:51:18] WARNING[23044] chan_iax2.c: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=20015, seqno=6)
[Feb 28 16:51:19] WARNING[23045] chan_iax2.c: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 2, ts=21017, seqno=7)
{noformat}

and from here on this is all I see.

Looking at the code for some reason the channel never gets destroyed.  At the location where the message is output (channels/chan_iax2.c, lines 3550-3569) it would seem that as long as iaxs[callno]=>owner is not NULL that the channel will never get destroyed and we will infinitely keep retransmitting a HANGUP request - which is likely to be ignored by the remote end due to the callid not existing.

Looking at frame.h it would seem that type=6 => AST_FRAME_IAX, and subclass=2 and 11 represents AST_CONTROL_RING and AST_CONTROL_OPTION respectively.

The logs on the remote server (not under my direct control) shows the following for the same call (time is offset by about an hour):

{noformat}
[2013-02-28 15:58:20] VERBOSE[23968] pbx.c:     -- Executing [s at macro-dialout-trunk:20] Dial("SIP/100-000003ea", "IAX2/ulsvoip/0761916763,300,") in new stack
[2013-02-28 15:58:20] VERBOSE[23968] app_dial.c:     -- Called ulsvoip/0761916763
[2013-02-28 15:58:20] VERBOSE[23969] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/100-000003ea
[2013-02-28 15:58:20] VERBOSE[2996] chan_iax2.c:     -- Call accepted by 196.37.63.68 (format g729)
[2013-02-28 15:58:20] VERBOSE[2996] chan_iax2.c:     -- Format for call is g729
[2013-02-28 15:58:20] VERBOSE[23968] app_dial.c:     -- IAX2/ulsvoip-16511 is making progress passing it to SIP/100-000003ea
[2013-02-28 15:58:31] VERBOSE[23968] chan_iax2.c:     -- Hungup 'IAX2/ulsvoip-16511'
[2013-02-28 15:58:31] VERBOSE[23968] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/100-000003ea' in macro 'dialout-trunk'
[2013-02-28 15:58:31] VERBOSE[23968] pbx.c:   == Spawn extension (from-internal, 0761916763, 5) exited non-zero on 'SIP/100-000003ea'
[2013-02-28 15:58:31] VERBOSE[23968] pbx.c:     -- Executing [h at from-internal:1] Hangup("SIP/100-000003ea", "") in new stack
[2013-02-28 15:58:31] VERBOSE[23968] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/100-000003ea'
{noformat}

So I'm not sure what to make of this ...

  was:
Hi,

Every now and again an IAX/2 channel will get locked up, with the following being sent to the CLI and logs repeatedly:

[Feb 28 21:38:47] WARNING[23040]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17269334, seqno=249)
[Feb 28 21:38:57] WARNING[23045]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17279334, seqno=250)
[Feb 28 21:39:00] WARNING[23047]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 2, ts=17282693, seqno=251)
[Feb 28 21:39:07] WARNING[23039]: chan_iax2.c:3552 __attempt_transmit: Max retries exceeded to host 105.236.192.85 on IAX2/arctica-3307 (type = 6, subclass = 11, ts=17289333, seqno=252)