20 sec delay's on out bound calls

I’m getting 20 sec delay’s on outbound calls. I rebooted Phone,server and softphone.
The problem just started today. What should i check?
asterisk 11
PBX Firmware: 3.211.63-8

How would you turn debug and verbose on?

So Verbosity is set at 3
debug set at 0
sip show peers shows 3 peers 2 online and one off
the one off line is 777 which may be one of my extensions
"777"off line, could have been the other server… My mistake running CLI commands from a networked pc assuming i am local host but not running CLI commands to the asterisk server currently registering my trunks
777 is an extension on my first box as 007,008 is on my second box

That is nothing to do with verbosity . You need to make a call and watch it’s progression.

How .
please
You need to make a call and watch it’s progression.

tail -f /var/log/asterisk/full

[code][[email protected] ~]# tail -f /var/log/asterisk/full
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/fpbx-1-IPjH1RLLAW4E-00000005’ in macro ‘vm’
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on ‘SIP/fpbx-1-IPjH1RLLAW4E-00000005’ in macro ‘exten-vm’
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: == Spawn extension (from-did-direct, 007, 2) exited non-zero on ‘SIP/fpbx-1-IPjH1RLLAW4E-00000005’
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Executing [[email protected]:1] Macro(“SIP/fpbx-1-IPjH1RLLAW4E-00000005”, “hangupcall,”) in new stack
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/fpbx-1-IPjH1RLLAW4E-00000005”, “1?theend”) in new stack
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Goto (macro-hangupcall,s,3)
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/fpbx-1-IPjH1RLLAW4E-00000005”, “0?Set(CDR(recordingfile)=)”) in new stack
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/fpbx-1-IPjH1RLLAW4E-00000005”, “”) in new stack
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/fpbx-1-IPjH1RLLAW4E-00000005’ in macro ‘hangupcall’
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on ‘SIP/fpbx-1-IPjH1RLLAW4E-00000005’
^C0

[/code]

That’s very far from a complete call.

cat /var/log/asterisk/full|grep “[13285]”

will give you all of that leg

