[asterisk-bugs] [JIRA] (ASTERISK-21193) IAX/2 fails to destroy channel on max retransmits exceeded
Rusty Newton (JIRA)
noreply at issues.asterisk.org
Mon Mar 25 13:05:02 CDT 2013
[ https://issues.asterisk.org/jira/browse/ASTERISK-21193?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Rusty Newton updated ASTERISK-21193:
------------------------------------
Assignee: Jaco Kroon (was: Rusty Newton)
Status: Waiting for Feedback (was: Triage)
Jaco, going to let this one sit for another two weeks so you have time to gather the debug if possible.
> 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