No internal extensions can be reached

I’ve just installed freepbx on a debian4 box running asterisk 1.2. Besides some minor permission issues, that went fine and I’m able to make outbound calls using an misdn trunk and a HFC/PCI card. I’m using a SIP phone (Snom) and a IAX2 softphone (Loudhush).

Internal or inward calls however can’t connect - extensions always appear to be busy or congested. If I enable voice mail, I always hit that.

I’ve searched high and low but can’t find any reason. Here’s a full log of an attempted internal call

Jun 29 071357 VERBOSE[7768] logger.c Asterisk Ready.
– Accepting AUTHENTICATED call from 192.168.123.100
> requested format = speex,
> requested prefs = (),
> actual format = ulaw,
> host prefs = (ulaw|alaw|gsm),
> priority = mine
Jun 29 071357 VERBOSE[7795] logger.c – Executing Macro(“IAX2/200-2”, “exten-vm|novm|100”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Macro(“IAX2/200-2”, “user-callerid”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Function result is ''
Jun 29 071357 DEBUG[7795] pbx.c Function result is ''
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, "user-callerid ") in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “0?report”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Not taking any branch
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '1’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “1?start”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Goto (macro-user-callerid,s,5)
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “REALCALLERIDNUM is 200”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Function result is '200’
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “AMPUSER=200”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Function result is 'dinges’
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “AMPUSERCIDNAME=dinges”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “0?report”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Not taking any branch
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “CALLERID(all)=dinges <200>”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Function result is '200’
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “REALCALLERIDNUM=200”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “TTL ARG1 novm”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “0?continue”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Not taking any branch
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '1’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '-1’
Jun 29 071357 DEBUG[7795] pbx.c Function result is '64’
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “__TTL=64”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '1’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “1?continue”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Goto (macro-user-callerid,s,21)
Jun 29 071357 DEBUG[7795] pbx.c Function result is '“dinges” <200>'
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “Using CallerID “dinges” <200>”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “FROMCONTEXT=exten-vm”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “VMBOX=novm”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “EXTTOCALL=100”) in new stack
Jun 29 071357 DEBUG[7795] db.c Unable to find key ‘100’ in family 'CFU’
Jun 29 071357 DEBUG[7795] func_db.c DB CFU/100 not found in database.
Jun 29 071357 DEBUG[7795] pbx.c Function result is ''
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “CFUEXT=”) in new stack
Jun 29 071357 DEBUG[7795] db.c Unable to find key ‘100’ in family 'CFB’
Jun 29 071357 DEBUG[7795] func_db.c DB CFB/100 not found in database.
Jun 29 071357 DEBUG[7795] pbx.c Function result is ''
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “CFBEXT=”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Function result is ''
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “RT=”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Macro(“IAX2/200-2”, “record-enable|100|IN”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Function result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “0?24”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Goto (macro-record-enable,s,4)
Jun 29 071357 DEBUG[7795] pbx.c Function result is '20070629-051357’
Jun 29 071357 VERBOSE[7795] logger.c – Executing DeadAGI(“IAX2/200-2”, “recordingcheck|20070629-051357|1183094037.0”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck
Jun 29 071357 VERBOSE[7795] logger.c – AGI Script recordingcheck completed, returning 0
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “No recording needed”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Macro(“IAX2/200-2”, “dial||tr|100”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing DeadAGI(“IAX2/200-2”, “dialparties.agi”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi
Jun 29 071357 VERBOSE[7795] logger.c – AGI Script dialparties.agi completed, returning 0
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “Returned from dialparties with no extensions to call”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, "DIALSTATUS is ") in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “SV_DIALSTATUS=”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GosubIf(“IAX2/200-2”, “0?docfu|1”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 DEBUG[7795] pbx.c Expression result is '0’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GosubIf(“IAX2/200-2”, “0?docfb|1”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing Set(“IAX2/200-2”, “DIALSTATUS=”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Executing NoOp(“IAX2/200-2”, “Voicemail is novm”) in new stack
Jun 29 071357 DEBUG[7795] pbx.c Expression result is ‘1’
Jun 29 071357 VERBOSE[7795] logger.c – Executing GotoIf(“IAX2/200-2”, “1?s-|1”) in new stack
Jun 29 071357 VERBOSE[7795] logger.c – Goto (macro-exten-vm,s-,1)
Jun 29 071357 VERBOSE[7795] logger.c – Executing PlayTones(“IAX2/200-2”, “congestion”) in new stack
Jun 29 071357 DEBUG[7795] channel.c Prodding channel ‘IAX2/200-2’
Jun 29 071357 VERBOSE[7795] logger.c – Executing Congestion(“IAX2/200-2”, “10”) in new stack
Jun 29 071357 DEBUG[7768] chan_iax2.c Ooh, voice format changed to 4
Jun 29 071358 DEBUG[7768] chan_iax2.c Immediately destroying 2, having received hangup
Jun 29 071358 VERBOSE[7795] logger.c == Spawn extension (macro-exten-vm, s-, 2) exited non-zero on ‘IAX2/200-2’ in macro ‘exten-vm’
Jun 29 071358 VERBOSE[7795] logger.c == Spawn extension (macro-exten-vm, s-, 2) exited non-zero on ‘IAX2/200-2’Jun 29 071358 DEBUG[7795] cdr_addon_mysql.c cdr_mysql inserting a CDR record.
Jun 29 071358 DEBUG[7795] cdr_addon_mysql.c cdr_mysql SQL command as follows INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2007-06-29 071357’,’“dinges” <200>’,‘200’,‘100’,‘from-internal’, ‘IAX2/200-2’,’’,‘Congestion’,‘10’,1,0,‘NO ANSWER’,3,‘200’)
Jun 29 071358 DEBUG[7795] pbx.c Function result is '“dinges” <200>'
Jun 29 071358 DEBUG[7795] pbx.c Function result is '200’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '100’
Jun 29 071358 DEBUG[7795] pbx.c Function result is 'from-internal’
Jun 29 071358 DEBUG[7795] pbx.c Function result is 'IAX2/200-2’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '(null)'
Jun 29 071358 DEBUG[7795] pbx.c Function result is 'Congestion’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '10’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '2007-06-29 071357’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '(null)'
Jun 29 071358 DEBUG[7795] pbx.c Function result is '2007-06-29 071358’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '1’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '0’
Jun 29 071358 DEBUG[7795] pbx.c Function result is 'NO ANSWER’
Jun 29 071358 DEBUG[7795] pbx.c Function result is 'DOCUMENTATION’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '200’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '1183094037.0’
Jun 29 071358 DEBUG[7795] pbx.c Function result is '(null)'
Jun 29 071358 DEBUG[7795] chan_iax2.c We’re hanging up IAX2/200-2 now…
Jun 29 071358 DEBUG[7795] chan_iax2.c Really destroying IAX2/200-2 now…
Jun 29 071358 VERBOSE[7795] logger.c – Hungup 'IAX2/200-2’
Jun 29 071426 DEBUG[7768] chan_iax2.c Peer lastms 2, historicms 2, maxms 2000

I’m not at the office right now to double-check, but I think you’re right. I chowned /usr/share/asterisk to asterisk:asterisk and everything seems OK now.

Thanks all for all the tips!!

then the issue would not be related to what dan points out. Check you paths and permissions such as on amportal.conf and make sure that asterisk and apache are running as user ‘asterisk.’

Nope, 2.2.2 :-/

is this 2.3beta or another version?

you tried:

require_once $config[‘ASTAGIDIR’]."/phpagi.php";
require_once $config[‘ASTAGIDIR’]."/phpagi-asmanager.php";

and it still doesn’t work?

I’m afraid so. More importantly: where should I check why the dialplan PHP script returns 0 every time? When executing from the commandline, it doesn’t generate much useful output.

Well, honestly, I did, but I’m still unable to get internal calls to work. Nor am I able to find some decent way to debug my problem. :slight_smile:

http://freepbx.org/forums/viewtopic.php?t=2429

and it still doesn’t work?

Yep. -/

Added the ./ path, deleted all extensions, rebuilt them no difference.

How can I review/debug the dialplan stuff in a sensible way?

Thanks for all your help!

Steven.

put the explicit pathname in that philippe suggested.

Tried that already before I posted - no luck.

-- Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi

AGI Tx >> agi_request: dialparties.agi
AGI Tx >> agi_channel: IAX2/200-1
AGI Tx >> agi_language: en
AGI Tx >> agi_type: IAX2
AGI Tx >> agi_uniqueid: 1183131271.1
AGI Tx >> agi_callerid: 200
AGI Tx >> agi_calleridname: Steven Softphone
AGI Tx >> agi_callingpres: 67
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 100
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: macro-dial
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode:
AGI Tx >>
– AGI Script dialparties.agi completed, returning 0

look in a couple of recent threads for the solution (sorry to be cryptic, i’m in a hurry…)

I saw a thread indicating the VM extension should be installed and enabled. No luck however. Switched ag debug on

calimeroCLI>
– Executing Macro(“SIP/100-081a5b58”, “exten-vm|200|200”) in new stack
– Executing Macro(“SIP/100-081a5b58”, “user-callerid”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “user-callerid device 100”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?report”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?start”) in new stack
– Executing Set(“SIP/100-081a5b58”, “REALCALLERIDNUM=100”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “REALCALLERIDNUM is 100”) in new stack
– Executing Set(“SIP/100-081a5b58”, “AMPUSER=100”) in new stack
– Executing Set(“SIP/100-081a5b58”, “AMPUSERCIDNAME=Steven Noels”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?report”) in new stack
– Executing Set(“SIP/100-081a5b58”, “CALLERID(all)=Steven Noels <100>”) in new stack
– Executing Set(“SIP/100-081a5b58”, “REALCALLERIDNUM=100”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “TTL ARG1 200”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?continue”) in new stack
– Executing Set(“SIP/100-081a5b58”, “__TTL=64”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,21)
– Executing NoOp(“SIP/100-081a5b58”, “Using CallerID “Steven Noels” <100>”) in new stack
– Executing Set(“SIP/100-081a5b58”, “FROMCONTEXT=exten-vm”) in new stack
– Executing Set(“SIP/100-081a5b58”, “VMBOX=200”) in new stack
– Executing Set(“SIP/100-081a5b58”, “EXTTOCALL=200”) in new stack
– Executing Set(“SIP/100-081a5b58”, “CFUEXT=”) in new stack
– Executing Set(“SIP/100-081a5b58”, “CFBEXT=”) in new stack
– Executing Set(“SIP/100-081a5b58”, “RT=15”) in new stack
– Executing Macro(“SIP/100-081a5b58”, “record-enable|200|IN”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?24”) in new stack
– Goto (macro-record-enable,s,4)
– Executing DeadAGI(“SIP/100-081a5b58”, “recordingcheck|20070629-055120|1183096280.11”) in new stack
– Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck
AGI Tx >> agi_request recordingcheck
AGI Tx >> agi_channel SIP/100-081a5b58
AGI Tx >> agi_language en
AGI Tx >> agi_type SIP
AGI Tx >> agi_uniqueid 1183096280.11
AGI Tx >> agi_callerid 100
AGI Tx >> agi_calleridname Steven Noels
AGI Tx >> agi_callingpres 0
AGI Tx >> agi_callingani2 0
AGI Tx >> agi_callington 0
AGI Tx >> agi_callingtns 0
AGI Tx >> agi_dnid 200
AGI Tx >> agi_rdnis unknown
AGI Tx >> agi_context macro-record-enable
AGI Tx >> agi_extension s
AGI Tx >> agi_priority 4
AGI Tx >> agi_enhanced 0.0
AGI Tx >> agi_accountcode
AGI Tx >> LI>
– AGI Script recordingcheck completed, returning 0
– Executing NoOp(“SIP/100-081a5b58”, “No recording needed”) in new stack
– Executing Macro(“SIP/100-081a5b58”, “dial|15|tr|200”) in new stack
– Executing DeadAGI(“SIP/100-081a5b58”, “dialparties.agi”) in new stack
– Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi
AGI Tx >> agi_request dialparties.agi
AGI Tx >> agi_channel SIP/100-081a5b58
AGI Tx >> agi_language en
AGI Tx >> agi_type SIP
AGI Tx >> agi_uniqueid 1183096280.11
AGI Tx >> agi_callerid 100
AGI Tx >> agi_calleridname Steven Noels
AGI Tx >> agi_callingpres 0
AGI Tx >> agi_callingani2 0
AGI Tx >> agi_callington 0
AGI Tx >> agi_callingtns 0
AGI Tx >> agi_dnid 200
AGI Tx >> agi_rdnis unknown
AGI Tx >> agi_context macro-dial
AGI Tx >> agi_extension s
AGI Tx >> agi_priority 1
AGI Tx >> agi_enhanced 0.0
AGI Tx >> agi_accountcode
AGI Tx >> LI>
– AGI Script dialparties.agi completed, returning 0
– Executing NoOp(“SIP/100-081a5b58”, “Returned from dialparties with no extensions to call”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, "DIALSTATUS is ") in new stack
– Executing Set(“SIP/100-081a5b58”, “SV_DIALSTATUS=”) in new stack
– Executing GosubIf(“SIP/100-081a5b58”, “0?docfu|1”) in new stack
– Executing GosubIf(“SIP/100-081a5b58”, “0?docfb|1”) in new stack
– Executing Set(“SIP/100-081a5b58”, “DIALSTATUS=”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “Voicemail is 200”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?s-|1”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “Sending to Voicemail box 200”) in new stack
– Executing Macro(“SIP/100-081a5b58”, “vm|200|”) in new stack
– Executing Macro(“SIP/100-081a5b58”, “user-callerid|SKIPTTL”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “user-callerid Steven Noels 100”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?report”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “1?start”) in new stack
– Goto (macro-user-callerid,s,5)
– Executing NoOp(“SIP/100-081a5b58”, “REALCALLERIDNUM is 100”) in new stack
– Executing Set(“SIP/100-081a5b58”, “AMPUSER=100”) in new stack
– Executing Set(“SIP/100-081a5b58”, “AMPUSERCIDNAME=Steven Noels”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?report”) in new stack
– Executing Set(“SIP/100-081a5b58”, “CALLERID(all)=Steven Noels <100>”) in new stack
– Executing Set(“SIP/100-081a5b58”, “REALCALLERIDNUM=100”) in new stack
– Executing NoOp(“SIP/100-081a5b58”, “TTL 64 ARG1 SKIPTTL”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,21)
– Executing NoOp(“SIP/100-081a5b58”, “Using CallerID “Steven Noels” <100>”) in new stack
– Executing Set(“SIP/100-081a5b58”, “VMGAIN=”) in new stack
Jun 29 075120 WARNING[8044] func_db.c53 function_db_read DB requires an argument, DB(/)
– Executing GotoIf(“SIP/100-081a5b58”, “1?s-|1”) in new stack
– Goto (macro-vm,s-,1)
– Executing Macro(“SIP/100-081a5b58”, “get-vmcontext|200”) in new stack
– Executing Set(“SIP/100-081a5b58”, “VMCONTEXT=default”) in new stack
– Executing GotoIf(“SIP/100-081a5b58”, “0?200300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing NoOp(“SIP/100-081a5b58”, “”) in new stack
– Executing VoiceMail(“SIP/100-081a5b58”, “200@default|u”) in new stack
– Playing ‘vm-theperson’ (language ‘en’)
== Spawn extension (macro-vm, s-, 2) exited non-zero on ‘SIP/100-081a5b58’ in macro ‘vm’
== Spawn extension (macro-vm, s-, 2) exited non-zero on ‘SIP/100-081a5b58’ in macro ‘exten-vm’
== Spawn extension (macro-vm, s-, 2) exited non-zero on 'SIP/100-081a5b58’
calimero
CLI>