[2015-04-02 09:51:52] VERBOSE[14233][C-00000007] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000007", "0?Set(CDR(recordingfile)=)") in new stack [2015-04-02 09:51:52] VERBOSE[14233][C-00000007] pbx.c: -- Executing [[email protected]:4] Hangup("SIP/fpbx-1-IPjH1RLLAW4E-00000007", "") in new stack [2015-04-02 09:51:52] VERBOSE[14233][C-00000007] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000007' in macro 'hangupcall' [2015-04-02 09:51:52] VERBOSE[14233][C-00000007] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000007' [2015-04-02 09:53:06] VERBOSE[2399][C-00000008] netsock2.c: == Using SIP RTP TOS bits 184 [2015-04-02 09:53:06] VERBOSE[2399][C-00000008] netsock2.c: == Using SIP RTP CoS mark 5 [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__FROM_DID=9713179221") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "app-blacklist-check,s,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?blacklisted") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLED_BLACKLIST=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(did)=9713179221") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0 ?Set(CALLERID(name)=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERPRES()=allowed_not_screened") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "from-did-direct,007,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (from-did-direct,007,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__RINGTIMER=15") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "exten-vm,007,007,0,0,0") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "user-callerid,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "TOUCH_MONITOR=1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__TTL=64") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(number)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(name)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnum)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnam)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CHANNEL(language)=en") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RingGroupMethod=none") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__EXTTOCALL=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__PICKUPMARK=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RT=15") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "sub-record-check,s,1(exten,007,)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "REC_POLICY_MODE_SAVE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?check") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,s,7) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__MON_FMT=wav") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]k:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?next") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,s,11) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(__REC_POLICY_MODE=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?exten,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:14] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_STATUS=INITIALIZED") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NOW=1427993586") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__DAY=02") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__MONTH=04") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__YEAR=2015") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:19] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__TIMESTR=20150402-095306") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:20] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__FROMEXTEN=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:21] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CALLFILENAME=exten-007-15033302014-20150402-095306-1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:22] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "exten,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,exten,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?callee") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_POLICY_MODE=dontcare") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?caller") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,exten,10) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_POLICY_MODE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?record,1(exten,007,15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?macrodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-exten-vm,s,13) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?clrheader,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:14] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "dial-one,15,Ttr,007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DEXTEN=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DIALSTATUS_CW=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?screen,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?cf,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?skip1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,8) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "EXTHASCW=ENABLED") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?next1:cwinusebusy") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,23) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:23] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?next3:continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,24) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:24] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DIALSTATUS_CW=BUSY)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:25] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:26] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?dstring,1():dlocal,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DEVICES=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DEVICES=07)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "LOOPCNT=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISDIAL=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?zap2dahdi,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NEWDIAL=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "LOOPCNT2=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER2=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISPART2=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(THISPART2=DAHDI/007)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NEWDIAL=SIP/007&") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER2=2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?begin2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISDIAL=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=SIP/007&") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER=2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?begin") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:27] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?skiptrace") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?ctset,1():ctclear,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DB(CALLTRACE/007)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "D_OPTIONS=Ttr") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?SIPAddHeader(Alert-Info: )") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?SIPAddHeader()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(CHANNEL(musicclass)=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:34] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?qwait,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CWIGNORE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:36] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__KEEPCID=TRUE") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:37] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?usegoto,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:38] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?godial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,42) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:42] Dial("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "SIP/007,15,Ttr") in new stack [2015-04-02 09:53:06] WARNING[14499][C-00000008] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:43] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?MacroExit()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:44] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DIALSTATUS=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:45] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "SV_DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?docfu,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?docfb,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:19] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?MacroExit()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:20] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:21] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "vm,007,CHANUNAVAIL,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "user-callerid,SKIPTTL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "TOUCH_MONITOR=1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(number)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(name)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnum)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnam)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CHANNEL(language)=en") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "VMGAIN=""") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "blkvm-check,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "GOSUB_RETVAL=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?vmx,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MEXTEN=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MMODE=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RETVM=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MODE=unavail") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?chknomsg") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,7) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?notdirect") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,10) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "Checking if ext 007 is enabled: ") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,s-CHANUNAVAIL,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "get-vmcontext,007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "VMCONTEXT=default") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?200:300") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-get-vmcontext,s,300) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "[email protected],u""") in new stack [2015-04-02 09:53:07] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'vm-theperson.ulaw' (language 'en') [2015-04-02 09:53:08] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/0.ulaw' (language 'en') [2015-04-02 09:53:09] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/0.ulaw' (language 'en') [2015-04-02 09:53:10] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/7.ulaw' (language 'en') [2015-04-02 09:53:11] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'vm-isunavail.ulaw' (language 'en') [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'vm' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'exten-vm' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: == Spawn extension (from-did-direct, 007, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "hangupcall,") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?theend") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-hangupcall,s,3) [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(CDR(recordingfile)=)") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Hangup("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'hangupcall' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' ^C

I think my soft phone is causing the issue no lag with hard phone

