[asterisk-bugs] [JIRA] (ASTERISK-21193) IAX/2 fails to destroy channel on max retransmits exceeded
Rusty Newton (JIRA)
noreply at issues.asterisk.org
Wed Mar 6 15:52:01 CST 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
Status: Waiting for Feedback (was: Triage)
Sounds like a bug, but still need further information.
1.Is it only calls going through the "arctica" peer that get locked up?
1A. Does this peer handle only inbound, or both inbound and outbound calls? If so, do only one or the other lock up? That could lead us to a dialplan path that affects the issue.
2.It may not be possible considering you probably don't know which channel will lock up, but I should ask anyway - can you provide a PCAP of a complete call where its locked up, plus a comparison with a working call?
3.Can you provide the same log info, but along with the DEBUG message type?
4. Can you provide the same log information, but for a working call and attach to the issue?
5. can you provide the iax.conf configuration for the "arctica" peer? along with the [general] config?
> 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