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