[2015-04-02 09:51:52] VERBOSE[14233][C-00000007] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000007' in macro 'hangupcall' [2015-04-02 09:51:52] VERBOSE[14233][C-00000007] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000007' [2015-04-02 09:53:06] VERBOSE[2399][C-00000008] netsock2.c: == Using SIP RTP TOS bits 184 [2015-04-02 09:53:06] VERBOSE[2399][C-00000008] netsock2.c: == Using SIP RTP CoS mark 5 [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__FROM_DID=9713179221") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "app-blacklist-check,s,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?blacklisted") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLED_BLACKLIST=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(did)=9713179221") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0 ?Set(CALLERID(name)=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERPRES()=allowed_not_screened") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "from-did-direct,007,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (from-did-direct,007,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__RINGTIMER=15") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "exten-vm,007,007,0,0,0") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "user-callerid,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "TOUCH_MONITOR=1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__TTL=64") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(number)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(name)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnum)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnam)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CHANNEL(language)=en") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RingGroupMethod=none") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__EXTTOCALL=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__PICKUPMARK=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RT=15") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "sub-record-check,s,1(exten,007,)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "REC_POLICY_MODE_SAVE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?check") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,s,7) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__MON_FMT=wav") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?next") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,s,11) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(__REC_POLICY_MODE=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?exten,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:14] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_STATUS=INITIALIZED") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NOW=1427993586") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__DAY=02") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__MONTH=04") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__YEAR=2015") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:19] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__TIMESTR=20150402-095306") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:20] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__FROMEXTEN=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:21] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CALLFILENAME=exten-007-15033302014-20150402-095306-1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:22] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "exten,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,exten,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?callee") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_POLICY_MODE=dontcare") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?caller") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (sub-record-check,exten,10) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__REC_POLICY_MODE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?record,1(exten,007,15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?macrodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-exten-vm,s,13) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?clrheader,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:14] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "dial-one,15,Ttr,007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DEXTEN=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DIALSTATUS_CW=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?screen,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?cf,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?skip1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,8) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "EXTHASCW=ENABLED") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?next1:cwinusebusy") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,23) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:23] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?next3:continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,24) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:24] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DIALSTATUS_CW=BUSY)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:25] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:26] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?dstring,1():dlocal,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DEVICES=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DEVICES=07)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "LOOPCNT=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISDIAL=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?zap2dahdi,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Return()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NEWDIAL=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "LOOPCNT2=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER2=1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISPART2=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(THISPART2=DAHDI/007)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NEWDIAL=SIP/007&") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER2=2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?begin2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "THISDIAL=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:9] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=SIP/007&") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "ITER=2") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?begin") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:12] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=SIP/007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:27] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?nodial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?skiptrace") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?ctset,1():ctclear,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DB(CALLTRACE/007)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "D_OPTIONS=Ttr") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?SIPAddHeader(Alert-Info: )") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?SIPAddHeader()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(CHANNEL(musicclass)=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:34] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?qwait,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CWIGNORE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:36] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__KEEPCID=TRUE") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:37] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?usegoto,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:38] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?godial") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-dial-one,s,42) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:42] Dial("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "SIP/007,15,Ttr") in new stack [2015-04-02 09:53:06] WARNING[14499][C-00000008] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:43] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?MacroExit()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:44] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(DIALSTATUS=)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:45] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "SV_DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:16] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?docfu,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:17] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?docfb,1()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]-exten-vm:19] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?MacroExit()") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:20] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:21] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "vm,007,CHANUNAVAIL,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "user-callerid,SKIPTTL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "TOUCH_MONITOR=1427993586.8") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?report") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?continue") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(number)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CALLERID(name)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnum)=15033302014") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CDR(cnam)=M CARPENTER") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "CHANNEL(language)=en") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "VMGAIN=""") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "blkvm-check,") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "GOSUB_RETVAL=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?vmx,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MEXTEN=007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MMODE=CHANUNAVAIL") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RETVM=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "MODE=unavail") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?chknomsg") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,7) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?notdirect") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,vmx,10) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:10] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "Checking if ext 007 is enabled: ") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?s-CHANUNAVAIL,1") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-vm,s-CHANUNAVAIL,1) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "get-vmcontext,007") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "VMCONTEXT=default") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?200:300") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-get-vmcontext,s,300) [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "[email protected],u""") in new stack [2015-04-02 09:53:07] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'vm-theperson.ulaw' (language 'en') [2015-04-02 09:53:08] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/0.ulaw' (language 'en') [2015-04-02 09:53:09] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/0.ulaw' (language 'en') [2015-04-02 09:53:10] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'digits/7.ulaw' (language 'en') [2015-04-02 09:53:11] VERBOSE[14499][C-00000008] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000008> Playing 'vm-isunavail.ulaw' (language 'en') [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'vm' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'exten-vm' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: == Spawn extension (from-did-direct, 007, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "hangupcall,") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "1?theend") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Goto (macro-hangupcall,s,3) [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "0?Set(CDR(recordingfile)=)") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [[email protected]:4] Hangup("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' in macro 'hangupcall' [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000008' ^C

my last post was mangled, to isolate a call look for the number after VERBOSE

cat /var/log/asterisk/full|grep "\[13285\]"

I added DNS that the modem shows to the free pbx DNS querry.
then add ip address of the pbx to /etc/hosts and seems to have gotten a little better.
how to isolate a call?

I guess i did somthing incorect
[[email protected] ~]# cat /var/log/asterisk/full|grep
Usage: grep [OPTION]… PATTERN [FILE]…
Try `grep --help’ for more information.
[[email protected] ~]#

See my previous post, you need a PATTERN as an argument to grep and that would be the "\[66666\]" bit.

[[email protected] ~]# cat /var/log/asterisk/full|grep "\[4630\]" [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__FROM_DID=9713179221") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "app-blacklist-check,s,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?blacklisted") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLED_BLACKLIST=1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CDR(did)=9713179221") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0 ?Set(CALLERID(name)=15033302014)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLERPRES()=allowed_not_screened") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "from-did-direct,007,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (from-did-direct,007,1) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__RINGTIMER=15") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "exten-vm,007,007,0,0,0") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "user-callerid,") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "TOUCH_MONITOR=1428090254.3") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?report") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSERCIDNAME=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?report") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?continue") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__TTL=64") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:17] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?continue") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLERID(number)=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLERID(name)=M CARPENTER") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CDR(cnum)=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CDR(cnam)=M CARPENTER") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CHANNEL(language)=en") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "RingGroupMethod=none") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__EXTTOCALL=007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__PICKUPMARK=007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "RT=15") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "sub-record-check,s,1(exten,007,)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "REC_POLICY_MODE_SAVE=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?check") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (sub-record-check,s,7) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__MON_FMT=wav") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?next") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (sub-record-check,s,11) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Return()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(__REC_POLICY_MODE=)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?exten,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:14] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__REC_STATUS=INITIALIZED") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "NOW=1428090254") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__DAY=03") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:17] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__MONTH=04") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__YEAR=2015") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:19] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__TIMESTR=20150403-124414") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:20] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__FROMEXTEN=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:21] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__CALLFILENAME=exten-007-15033302014-20150403-124414-1428090254.3") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:22] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "exten,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (sub-record-check,exten,1) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?callee") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__REC_POLICY_MODE=dontcare") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?caller") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (sub-record-check,exten,10) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__REC_POLICY_MODE=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?record,1(exten,007,15033302014)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:12] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?macrodial") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-exten-vm,s,13) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:13] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?clrheader,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:14] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "dial-one,15,Ttr,007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DEXTEN=007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DIALSTATUS_CW=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?screen,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?cf,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?skip1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-dial-one,s,8) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?nodial") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?continue") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "EXTHASCW=ENABLED") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?next1:cwinusebusy") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-dial-one,s,23) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:23] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?next3:continue") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-dial-one,s,24) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:24] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(DIALSTATUS_CW=BUSY)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:25] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?nodial") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:26] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?dstring,1():dlocal,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DSTRING=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DEVICES=007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Return()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(DEVICES=07)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "LOOPCNT=1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "ITER=1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "THISDIAL=SIP/007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [dst[email protected]:8] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?zap2dahdi,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Return()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "NEWDIAL=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "LOOPCNT2=1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "ITER2=1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "THISPART2=SIP/007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(THISPART2=DAHDI/007)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "NEWDIAL=SIP/007&") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:8] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "ITER2=2") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?begin2") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "THISDIAL=SIP/007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:9] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DSTRING=SIP/007&") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "ITER=2") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?begin") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:12] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DSTRING=SIP/007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:27] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?nodial") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:28] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?skiptrace") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:29] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?ctset,1():ctclear,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DB(CALLTRACE/007)=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "D_OPTIONS=Ttr") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:31] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?SIPAddHeader(Alert-Info: )") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]ne:32] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?SIPAddHeader()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(CHANNEL(musicclass)=)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:34] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?qwait,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__CWIGNORE=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:36] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__KEEPCID=TRUE") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:37] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?usegoto,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:38] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?godial") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-dial-one,s,42) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:42] Dial("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "SIP/007,15,Ttr") in new stack [2015-04-03 12:44:14] WARNING[4630][C-00000003] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:43] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?MacroExit()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:44] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(DIALSTATUS=)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:45] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?s-CHANUNAVAIL,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "SV_DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:16] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?docfu,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:17] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?docfb,1()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DIALSTATUS=CHANUNAVAIL") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:19] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?MacroExit()") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:20] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?s-CHANUNAVAIL,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:21] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "vm,007,CHANUNAVAIL,") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "user-callerid,SKIPTTL") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "TOUCH_MONITOR=1428090254.3") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?report") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(REALCALLERIDNUM=15033302014)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSERCIDNAME=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?report") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,15) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?continue") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLERID(number)=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CALLERID(name)=M CARPENTER") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CDR(cnum)=15033302014") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CDR(cnam)=M CARPENTER") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "CHANNEL(language)=en") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "VMGAIN=""") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "blkvm-check,") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "GOSUB_RETVAL=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?vmx,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-vm,vmx,1) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "MEXTEN=007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "MMODE=CHANUNAVAIL") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "RETVM=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "MODE=unavail") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?chknomsg") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-vm,vmx,7) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?s-CHANUNAVAIL,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?notdirect") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-vm,vmx,10) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:10] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "Checking if ext 007 is enabled: ") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?s-CHANUNAVAIL,1") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-vm,s-CHANUNAVAIL,1) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "get-vmcontext,007") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "VMCONTEXT=default") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?200:300") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-get-vmcontext,s,300) [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "[email protected],u""") in new stack [2015-04-03 12:44:15] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'vm-theperson.ulaw' (language 'en') [2015-04-03 12:44:16] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'digits/0.ulaw' (language 'en') [2015-04-03 12:44:17] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'digits/0.ulaw' (language 'en') [2015-04-03 12:44:18] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'digits/7.ulaw' (language 'en') [2015-04-03 12:44:19] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'vm-isunavail.ulaw' (language 'en') [2015-04-03 12:44:20] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'vm-intro.ulaw' (language 'en') [2015-04-03 12:44:25] VERBOSE[4630][C-00000003] file.c: -- <SIP/fpbx-1-IPjH1RLLAW4E-00000003> Playing 'beep.ulaw' (language 'en') [2015-04-03 12:44:26] VERBOSE[4630][C-00000003] app_voicemail.c: -- Recording the message [2015-04-03 12:44:26] VERBOSE[4630][C-00000003] app.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/007/tmp/aAodts format: wav, 0x7f89b80142b8 [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] app.c: -- User hung up [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000003' in macro 'vm' [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000003' in macro 'exten-vm' [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: == Spawn extension (from-did-direct, 007, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000003' [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "hangupcall,") in new stack [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "1?theend") in new stack [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Goto (macro-hangupcall,s,3) [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "0?Set(CDR(recordingfile)=)") in new stack [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Executing [[email protected]:4] Hangup("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000003' in macro 'hangupcall' [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000003' [[email protected] ~]#

That’s an inbound call failing to get an answer from extension 007 because it’s not there and successfully going to voicemail for 007.

Dicko,
I think you are pointing in the right direction. I do have a problem with inbound calls going straight to voice mail. But if i can retrieve messages and record calls on ext 007. How is there not an extension?
I show 2 extensions in extension module 007,008
Below is new cat /var/log/asterisk/full|grep "[3509]"
call placed directly from hand set with no leg times or delays.

[2015-04-06 15:05:30] VERBOSE[2245] asterisk.c: Asterisk Ready.
[2015-04-06 15:10:28] VERBOSE[2366][C-00000000] netsock2.c:   == Using SIP RTP TOS bits 184
[2015-04-06 15:10:28] VERBOSE[2366][C-00000000] netsock2.c:   == Using SIP RTP CoS mark 5
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__FROM_DID=9713179221") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "sub-record-check,s,1(force,9713179221,always)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "REC_POLICY_MODE_SAVE=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?check") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (sub-record-check,s,7)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__MON_FMT=wav") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?next") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (sub-record-check,s,11)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Return()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:12] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?Set(__REC_POLICY_MODE=always)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:13] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?force,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:14] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__REC_STATUS=INITIALIZED") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "NOW=1428358228") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__DAY=06") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:17] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__MONTH=04") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__YEAR=2015") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:19] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__TIMESTR=20150406-151028") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:20] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__FROMEXTEN=unknown") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:21] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__CALLFILENAME=force-9713179221-unknown-20150406-151028-1428358228.0") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:22] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "force,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (sub-record-check,force,1)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?record,1(force,always,unknown)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] MixMonitor("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "2015/04/06/force-9713179221-unknown-20150406-151028-1428358228.0.wav,,") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__REC_STATUS=RECORDING") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(recordingfile)=force-9713179221-unknown-20150406-151028-1428358228.0.wav") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "app-blacklist-check,s,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?blacklisted") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLED_BLACKLIST=1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(did)=9713179221") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0 ?Set(CALLERID(name)=15033302014)") in new stack
[2015-04-06 15:10:28] WARNING[3509][C-00000000] func_callerid.c: CALLERPRES is deprecated.  Use CALLERID(name-pres) or CALLERID(num-pres) instead.
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLERPRES()=allowed_not_screened") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:8] Goto("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "from-did-direct,007,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (from-did-direct,007,1)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__RINGTIMER=15") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "exten-vm,007,007,0,0,0") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "user-callerid,") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "TOUCH_MONITOR=1428358228.0") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?report") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?Set(REALCALLERIDNUM=15033302014)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSERCIDNAME=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?report") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-user-callerid,s,15)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?continue") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:16] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__TTL=64") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:17] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?continue") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-user-callerid,s,28)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLERID(number)=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLERID(name)=M CARPENTER") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(cnum)=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(cnam)=M CARPENTER") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CHANNEL(language)=en") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "RingGroupMethod=none") in new stack
[2015-04-06 15:10:28] VERBOSE[3510][C-00000000] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/fpbx-1-IPjH1RLLAW4E-00000000
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__EXTTOCALL=007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__PICKUPMARK=007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "RT=15") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:6] Gosub("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "sub-record-check,s,1(exten,007,)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "REC_POLICY_MODE_SAVE=always") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?check") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (sub-record-check,s,7)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__MON_FMT=wav") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?next") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:9] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(recordingfile)=force-9713179221-unknown-20150406-151028-1428358228.0.wav") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:10] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?macrodial") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-exten-vm,s,13)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:13] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?clrheader,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:14] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "dial-one,15,Ttr,007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DEXTEN=007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DIALSTATUS_CW=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?screen,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?cf,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?skip1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-dial-one,s,8)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:8] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?nodial") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?continue") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "EXTHASCW=ENABLED") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?next1:cwinusebusy") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-dial-one,s,23)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:23] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?next3:continue") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-dial-one,s,24)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:24] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:25] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?nodial") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:26] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?dstring,1():dlocal,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DSTRING=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DEVICES=007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Return()") in new stack
dial-one:8] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?zap2dahdi,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Return()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "NEWDIAL=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "LOOPCNT2=1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "ITER2=1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "THISPART2=SIP/007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:6] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(THISPART2=DAHDI/007)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "NEWDIAL=SIP/007&") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:8] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "ITER2=2") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?begin2") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "THISDIAL=SIP/007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:9] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DSTRING=SIP/007&") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:10] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "ITER=2") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:11] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?begin") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:12] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DSTRING=SIP/007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:27] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?nodial") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:28] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?skiptrace") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:29] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?ctset,1():ctclear,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DB(CALLTRACE/007)=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "D_OPTIONS=Ttr") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:31] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?SIPAddHeader(Alert-Info: )") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:32] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?SIPAddHeader()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:33] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(CHANNEL(musicclass)=)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:34] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?qwait,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__CWIGNORE=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:36] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__KEEPCID=TRUE") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:37] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?usegoto,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:38] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?godial") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-dial-one,s,42)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:42] Dial("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "SIP/007,15,Ttr") in new stack
[2015-04-06 15:10:28] WARNING[3509][C-00000000] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] app_dial.c:   == Everyone is busy/congested at this time (1:0/0/1)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:43] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?MacroExit()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:44] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(DIALSTATUS=)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:45] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?s-CHANUNAVAIL,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:15] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:16] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?docfu,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:17] GosubIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?docfb,1()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:18] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DIALSTATUS=CHANUNAVAIL") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:19] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?MacroExit()") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:20] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?s-CHANUNAVAIL,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:21] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "vm,007,CHANUNAVAIL,") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "user-callerid,SKIPTTL") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "TOUCH_MONITOR=1428358228.0") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?report") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(REALCALLERIDNUM=15033302014)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSERCIDNAME=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?report") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-user-callerid,s,15)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:15] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?continue") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-user-callerid,s,28)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:28] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLERID(number)=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:29] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CALLERID(name)=M CARPENTER") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:30] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(cnum)=15033302014") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:31] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CDR(cnam)=M CARPENTER") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:32] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "CHANNEL(language)=en") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "VMGAIN=""") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "blkvm-check,") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "GOSUB_RETVAL=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?vmx,1") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-vm,vmx,1)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "MEXTEN=007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "MMODE=CHANUNAVAIL") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "RETVM=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "MODE=unavail") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:5] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?chknomsg") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-vm,vmx,7)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?s-CHANUNAVAIL,1") in new stack
"get-vmcontext,007") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "VMCONTEXT=default") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?200:300") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-get-vmcontext,s,300)
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "[email protected],u""") in new stack
[2015-04-06 15:10:29] VERBOSE[3509][C-00000000] file.c:     -- <SIP/fpbx-1-IPjH1RLLAW4E-00000000> Playing 'vm-theperson.ulaw' (language 'en')
[2015-04-06 15:10:30] VERBOSE[3509][C-00000000] file.c:     -- <SIP/fpbx-1-IPjH1RLLAW4E-00000000> Playing 'digits/0.ulaw' (language 'en')
[2015-04-06 15:10:31] VERBOSE[3509][C-00000000] file.c:     -- <SIP/fpbx-1-IPjH1RLLAW4E-00000000> Playing 'digits/0.ulaw' (language 'en')
[2015-04-06 15:10:32] VERBOSE[3509][C-00000000] file.c:     -- <SIP/fpbx-1-IPjH1RLLAW4E-00000000> Playing 'digits/7.ulaw' (language 'en')
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] app_macro.c:   == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000000' in macro 'vm'
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] app_macro.c:   == Spawn extension (macro-exten-vm, s, 21) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000000' in macro 'exten-vm'
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:   == Spawn extension (from-did-direct, 007, 2) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000000'
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "hangupcall,") in new stack
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "1?theend") in new stack
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "0?Set(CDR(recordingfile)=)") in new stack
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [[email protected]:4] Hangup("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] app_macro.c:   == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000000' in macro 'hangupcall'
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:   == Spawn extension (from-did-direct, h, 1) exited non-zero on 'SIP/fpbx-1-IPjH1RLLAW4E-00000000'
[[email protected] ~]# cat /var/log/asterisk/full|grep "[3509]"

from bash:-
rasterisk -x 'voicemail show users’
rasterisk -x ‘sip show peers’

from asterisk:-

sip show peers
voicemail show users

Thanks

[[email protected] ~]# rasterisk -x 'voicemail show users’
Context Mbox User Zone NewMsg
default 008 008 4
default 007 APEX 15
2 voicemail users configured.

[[email protected] ~]# rasterisk -x 'sip show peers’
Name/username Host Dyn Forcerport ACL Port Status Description
007 (Unspecified) D A 0 UNKNOWN
008 (Unspecified) D A 0 UNKNOWN
fpbx-1-IPjH1RLLAW4E/IPjH1 192.159.66.3 N 5060 OK (133 ms)
fpbx-2-IPjH1RLLAW4E/IPjH1 66.243.108.101 N 5060 OK (135 ms)
4 sip peers [Monitored: 2 online, 2 offline Unmonitored: 0 online, 0 offline]

Name/username Host Dyn Forcerport ACL Port Status Description
007 (Unspecified) D A 0 UNKNOWN
008 (Unspecified) D A 0 UNKNOWN
fpbx-1-IPjH1RLLAW4E/IPjH1 192.159.66.3 N 5060 OK (134 ms)
fpbx-2-IPjH1RLLAW4E/IPjH1 66.243.108.101 N 5060 OK (110 ms)
4 sip peers [Monitored: 2 online, 2 offline Unmonitored: 0 online, 0 offline]

Context Mbox User Zone NewMsg
default 008 008 4
default 007 APEX 15
2 voicemail users configured.