Returned from dialparties with no extensions to call and DIALSTATUS: BUSY

General Help
1

I’m having problems with a few extensions…

These extension go directly to voicemail, and do not ring the telephone through a DID call, or from an IVR, or direct dial from another extension.

The telephones themselve work perfectly otherwise… they can call other extensions, dial outside lines, etc…

Any ideas would be appreciated… if there is any additional details that would help, please let me know
what to provide.

All extensions are configured the same, with the obvious exceptions (userid, password)
The telephones are SNOM370 Firmware 7.1.33

FreePBX 2.4.1.2
Asterisk 1.4.19 built by root @ centos5-rpmbuilder.palosanto.com on a i686 running Linux on 2008-04-02 16:56:34 UTC

Here’s the dialog from an inbound DID call

freepbxCLI>
– Accepting call from ‘8585587100’ to ‘8116’ on channel 0/22, span 1
– Executing [8116@from-pstn:1] Set(“Zap/22-1”, “__FROM_DID=8116”) in new stack
– Executing [8116@from-pstn:2] GotoIf(“Zap/22-1”, “0 ?cidok”) in new stack
– Executing [8116@from-pstn:3] Set(“Zap/22-1”, “CALLERID(name)=8585587100”) in new stack
– Executing [8116@from-pstn:4] NoOp(“Zap/22-1”, “CallerID is “8585587100” <8585587100>”) in new stack
– Executing [8116@from-pstn:5] SetMusicOnHold(“Zap/22-1”, “acc_1”) in new stack
– Executing [8116@from-pstn:6] Set(“Zap/22-1”, “__MOHCLASS=acc_1”) in new stack
– Executing [8116@from-pstn:7] Goto(“Zap/22-1”, “from-did-direct|8116|1”) in new stack
– Goto (from-did-direct,8116,1)
– Executing [8116@from-did-direct:1] Macro(“Zap/22-1”, “exten-vm|8116|8116”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“Zap/22-1”, “user-callerid”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Zap/22-1”, “user-callerid: 8585587100 8585587100”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Zap/22-1”, “AMPUSER=8585587100”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Zap/22-1”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“Zap/22-1”, “1|Set|REALCALLERIDNUM=8585587100”) in new stack
– Executing [s@macro-user-callerid:5] NoOp(“Zap/22-1”, “REALCALLERIDNUM is 8585587100”) in new stack
– Executing [s@macro-user-callerid:6] Set(“Zap/22-1”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:7] Set(“Zap/22-1”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“Zap/22-1”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Zap/22-1”, “TTL: ARG1: 8116”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Zap/22-1”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:15] Set(“Zap/22-1”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:16] GotoIf(“Zap/22-1”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Zap/22-1”, “Using CallerID “8585587100” <8585587100>”) in new stack
– Executing [s@macro-exten-vm:2] Set(“Zap/22-1”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“Zap/22-1”, “VMBOX=8116”) in new stack
– Executing [s@macro-exten-vm:4] Set(“Zap/22-1”, “EXTTOCALL=8116”) in new stack
– Executing [s@macro-exten-vm:5] Set(“Zap/22-1”, “CFUEXT=”) in new stack
– Executing [s@macro-exten-vm:6] Set(“Zap/22-1”, “CFBEXT=”) in new stack
– Executing [s@macro-exten-vm:7] Set(“Zap/22-1”, “RT=15”) in new stack
– Executing [s@macro-exten-vm:8] Macro(“Zap/22-1”, “record-enable|8116|IN”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“Zap/22-1”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] AGI(“Zap/22-1”, “recordingcheck|20081021-151703|1224627423.1017”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck|20081021-151703|1224627423.1017: Inbound recording not enabled
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] NoOp(“Zap/22-1”, “No recording needed”) in new stack
– Executing [s@macro-exten-vm:9] Macro(“Zap/22-1”, “dial|15|tr|8116”) in new stack
– Executing [s@macro-dial:1] GotoIf(“Zap/22-1”, “0?dial”) in new stack
– Executing [s@macro-dial:2] SetMusicOnHold(“Zap/22-1”, “acc_1”) in new stack
– Executing [s@macro-dial:3] AGI(“Zap/22-1”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_additional.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘admin’ logged on from 127.0.0.1
dialparties.agi: Caller ID name is ‘8585587100’ number is '8585587100’
dialparties.agi: USE_CONFIRMATION: 'FALSE’
dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 8116 to extension map
– dialparties.agi: Extension 8116 cf is disabled
– dialparties.agi: Extension 8116 do not disturb is disabled
> dialparties.agi: extnum 8116 has: cw: 0; hascfb: 0 [] hascfu: 0 []
> dialparties.agi: ExtensionState: 1
dialparties.agi: Extension 8116 has ExtensionState: 1
– dialparties.agi: Checking CW and CFB status for extension 8116
dialparties.agi: Extension 8116 is not available to be called
dialparties.agi: Extension 8116 has call waiting disabled
– dialparties.agi: Filtered ARG3:
== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:4] NoOp(“Zap/22-1”, “Returned from dialparties with no extensions to call and DIALSTATUS: BUSY”) in new stack
– Executing [s@macro-exten-vm:10] Set(“Zap/22-1”, “SV_DIALSTATUS=BUSY”) in new stack
– Executing [s@macro-exten-vm:11] GosubIf(“Zap/22-1”, “0?docfu|1”) in new stack
– Executing [s@macro-exten-vm:12] GosubIf(“Zap/22-1”, “0?docfb|1”) in new stack
– Executing [s@macro-exten-vm:13] Set(“Zap/22-1”, “DIALSTATUS=BUSY”) in new stack
– Executing [s@macro-exten-vm:14] NoOp(“Zap/22-1”, “Voicemail is 8116”) in new stack
– Executing [s@macro-exten-vm:15] GotoIf(“Zap/22-1”, “0?s-BUSY|1”) in new stack
– Executing [s@macro-exten-vm:16] NoOp(“Zap/22-1”, “Sending to Voicemail box 8116”) in new stack
– Executing [s@macro-exten-vm:17] Macro(“Zap/22-1”, “vm|8116|BUSY”) in new stack
– Executing [s@macro-vm:1] Macro(“Zap/22-1”, “user-callerid|SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“Zap/22-1”, “user-callerid: 8585587100 8585587100”) in new stack
– Executing [s@macro-user-callerid:2] Set(“Zap/22-1”, “AMPUSER=8585587100”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“Zap/22-1”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“Zap/22-1”, “0|Set|REALCALLERIDNUM=8585587100”) in new stack
– Executing [s@macro-user-callerid:5] NoOp(“Zap/22-1”, “REALCALLERIDNUM is 8585587100”) in new stack
– Executing [s@macro-user-callerid:6] Set(“Zap/22-1”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:7] Set(“Zap/22-1”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“Zap/22-1”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“Zap/22-1”, “TTL: 64 ARG1: SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“Zap/22-1”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“Zap/22-1”, “Using CallerID “8585587100” <8585587100>”) in new stack
– Executing [s@macro-vm:2] Set(“Zap/22-1”, “VMGAIN=”"") in new stack
– Executing [s@macro-vm:3] GotoIf(“Zap/22-1”, “1?vmx|1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] GotoIf(“Zap/22-1”, “0?s-BUSY|1”) in new stack
– Executing [vmx@macro-vm:2] Set(“Zap/22-1”, “MODE=busy”) in new stack
– Executing [vmx@macro-vm:3] GotoIf(“Zap/22-1”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,5)
– Executing [vmx@macro-vm:5] NoOp(“Zap/22-1”, "Checking if ext 8116 is enabled: ") in new stack
– Executing [vmx@macro-vm:6] GotoIf(“Zap/22-1”, “1?s-BUSY|1”) in new stack
– Goto (macro-vm,s-BUSY,1)
– Executing [s-BUSY@macro-vm:1] NoOp(“Zap/22-1”, “BUSY voicemail”) in new stack
– Executing [s-BUSY@macro-vm:2] Macro(“Zap/22-1”, “get-vmcontext|8116”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“Zap/22-1”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“Zap/22-1”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“Zap/22-1”, “”) in new stack
– Executing [s-BUSY@macro-vm:3] VoiceMail(“Zap/22-1”, “8116@default|b”) in new stack
– Zap/1-1 answered SIP/8134-088ed7b0
– <Zap/22-1> Playing ‘/var/spool/asterisk/voicemail/default/8116/busy’ (language ‘en’)
– Channel 0/22, span 1 got hangup request, cause 16
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on ‘Zap/22-1’ in macro ‘vm’
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on ‘Zap/22-1’ in macro ‘exten-vm’
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on ‘Zap/22-1’
– Hungup 'Zap/22-1’
freepbxCLI>

