[Home]

Summary:ASTERISK-14346: ChanIsAvail is returning unavailable when the device is actually available
Reporter:rbosch (rbosch)Labels:
Date Opened:2009-06-20 09:50:07Date Closed:2011-06-07 14:08:17
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:We have a SIP device (snom 300) that is registered successfully with asterisk 1.4.25 (sip show peers shows the device). We are running freepbx and try to call the extension associated with the device and the call goes through. When we try to intercom, the call returns busy.

FreePBX uses the following dialplan for intercom. The ChanIsAvail is returning the channel isn't available when it clearly is (calls can be routed there and it is registered in sip show peers).  The sip.conf includes a qualify statement which shows the peer online with 40ms response time.

The problem does not impact ALL devices. Re-registering the device and/or rebooting it has no impact on the problem.

Over time the number of devices impacted increases.  Once a device is in this "state" then it will never get back to a correct state unless the system is completely rebooted.



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

Dialplan snippet:

[ext-intercom]
include => ext-intercom-custom
exten => _7.,1,Macro(user-callerid,)
exten => _7.,n,Set(dialnumber=${EXTEN:1})
exten => _7.,n,GotoIf($["${DB(AMPUSER/${AMPUSER}/intercom/block)}" = "blocked"]?end)
exten => _7.,n,GotoIf($["${DB(DND/${dialnumber})}" = "YES"]?end)
exten => _7.,n,GotoIf($["${DB(AMPUSER/${dialnumber}/intercom/${AMPUSER})}" = "allow" ]?allow)
exten => _7.,n,GotoIf($["${DB(AMPUSER/${dialnumber}/intercom/${AMPUSER})}" = "deny" ]?nointercom)
exten => _7.,n,GotoIf($["${DB(AMPUSER/${dialnumber}/intercom)}" = "disabled" ]?nointercom)
exten => _7.,n(allow),Set(DEVICES=${DB(AMPUSER/${dialnumber}/device)})
exten => _7.,n,GotoIf($["${DEVICES}" = "" ]?end)
exten => _7.,n,Set(LOOPCNT=${FIELDQTY(DEVICES,&)})
exten => _7.,n,GotoIf($[${LOOPCNT} > 1 ]?pagemode)
exten => _7.,n,Macro(autoanswer,${DEVICES})
exten => _7.,n(check),ChanIsAvail(${DIAL},sj)
exten => _7.,n,Dial(${DIAL},${DTIME},${DOPTIONS})
exten => _7.,n(end),Busy(20)

Log output from dialplan showing chanisavail returning not available:
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:7] Set("SIP/9242-b81327e0", "SIPURI=intercom=true") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: Set
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:8] Set("SIP/9242-b81327e0", "DOPTIONS=A(beep)") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: Set
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:9] Set("SIP/9242-b81327e0", "DTIME=5") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: Set
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:10] Set("SIP/9242-b81327e0", "ANSWERMACRO=") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: Set
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:11] ExecIf("SIP/9242-b81327e0", "0|Set|CALLINFO=Call-Info: <sip:broadworks.net>;answer-after=0") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: ExecIf
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:12] GotoIf("SIP/9242-b81327e0", "0?macro2") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: GotoIf
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:13] ExecIf("SIP/9242-b81327e0", "1|SipAddHeader|Alert-Info: Ring Answer") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: ExecIf
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Last app: SipAddHeader|Alert-Info: Ring Answer
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:14] ExecIf("SIP/9242-b81327e0", "1|SipAddHeader|Call-Info: <uri>;answer-after=0") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: ExecIf
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Last app: SipAddHeader|Call-Info: <uri>;answer-after=0
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [s@macro-autoanswer:15] ExecIf("SIP/9242-b81327e0", "1|Set|__SIP_URI_OPTIONS=intercom=true") in new stack
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Executed application: ExecIf
[Jun 18 12:32:28] DEBUG[21832] app_macro.c: Last app: Set|__SIP_URI_OPTIONS=intercom=true
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [7291@ext-intercom:13] ChanIsAvail("SIP/9242-b81327e0", "SIP/9291|sj") in new stack
[Jun 18 12:32:28] VERBOSE[21832] logger.c:     -- Executing [7291@ext-intercom:114] Busy("SIP/9242-b81327e0", "20") in new stack
Comments:By: rbosch (rbosch) 2009-06-21 01:31:34

I was looking at the set up further and it looks like the channels are not getting properly closed.  The problem extensions have channels showing as active in "sip show channels" when in fact no channels are active.  So the issue may not be related to app_chanisavail, but may be an issue elsewhere.  Restarting asterisk resolves the issue.
By: Leif Madsen (lmadsen) 2009-08-20 14:59:03

I'm changing this category to chan_sip. In order to determine if this is really true, can you confirm you are still having the issue on the latest version checked out from SVN, and provide the following:

* sip debug showing process that is causing the sip channels to become stuck
* sip history for the same
* relevant parts of sip.conf
* any additional information you can provide to reproduce the issue

Thanks!
By: Leif Madsen (lmadsen) 2009-09-22 08:19:58

Closing this issue due to lack of response from the reporter.