[asterisk-bugs] [JIRA] (ASTERISK-21193) IAX/2 fails to destroy channel on max retransmits exceeded
Jaco Kroon (JIRA)
noreply at issues.asterisk.org
Wed Apr 10 08:52:01 CDT 2013
[ https://issues.asterisk.org/jira/browse/ASTERISK-21193?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=205139#comment-205139 ]
Jaco Kroon commented on ASTERISK-21193:
---------------------------------------
Rusty,
I'm not seeing this happen any more. And I hate that. I really do not like it if problems just go away. Don't get me wrong, I'm thankful that the problem is gone, but it means there is an underlying problem sitting in limbo somewhere just waiting to trigger and bite.
For now I cannot see how we can possibly troubleshoot this, so let's close. If I get more information I'll log a new issue.
> IAX/2 fails to destroy channel on max retransmits exceeded
> ----------------------------------------------------------
>
> Key: ASTERISK-21193
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-21193
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Channels/chan_iax2
> Affects Versions: 11.2.1
> Reporter: Jaco Kroon
> Assignee: Jaco Kroon
>
> 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 ...
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.asterisk.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the asterisk-bugs
mailing list