2

ok here you go
From your output

dialparties.agi: Extension 8116 has ExtensionState: 1
– dialparties.agi: Checking CW and CFB status for extension 8116
dialparties.agi: Extension 8116 is not available to be called
dialparties.agi: Extension 8116 has call waiting disabled

The first line means that the system thinks the phone is currently in use, the extension does not have call waiting enabled (4th line)

So it can’t call the extension.

Was it in use at the time? Are you sure? Check the FOP to see what it thinks. Also in the asterisk cli do a soft hangup command then press the tab key it will provide to you all the extensions it thinks are busy with calls, if it is NOT on the phone you’ll see the extension listed, type enough of the line to make it unique and press the tab (it will auto fill in the rest) then press return.

That will tell the system to hangup the call. Now can it be called?

If this solves the problem I’ll bet what has happened is that the extension was in use when asterisk died and while it was starting up, dying the extension hung up, sent the notices to the server but since it was not functioning it didn’t update the status in the asterisk database it uses to track this stuff and still thinks it’s busy.

A asterisk crash like this can happen if for example if you are using any version of trixbox with * 1.4 and attempting to using the built in spansp faxing routines (there is a bug they refuse to fix and it causes a application crash).

Hope this helps.

Bet

3

I’ve also seen many a genius of a user hit the DND key, which would return the same dial status (usually)

