20 sec delay's on out bound calls

Jeff_504 · April 2, 2015, 1:05am

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

Jeff_504 · April 2, 2015, 1:10am

How would you turn debug and verbose on?

dicko · April 2, 2015, 1:29am

Jeff_504 · April 2, 2015, 3:35am

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

dicko · April 2, 2015, 3:39am

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

Jeff_504 · April 2, 2015, 5:43am

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

dicko · April 2, 2015, 4:23pm

tail -f /var/log/asterisk/full

Jeff_504 · April 2, 2015, 4:47pm

[code][root@localhost ~]# 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 [h@from-did-direct:1] Macro(“SIP/fpbx-1-IPjH1RLLAW4E-00000005”, “hangupcall,”) in new stack
[2015-04-02 09:45:38] VERBOSE[13285][C-00000005] pbx.c: – Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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]

dicko · April 2, 2015, 4:50pm

That’s very far from a complete call.

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

will give you all of that leg

Jeff_504 · April 2, 2015, 5:02pm

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

Jeff_504 · April 2, 2015, 5:03pm

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

Jeff_504 · April 2, 2015, 5:06pm

[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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [s@app-blacklist-check: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 [s@app-blacklist-check: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 [s@app-blacklist-check:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [007@from-did-direct: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 [007@from-did-direct: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 [s@macro-exten-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check:12] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [dstring@macro-dial-one:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "DSTRING=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "NEWDIAL=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [ctset@macro-dial-one: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 [ctset@macro-dial-one:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "__CWIGNORE=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSER=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "AMPUSERCIDNAME=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-vm:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "VMGAIN=""") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-vm: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "RETVM=") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [s-CHANUNAVAIL@macro-vm: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "") in new stack [2015-04-02 09:53:06] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "007@default,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 [h@from-did-direct:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000008", "hangupcall,") in new stack [2015-04-02 09:53:12] VERBOSE[14499][C-00000008] pbx.c: -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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

dicko · April 2, 2015, 6:19pm

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

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

Jeff_504 · April 2, 2015, 9:01pm

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
[root@localhost ~]# cat /var/log/asterisk/full|grep
Usage: grep [OPTION]… PATTERN [FILE]…
Try `grep --help’ for more information.
[root@localhost ~]#

dicko · April 2, 2015, 9:42pm

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

Jeff_504 · April 3, 2015, 7:53pm

[root@localhost ~]# cat /var/log/asterisk/full|grep "\[4630\]" [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [9713179221@from-pstn: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 [9713179221@from-pstn: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 [s@app-blacklist-check: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 [s@app-blacklist-check: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 [s@app-blacklist-check:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [007@from-did-direct: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 [007@from-did-direct: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 [s@macro-exten-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSERCIDNAME=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check: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 [exten@sub-record-check:12] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [dstring@macro-dial-one:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "DSTRING=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "NEWDIAL=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [ctset@macro-dial-one: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 [ctset@macro-dial-one:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "__CWIGNORE=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSER=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "AMPUSERCIDNAME=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-vm:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "VMGAIN=""") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-vm: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "RETVM=") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [s-CHANUNAVAIL@macro-vm: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "") in new stack [2015-04-03 12:44:14] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "007@default,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 [h@from-did-direct:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000003", "hangupcall,") in new stack [2015-04-03 12:44:57] VERBOSE[4630][C-00000003] pbx.c: -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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' [root@localhost ~]#

dicko · April 3, 2015, 9:03pm

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.

Jeff_504 · April 6, 2015, 10:25pm

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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [force@sub-record-check: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 [record@sub-record-check: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 [record@sub-record-check: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 [record@sub-record-check: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 [record@sub-record-check: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 [record@sub-record-check:5] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [force@sub-record-check:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [9713179221@from-pstn: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 [s@app-blacklist-check: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 [s@app-blacklist-check: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 [s@app-blacklist-check:3] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [9713179221@from-pstn: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 [007@from-did-direct: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 [007@from-did-direct: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 [s@macro-exten-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSERCIDNAME=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check:10] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [dstring@macro-dial-one:1] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "DSTRING=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "NEWDIAL=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one: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 [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one: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 [dstring@macro-dial-one:13] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [ctset@macro-dial-one: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 [ctset@macro-dial-one:2] Return("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:35] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "__CWIGNORE=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one: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 [s@macro-dial-one:46] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-exten-vm: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 [s@macro-vm: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSER=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-user-callerid:6] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "AMPUSERCIDNAME=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-vm:2] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "VMGAIN=""") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-vm: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check: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 [s@macro-blkvm-check:3] MacroExit("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm:3] Set("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "RETVM=") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:300] NoOp("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "") in new stack
[2015-04-06 15:10:28] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "007@default,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 [h@from-did-direct:1] Macro("SIP/fpbx-1-IPjH1RLLAW4E-00000000", "hangupcall,") in new stack
[2015-04-06 15:10:33] VERBOSE[3509][C-00000000] pbx.c:     -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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'
[root@localhost ~]# cat /var/log/asterisk/full|grep "[3509]"

dicko · April 6, 2015, 10:31pm

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

from asterisk:-

sip show peers
voicemail show users

Jeff_504 · April 6, 2015, 11:10pm

Thanks

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

[root@localhost ~]# 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.