4

true that does happen, but at least on my phones if I enable the phone side DND you’ll see below instead. (server side you’ll see it check and respond on the DND values in the dialparties.agi)

--  dialparties.agi: Added extension 112 to extension map
--  dialparties.agi: Extension 112 cf is disabled
--  dialparties.agi: Extension 112 do not disturb is disabled
   >  dialparties.agi: extnum 112 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
   >  dialparties.agi: ExtensionState: 0
--  dialparties.agi: dbset CALLTRACE/112 to 789
--  dialparties.agi: Filtered ARG3: 112

== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing Dial(“Zap/3-1”, “SIP/112|20|tr”) in new stack
– Called 112
– Got SIP response 486 “Busy Here” back from 172.18.1.85
– SIP/112-08de7fc8 is busy
== Everyone is busy/congested at this time (1:1/0/0)

5

I was refering to client side DND, which often returnes as busy

6

Yep that is the trace I provided (client = phone side) above showing it looking different.

7

I saw that as I was looking through the log, but it didn’t make sense to me…

FOP show’s the extension off-hook… I tried hanging up in FOP, no joy. I rebooted the telephone, no joy, I checked DND, both on the telephone and with *97 and no joy.

The extension is NOT in use, at least not in any way I can see. From the extension I can dial anywhere I like and it works fine.

OK, I tried soft hangup…

freepbxCLI> soft hangup zap/23-1
zap/23-1 is not a known channel
freepbxCLI> soft hangup SIP/8116-b7745c68
Requested Hangup on channel ‘SIP/8116-b7745c68’

FOP still show the line off-hook
and the same behavior is still happening on this one extension, by the way, only this extension is having these issues.

FYI it’s Elastix 1.1-17

could the condition you describe happen if the extension was off-hook when a reload happened?
or what if the telephone was unplugged while in a call?

Would a system reboot possibly fix this?
Can I look in the databse somewhere to see? Manually alter a DB record?

I am sooo lost on this

thanks for your help

8

I’ve seen it happen once with a Zap Channel also. When you type soft hangup if you press the tab key at that point it should show all lines it thinks are busy. See if it lists that extension.

In that it’s a Zap channel a reboot should clear it.

9

It does not appear to be a ZAP channel.(see below) and soft-hangup does not clear the condition.

Is there a way to trace why dialparties.agi states “is not available to be called”?
I’ve looked at the code, and it seems to me the most likely culprit is

$extstate = is_ext_avail($extnum);

but what does this function do? And how do I change it/fix it?

Poking around I also found this

freepbxCLI> core show channels
Channel Location State Application(Data)
SIP/8116-b7745c68 98@from-internal:4 Up VoiceMailMain()
1 active channel
1 active call
freepbxCLI> show hints
freepbxCLI>
-= Registered Asterisk Dial Plan Hints =-
8116@ext-local : SIP/8116 State:InUse Watchers 0

freepbxCLI> soft hangup
SIP/8104-08da7cf0 Zap/23-1 SIP/8116-b7745c68
freepbxCLI> soft hangup SIP/8116-b7745c68
Requested Hangup on channel 'SIP/8116-b7745c68’
freepbx*CLI>

But the FOP still show’s Off-Hook, and dialing the extension still goes straight to voicemail with this in the CLI

dialparties.agi: Starting New Dialparties.agi
dialparties.agi: Caller ID name is ‘Test Extension’ number is '8177’
dialparties.agi: USE_CONFIRMATION: 'FALSE’
dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 8116 to extension map
– dialparties.agi: Extension 8116 cf is disabled
– dialparties.agi: Extension 8116 do not disturb is disabled
> dialparties.agi: extnum 8116 has: cw: 0; hascfb: 0 [] hascfu: 0 []
> dialparties.agi: ExtensionState: 1
dialparties.agi: Extension 8116 has ExtensionState: 1
– dialparties.agi: Checking CW and CFB status for extension 8116
dialparties.agi: Extension 8116 is not available to be called
dialparties.agi: Extension 8116 has call waiting disabled
– dialparties.agi: Filtered ARG3:
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:4] NoOp(“SIP/8177-b759b1b0”, “Returned from dialparties with no extensions to call and DIALSTATUS: BUSY”) in new stack

10

If soft hangup SIP/8116-b7745c68 will not free it up then you’ll need to reboot. Something is really stuck in one of the conditions. Besides that will clear the any stuck zap channel at the same time.

before you do that do

ps -aef | grep asterisk
and you should get a few lines. Take a look at the line for starting /bin/sh /usr/sbin/safe_asterisk and the line /usr/sbin/asterisk

Are the date/time stamps the same or is the date/time stamp /usr/sbin/asterisk corespond to when extension 8116 started having issues? If so that would mean that asterisk crashed and restarted at the date and time of the process.

11

Here’s the output… it’s probably about the same time… but I can’t be positive.

root 3169 1 0 Oct20 ? 00:00:00 /bin/bash /usr/sbin/safe_asterisk -U asterisk -G asterisk
asterisk 3188 3169 99 Oct20 ? 2-17:11:22 /usr/sbin/asterisk -f -U asterisk -G asterisk -vvvg -c

I’m assuming that the 2-17:11:22 is how long the process has been running (2 days, 17 hours, 11 minutes, 22 seconds)?
and uptime show about 32 minutes longer than that… does a reload change the process start time? if not, then it must
have crashed, otherwise I might have done a reload.

I will reboot after hours and see if that resolves the problem.

thanks

12

2-17:11:22 is the total amount of CPU time used for the process so far.

Yea something is interesting… with 43 extensions and we’ve been running since Feb 15th I have a total load of 4:01:32, we don’t record calls, but we have easly a 100 conference calls a week as we have a distributed office with people in two different cities, and 6 more remote people all along the north east.

13

Well, a reboot solved the problem…

I really wish there had been a way to fix it without having to reboot… it’s not something
that can be done readily… user tend to object, hopefully this condition will not reappear.

thanks for your help

14

It is very rare that I’ve had it happen that way. 99.9% of the time a soft hangup normally works. it’s been twice in 2.5 years I think I’ve had it happen to me that the command didn’t resolve it.

15

OK, I have the condition again… hthis time there are two extensions
that seem to be in the condition that they appear off hook, even so they are not.

The only thing that both people can recall doing that is similar, both had
temporary announcements, and deleted them.

Any idea how that might make it happen?

Also, I do rememeber pushing the # key when I wasn’t prompted to, and having the
telephone go silent… while I was in voicemail, and having to hangup.
Not sure that helps any either.