Outbound call always disconnects on transfer / park-pick up

justinjack · May 19, 2012, 9:16pm

I don’t know what’s going on. When a caller calls IN, no problem, I can transfer, park the call, pick it up, anything, but when I call out from a softphone, to my cell phone. Then I transfer (via ##, or send REFER sip msg, or ANYTHING), the call drops and both clients are notified of the disconnection. A reason 410 (Gone) on the client initialing the transfer, and a 487 (Request Terminated) on the Rx end. I’ve never posted a log before, but from what I’ve read people are always asking for them, so I went to Report->Asterisk Logfiles and copied the last 100 lines (that test call was the last activity). Anyways, please asterisk / freepbx guru’s help with this I’m trying hard to understand how all this works, and it’s a lot of fun- usually, but this one has me stumped!

[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:2] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “RingGroupMethod=none”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:3] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__EXTTOCALL=004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:4] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__PICKUPMARK=004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:5] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “RT=15”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:6] Gosub(“SIP/fpbx-1-aa4a4f2c-00000001”, “sub-record-check,s,1(exten,004,)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:1] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?check”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:2] ResetCDR(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:3] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?check”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (sub-record-check,s,6)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:6] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__MON_FMT=wav”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:7] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?next”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (sub-record-check,s,10)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:10] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Return()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@sub-record-check:11] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?exten,1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (sub-record-check,exten,1)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:1] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?callee”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:2] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__REC_POLICY_MODE=dontcare”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:3] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?caller”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (sub-record-check,exten,10)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:10] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “REC_POLICY_MODE=”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:11] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?record,1(exten,004,unknown)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [exten@sub-record-check:12] Return(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:7] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?macrodial”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (macro-exten-vm,s,13)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:13] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?clrheader,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-exten-vm:14] Macro(“SIP/fpbx-1-aa4a4f2c-00000001”, “dial-one,15,Ttr,004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:1] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DEXTEN=004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:2] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DIALSTATUS_CW=”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:3] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?screen,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:4] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?cf,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:5] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?skip1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (macro-dial-one,s,8)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:8] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?nodial”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:9] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?continue”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:10] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “EXTHASCW=ENABLED”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:11] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?next1:cwinusebusy”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (macro-dial-one,s,23)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:23] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?next3:continue”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (macro-dial-one,s,24)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:24] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:25] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?nodial”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:26] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?dstring,1():dlocal,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:1] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DSTRING=”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:2] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DEVICES=004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:3] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Return()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:4] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Set(DEVICES=04)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:5] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “LOOPCNT=1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:6] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “ITER=1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:7] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “THISDIAL=SIP/004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:8] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?zap2dahdi,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Return()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “NEWDIAL=”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “LOOPCNT2=1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “ITER2=1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “THISPART2=SIP/004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Set(THISPART2=DAHDI/004)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “NEWDIAL=SIP/004&”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “ITER2=2”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?begin2”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “THISDIAL=SIP/004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:9] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DSTRING=SIP/004&”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:10] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “ITER=2”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:11] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?begin”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:12] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DSTRING=SIP/004”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [dstring@macro-dial-one:13] Return(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:27] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?nodial”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:28] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?skiptrace”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:29] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?ctset,1():ctclear,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [ctset@macro-dial-one:1] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “DB(CALLTRACE/004)=9402557773”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [ctset@macro-dial-one:2] Return(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:30] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “D_OPTIONS=Ttr”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:31] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:32] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?SIPAddHeader()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:33] ExecIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?Set(CHANNEL(musicclass)=)”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:34] GosubIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?qwait,1()”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:35] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__CWIGNORE=”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:36] Set(“SIP/fpbx-1-aa4a4f2c-00000001”, “__KEEPCID=TRUE”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:37] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “0?usegoto,1”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:38] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?godial”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Goto (macro-dial-one,s,42)
[2012-05-19 16:06:52] VERBOSE[-1] pbx.c: – Executing [s@macro-dial-one:42] Dial(“SIP/fpbx-1-aa4a4f2c-00000001”, “SIP/004,15,Ttr”) in new stack
[2012-05-19 16:06:52] VERBOSE[-1] netsock2.c: == Using SIP RTP TOS bits 184
[2012-05-19 16:06:52] VERBOSE[-1] netsock2.c: == Using SIP RTP CoS mark 5
[2012-05-19 16:06:52] VERBOSE[-1] app_dial.c: – Called SIP/004
[2012-05-19 16:06:53] VERBOSE[-1] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/fpbx-1-aa4a4f2c-00000001’ in macro ‘dial-one’
[2012-05-19 16:06:53] VERBOSE[-1] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/fpbx-1-aa4a4f2c-00000001’ in macro ‘exten-vm’
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: == Spawn extension (from-internal-xfer, 004, 2) exited non-zero on ‘SIP/fpbx-1-aa4a4f2c-00000001’
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: – Executing [h@from-internal-xfer:1] Macro(“SIP/fpbx-1-aa4a4f2c-00000001”, “hangupcall”) in new stack
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/fpbx-1-aa4a4f2c-00000001”, “1?theend”) in new stack
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: – Goto (macro-hangupcall,s,3)
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:3] Hangup(“SIP/fpbx-1-aa4a4f2c-00000001”, “”) in new stack
[2012-05-19 16:06:53] VERBOSE[-1] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/fpbx-1-aa4a4f2c-00000001’ in macro ‘hangupcall’
[2012-05-19 16:06:53] VERBOSE[-1] pbx.c: == Spawn extension (from-internal-xfer, h, 1) exited non-zero on ‘SIP/fpbx-1-aa4a4f2c-00000001’
[2012-05-19 16:07:23] VERBOSE[-1] asterisk.c: – Remote UNIX connection
[2012-05-19 16:07:23] VERBOSE[-1] asterisk.c: – Remote UNIX connection disconnected
[2012-05-19 16:07:26] VERBOSE[-1] asterisk.c: – Remote UNIX connection
[2012-05-19 16:07:26] VERBOSE[-1] asterisk.c: – Remote UNIX connection disconnected
[2012-05-19 16:08:01] VERBOSE[-1] asterisk.c: – Remote UNIX connection
[2012-05-19 16:08:01] VERBOSE[-1] asterisk.c: – Remote UNIX connection disconnected

cosmicwombat · May 20, 2012, 1:28pm

Maybe I am getting rusty as I do not see any indicators of cause -or- we don’t have enough data. That and you left plenty to assume such as is this a FreePBX ISO Based system and if so which version of Asterisk and FreePBX are you running ?

So, ssh into your PBX and do a asterisk -rx “core set verbose 5” -or- asterisk -rx “core set verbose 10” and then perhaps do a tail -f /var/log/asterisk/full so you can gather some more data.

CONTROL-C will end the tail and I would suggest turning the verbosity back down with asterisk -rx “core set verbose 3”

NOTE - the “blah” in --> asterisk -rx “core set verbose 5” is required.

justinjack · May 19, 2012, 9:17pm

sorry, i didn’t put the log output in the right spot.

justinjack · May 20, 2012, 4:43pm

Asterisk v. 1.8.12.0 (originally 1.8.10 with distro CD)
CentOS v 5.7
FreePBX v 2.10.0.7

I used a distro ISO to install this; I updated asterisk using the auto-update scripts on this website trying to see if this was an asterisk bug that may have been fixed with the updates, but no…same problem.

Yup, it does it every time. All I did was create a call to a cell phone from extension 002. When the cell phone answered, my softphone (written with the pjsip lib) did a REFER to 004. I heard music on the cellphone for a second, then beep the cell phone disconnected and the 004 softphone showed a disconnect.
This acts the same with two other softphones: Ekiga, and one android job I downloaded for the cell phone.


[2012-05-20 11:21:53] VERBOSE[-1] asterisk.c:     -- Remote UNIX connection
[2012-05-20 11:21:53] VERBOSE[-1] asterisk.c:     -- Remote UNIX connection disconnected
[2012-05-20 11:22:40] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-05-20 11:22:42] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:24:25] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-05-20 11:24:27] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:25:21] ERROR[-1] sip/reqresp_parser.c: can not parse name and number from sip header.
[2012-05-20 11:25:21] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:25:21] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:1] SIPAddHeader("SIP/002-00000011", "P-Asserted-Identity: <[email protected]>") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:2] Set("SIP/002-00000011", "MOHCLASS=default") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:3] ExecIf("SIP/002-00000011", "1?Set(TRUNKCIDOVERRIDE=8175726610)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:4] Set("SIP/002-00000011", "_NODEST=") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:5] Gosub("SIP/002-00000011", "sub-record-check,s,1(out,9402557773,)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:1] GotoIf("SIP/002-00000011", "1?check") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,6)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:6] Set("SIP/002-00000011", "__MON_FMT=wav") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:7] GotoIf("SIP/002-00000011", "1?next") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,10)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:10] ExecIf("SIP/002-00000011", "0?Return()") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:11] GotoIf("SIP/002-00000011", "0?out,1") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:12] Set("SIP/002-00000011", "__REC_STATUS=INITIALIZED") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:13] ExecIf("SIP/002-00000011", "0?Set(__REC_POLICY_MODE=)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:14] Set("SIP/002-00000011", "NOW=1337531121") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:15] Set("SIP/002-00000011", "__DAY=20") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:16] Set("SIP/002-00000011", "__MONTH=05") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:17] Set("SIP/002-00000011", "__YEAR=2012") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:18] Set("SIP/002-00000011", "__TIMESTR=20120520-112521") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:19] Set("SIP/002-00000011", "__FROMEXTEN=unknown") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:20] Set("SIP/002-00000011", "__CALLFILENAME=out-9402557773-unknown-20120520-112521-1337531121.20") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:21] Goto("SIP/002-00000011", "out,1") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,out,1)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:1] ExecIf("SIP/002-00000011", "1?Set(__REC_POLICY_MODE=)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:2] GosubIf("SIP/002-00000011", "0?record,1(exten,9402557773,unknown)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:3] Return("SIP/002-00000011", "") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:6] Macro("SIP/002-00000011", "dialout-trunk,2,9402557773,") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/002-00000011", "DIAL_TRUNK=2") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/002-00000011", "0?sub-pincheck,s,1()") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/002-00000011", "0?disabletrunk,1") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/002-00000011", "DIAL_NUMBER=9402557773") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/002-00000011", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/002-00000011", "OUTBOUND_GROUP=OUT_2") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/002-00000011", "1?nomax") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/002-00000011", "0?skipoutcid") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/002-00000011", "DIAL_TRUNK_OPTIONS=TtW") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/002-00000011", "outbound-callerid,2") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/002-00000011", "0?Set(CALLERPRES()=)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/002-00000011", "1?Set(REALCALLERIDNUM=002)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/002-00000011", "1?normcid") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/002-00000011", "USEROUTCID=") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/002-00000011", "EMERGENCYCID=") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/002-00000011", "TRUNKOUTCID=9405315042") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/002-00000011", "1?trunkcid") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/002-00000011", "1?Set(CALLERID(all)=9405315042)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/002-00000011", "0?Set(CALLERID(all)=)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/002-00000011", "1?Set(CALLERID(all)=8175726610)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/002-00000011", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/002-00000011", "0?sub-flp-2,s,1()") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/002-00000011", "OUTNUM=9402557773") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/002-00000011", "custom=SIP/fpbx-1-aa4a4f2c") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/002-00000011", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)TtW)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/002-00000011", "0?Set(DIAL_TRUNK_OPTIONS=TtWM(confirm))") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/002-00000011", "dialout-trunk-predial-hook,") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/002-00000011", "") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/002-00000011", "0?bypass,1") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/002-00000011", "0?Set(CONNECTEDLINE(num,i)=9402557773)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/002-00000011", "0?Set(CONNECTEDLINE(name,i)=CID:8175726610)") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/002-00000011", "0?customtrunk") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/002-00000011", "SIP/fpbx-1-aa4a4f2c/9402557773,300,TtW") in new stack
[2012-05-20 11:25:21] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:25:21] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:25:21] VERBOSE[-1] app_dial.c:     -- Called SIP/fpbx-1-aa4a4f2c/9402557773
[2012-05-20 11:25:23] VERBOSE[-1] app_dial.c:     -- SIP/fpbx-1-aa4a4f2c-00000012 is making progress passing it to SIP/002-00000011
[2012-05-20 11:25:38] VERBOSE[-1] app_dial.c:     -- SIP/fpbx-1-aa4a4f2c-00000012 answered SIP/002-00000011
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [h@macro-dialout-trunk:1] Macro("SIP/002-00000011", "hangupcall,") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/002-00000011", "1?theend") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/002-00000011", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/002-00000011' in macro 'hangupcall'
[2012-05-20 11:25:46] VERBOSE[-1] features.c:   == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/002-00000011'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [004@from-internal-xfer:1] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__RINGTIMER=15") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [004@from-internal-xfer:2] Macro("SIP/fpbx-1-aa4a4f2c-00000012", "exten-vm,004,004,0,0,0") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/fpbx-1-aa4a4f2c-00000012", "user-callerid,") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-1-aa4a4f2c-00000012", "AMPUSER=9402557773") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?report") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?Set(REALCALLERIDNUM=9402557773)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-1-aa4a4f2c-00000012", "AMPUSER=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-1-aa4a4f2c-00000012", "AMPUSERCIDNAME=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?report") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-user-callerid,s,13)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?continue") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:14] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__TTL=64") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:15] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?continue") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-user-callerid,s,26)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:26] Set("SIP/fpbx-1-aa4a4f2c-00000012", "CALLERID(number)=9402557773") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:27] Set("SIP/fpbx-1-aa4a4f2c-00000012", "CALLERID(name)=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:28] Set("SIP/fpbx-1-aa4a4f2c-00000012", "CHANNEL(language)=en") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/fpbx-1-aa4a4f2c-00000012", "RingGroupMethod=none") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__EXTTOCALL=004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__PICKUPMARK=004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/fpbx-1-aa4a4f2c-00000012", "RT=15") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:6] Gosub("SIP/fpbx-1-aa4a4f2c-00000012", "sub-record-check,s,1(exten,004,)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?check") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:2] ResetCDR("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:3] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?check") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,6)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:6] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__MON_FMT=wav") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:7] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?next") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,10)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:10] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Return()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?exten,1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,exten,1)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?callee") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:2] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__REC_POLICY_MODE=dontcare") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:3] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?caller") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,exten,10)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:10] Set("SIP/fpbx-1-aa4a4f2c-00000012", "REC_POLICY_MODE=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:11] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?record,1(exten,004,unknown)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:12] Return("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/002-00000011' in macro 'dialout-trunk'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal, 9402557773, 6) exited non-zero on 'SIP/002-00000011'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:7] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?macrodial") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-exten-vm,s,13)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?clrheader,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:14] Macro("SIP/fpbx-1-aa4a4f2c-00000012", "dial-one,15,Ttr,004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DEXTEN=004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DIALSTATUS_CW=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:3] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?screen,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:4] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?cf,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:5] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?skip1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,8)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:8] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?nodial") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:9] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?continue") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000012", "EXTHASCW=ENABLED") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?next1:cwinusebusy") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,23)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:23] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?next3:continue") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,24)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:24] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:25] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?nodial") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:26] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?dstring,1():dlocal,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DSTRING=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DEVICES=004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Return()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Set(DEVICES=04)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:5] Set("SIP/fpbx-1-aa4a4f2c-00000012", "LOOPCNT=1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:6] Set("SIP/fpbx-1-aa4a4f2c-00000012", "ITER=1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:7] Set("SIP/fpbx-1-aa4a4f2c-00000012", "THISDIAL=SIP/004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?zap2dahdi,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Return()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000012", "NEWDIAL=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/fpbx-1-aa4a4f2c-00000012", "LOOPCNT2=1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/fpbx-1-aa4a4f2c-00000012", "ITER2=1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/fpbx-1-aa4a4f2c-00000012", "THISPART2=SIP/004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Set(THISPART2=DAHDI/004)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/fpbx-1-aa4a4f2c-00000012", "NEWDIAL=SIP/004&") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/fpbx-1-aa4a4f2c-00000012", "ITER2=2") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?begin2") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000012", "THISDIAL=SIP/004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:9] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DSTRING=SIP/004&") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000012", "ITER=2") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?begin") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:12] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DSTRING=SIP/004") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:13] Return("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:27] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?nodial") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:28] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?skiptrace") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:29] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?ctset,1():ctclear,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [ctset@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000012", "DB(CALLTRACE/004)=9402557773") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [ctset@macro-dial-one:2] Return("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:30] Set("SIP/fpbx-1-aa4a4f2c-00000012", "D_OPTIONS=Ttr") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:31] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?SIPAddHeader(Alert-Info: )") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:32] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?SIPAddHeader()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:33] ExecIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?Set(CHANNEL(musicclass)=)") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:34] GosubIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?qwait,1()") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:35] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__CWIGNORE=") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:36] Set("SIP/fpbx-1-aa4a4f2c-00000012", "__KEEPCID=TRUE") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:37] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "0?usegoto,1") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:38] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?godial") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,42)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:42] Dial("SIP/fpbx-1-aa4a4f2c-00000012", "SIP/004,15,Ttr") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:25:46] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:25:46] VERBOSE[-1] app_dial.c:     -- Called SIP/004
[2012-05-20 11:25:46] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-dial-one, s, 42) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000012' in macro 'dial-one'
[2012-05-20 11:25:46] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000012' in macro 'exten-vm'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal-xfer, 004, 2) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000012'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [h@from-internal-xfer:1] Macro("SIP/fpbx-1-aa4a4f2c-00000012", "hangupcall") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000012", "1?theend") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/fpbx-1-aa4a4f2c-00000012", "") in new stack
[2012-05-20 11:25:46] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000012' in macro 'hangupcall'
[2012-05-20 11:25:46] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal-xfer, h, 1) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000012'
[2012-05-20 11:26:10] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-05-20 11:26:12] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:26:57] NOTICE[-1] chan_sip.c: Peer 'fpbx-2-aa4a4f2c' is now UNREACHABLE!  Last qualify: 34
[2012-05-20 11:27:02] ERROR[-1] sip/reqresp_parser.c: can not parse name and number from sip header.
[2012-05-20 11:27:02] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:27:02] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:1] SIPAddHeader("SIP/002-00000014", "P-Asserted-Identity: <[email protected]>") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:2] Set("SIP/002-00000014", "MOHCLASS=default") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:3] ExecIf("SIP/002-00000014", "1?Set(TRUNKCIDOVERRIDE=8175726610)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:4] Set("SIP/002-00000014", "_NODEST=") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:5] Gosub("SIP/002-00000014", "sub-record-check,s,1(out,9402557773,)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:1] GotoIf("SIP/002-00000014", "1?check") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,6)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:6] Set("SIP/002-00000014", "__MON_FMT=wav") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:7] GotoIf("SIP/002-00000014", "1?next") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,10)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:10] ExecIf("SIP/002-00000014", "0?Return()") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:11] GotoIf("SIP/002-00000014", "0?out,1") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:12] Set("SIP/002-00000014", "__REC_STATUS=INITIALIZED") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:13] ExecIf("SIP/002-00000014", "0?Set(__REC_POLICY_MODE=)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:14] Set("SIP/002-00000014", "NOW=1337531222") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:15] Set("SIP/002-00000014", "__DAY=20") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:16] Set("SIP/002-00000014", "__MONTH=05") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:17] Set("SIP/002-00000014", "__YEAR=2012") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:18] Set("SIP/002-00000014", "__TIMESTR=20120520-112702") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:19] Set("SIP/002-00000014", "__FROMEXTEN=unknown") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:20] Set("SIP/002-00000014", "__CALLFILENAME=out-9402557773-unknown-20120520-112702-1337531222.24") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:21] Goto("SIP/002-00000014", "out,1") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,out,1)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:1] ExecIf("SIP/002-00000014", "1?Set(__REC_POLICY_MODE=)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:2] GosubIf("SIP/002-00000014", "0?record,1(exten,9402557773,unknown)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [out@sub-record-check:3] Return("SIP/002-00000014", "") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [9402557773@from-internal:6] Macro("SIP/002-00000014", "dialout-trunk,2,9402557773,") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/002-00000014", "DIAL_TRUNK=2") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/002-00000014", "0?sub-pincheck,s,1()") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/002-00000014", "0?disabletrunk,1") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/002-00000014", "DIAL_NUMBER=9402557773") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/002-00000014", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/002-00000014", "OUTBOUND_GROUP=OUT_2") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/002-00000014", "1?nomax") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/002-00000014", "0?skipoutcid") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/002-00000014", "DIAL_TRUNK_OPTIONS=TtW") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/002-00000014", "outbound-callerid,2") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/002-00000014", "0?Set(CALLERPRES()=)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/002-00000014", "1?Set(REALCALLERIDNUM=002)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/002-00000014", "1?normcid") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/002-00000014", "USEROUTCID=") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/002-00000014", "EMERGENCYCID=") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/002-00000014", "TRUNKOUTCID=9405315042") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/002-00000014", "1?trunkcid") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/002-00000014", "1?Set(CALLERID(all)=9405315042)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/002-00000014", "0?Set(CALLERID(all)=)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/002-00000014", "1?Set(CALLERID(all)=8175726610)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/002-00000014", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/002-00000014", "0?sub-flp-2,s,1()") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/002-00000014", "OUTNUM=9402557773") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/002-00000014", "custom=SIP/fpbx-1-aa4a4f2c") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/002-00000014", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)TtW)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/002-00000014", "0?Set(DIAL_TRUNK_OPTIONS=TtWM(confirm))") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/002-00000014", "dialout-trunk-predial-hook,") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/002-00000014", "") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/002-00000014", "0?bypass,1") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/002-00000014", "0?Set(CONNECTEDLINE(num,i)=9402557773)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/002-00000014", "0?Set(CONNECTEDLINE(name,i)=CID:8175726610)") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/002-00000014", "0?customtrunk") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/002-00000014", "SIP/fpbx-1-aa4a4f2c/9402557773,300,TtW") in new stack
[2012-05-20 11:27:02] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:27:02] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:27:02] VERBOSE[-1] app_dial.c:     -- Called SIP/fpbx-1-aa4a4f2c/9402557773
[2012-05-20 11:27:04] VERBOSE[-1] app_dial.c:     -- SIP/fpbx-1-aa4a4f2c-00000015 is making progress passing it to SIP/002-00000014
[2012-05-20 11:27:12] VERBOSE[-1] app_dial.c:     -- SIP/fpbx-1-aa4a4f2c-00000015 answered SIP/002-00000014
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [h@macro-dialout-trunk:1] Macro("SIP/002-00000014", "hangupcall,") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/002-00000014", "1?theend") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/002-00000014", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/002-00000014' in macro 'hangupcall'
[2012-05-20 11:27:19] VERBOSE[-1] features.c:   == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/002-00000014'
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [004@from-internal-xfer:1] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__RINGTIMER=15") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/002-00000014' in macro 'dialout-trunk'
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal, 9402557773, 6) exited non-zero on 'SIP/002-00000014'
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [004@from-internal-xfer:2] Macro("SIP/fpbx-1-aa4a4f2c-00000015", "exten-vm,004,004,0,0,0") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/fpbx-1-aa4a4f2c-00000015", "user-callerid,") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/fpbx-1-aa4a4f2c-00000015", "AMPUSER=9402557773") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?report") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?Set(REALCALLERIDNUM=9402557773)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/fpbx-1-aa4a4f2c-00000015", "AMPUSER=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/fpbx-1-aa4a4f2c-00000015", "AMPUSERCIDNAME=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?report") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-user-callerid,s,13)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:13] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?continue") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:14] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__TTL=64") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:15] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?continue") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-user-callerid,s,26)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:26] Set("SIP/fpbx-1-aa4a4f2c-00000015", "CALLERID(number)=9402557773") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:27] Set("SIP/fpbx-1-aa4a4f2c-00000015", "CALLERID(name)=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-user-callerid:28] Set("SIP/fpbx-1-aa4a4f2c-00000015", "CHANNEL(language)=en") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/fpbx-1-aa4a4f2c-00000015", "RingGroupMethod=none") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__EXTTOCALL=004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__PICKUPMARK=004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/fpbx-1-aa4a4f2c-00000015", "RT=15") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:6] Gosub("SIP/fpbx-1-aa4a4f2c-00000015", "sub-record-check,s,1(exten,004,)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?check") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:2] ResetCDR("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:3] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?check") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,6)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:6] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__MON_FMT=wav") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:7] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?next") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,s,10)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:10] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Return()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@sub-record-check:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?exten,1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,exten,1)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?callee") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:2] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__REC_POLICY_MODE=dontcare") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:3] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?caller") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (sub-record-check,exten,10)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:10] Set("SIP/fpbx-1-aa4a4f2c-00000015", "REC_POLICY_MODE=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:11] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?record,1(exten,004,unknown)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [exten@sub-record-check:12] Return("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:7] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?macrodial") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-exten-vm,s,13)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?clrheader,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-exten-vm:14] Macro("SIP/fpbx-1-aa4a4f2c-00000015", "dial-one,15,Ttr,004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DEXTEN=004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DIALSTATUS_CW=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:3] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?screen,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:4] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?cf,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:5] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?skip1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,8)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:8] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?nodial") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:9] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?continue") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000015", "EXTHASCW=ENABLED") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?next1:cwinusebusy") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,23)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:23] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?next3:continue") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,24)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:24] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:25] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?nodial") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:26] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?dstring,1():dlocal,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DSTRING=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DEVICES=004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Return()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:4] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Set(DEVICES=04)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:5] Set("SIP/fpbx-1-aa4a4f2c-00000015", "LOOPCNT=1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:6] Set("SIP/fpbx-1-aa4a4f2c-00000015", "ITER=1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:7] Set("SIP/fpbx-1-aa4a4f2c-00000015", "THISDIAL=SIP/004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:8] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?zap2dahdi,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Return()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:2] Set("SIP/fpbx-1-aa4a4f2c-00000015", "NEWDIAL=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:3] Set("SIP/fpbx-1-aa4a4f2c-00000015", "LOOPCNT2=1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:4] Set("SIP/fpbx-1-aa4a4f2c-00000015", "ITER2=1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:5] Set("SIP/fpbx-1-aa4a4f2c-00000015", "THISPART2=SIP/004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Set(THISPART2=DAHDI/004)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:7] Set("SIP/fpbx-1-aa4a4f2c-00000015", "NEWDIAL=SIP/004&") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:8] Set("SIP/fpbx-1-aa4a4f2c-00000015", "ITER2=2") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?begin2") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000015", "THISDIAL=SIP/004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [zap2dahdi@macro-dial-one:11] Return("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:9] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DSTRING=SIP/004&") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:10] Set("SIP/fpbx-1-aa4a4f2c-00000015", "ITER=2") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:11] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?begin") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:12] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DSTRING=SIP/004") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [dstring@macro-dial-one:13] Return("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:27] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?nodial") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:28] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?skiptrace") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:29] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?ctset,1():ctclear,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [ctset@macro-dial-one:1] Set("SIP/fpbx-1-aa4a4f2c-00000015", "DB(CALLTRACE/004)=9402557773") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [ctset@macro-dial-one:2] Return("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:30] Set("SIP/fpbx-1-aa4a4f2c-00000015", "D_OPTIONS=Ttr") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:31] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?SIPAddHeader(Alert-Info: )") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:32] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?SIPAddHeader()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:33] ExecIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?Set(CHANNEL(musicclass)=)") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:34] GosubIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?qwait,1()") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:35] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__CWIGNORE=") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:36] Set("SIP/fpbx-1-aa4a4f2c-00000015", "__KEEPCID=TRUE") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:37] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "0?usegoto,1") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:38] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?godial") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Goto (macro-dial-one,s,42)
[2012-05-20 11:27:19] VERBOSE[-1] pbx.c:     -- Executing [s@macro-dial-one:42] Dial("SIP/fpbx-1-aa4a4f2c-00000015", "SIP/004,15,Ttr") in new stack
[2012-05-20 11:27:19] VERBOSE[-1] netsock2.c:   == Using SIP RTP TOS bits 184
[2012-05-20 11:27:19] VERBOSE[-1] netsock2.c:   == Using SIP RTP CoS mark 5
[2012-05-20 11:27:19] VERBOSE[-1] app_dial.c:     -- Called SIP/004
[2012-05-20 11:27:20] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-dial-one, s, 42) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000015' in macro 'dial-one'
[2012-05-20 11:27:20] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000015' in macro 'exten-vm'
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal-xfer, 004, 2) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000015'
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:     -- Executing [h@from-internal-xfer:1] Macro("SIP/fpbx-1-aa4a4f2c-00000015", "hangupcall") in new stack
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/fpbx-1-aa4a4f2c-00000015", "1?theend") in new stack
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/fpbx-1-aa4a4f2c-00000015", "") in new stack
[2012-05-20 11:27:20] VERBOSE[-1] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000015' in macro 'hangupcall'
[2012-05-20 11:27:20] VERBOSE[-1] pbx.c:   == Spawn extension (from-internal-xfer, h, 1) exited non-zero on 'SIP/fpbx-1-aa4a4f2c-00000015'
[2012-05-20 11:27:21] NOTICE[-1] chan_sip.c: Peer 'fpbx-2-aa4a4f2c' is now Reachable. (33ms / 2000ms)
[2012-05-20 11:27:55] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-05-20 11:27:57] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:29:26] NOTICE[-1] chan_sip.c: Peer 'fpbx-2-aa4a4f2c' is now UNREACHABLE!  Last qualify: 1144
[2012-05-20 11:29:40] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk1.phonebooth.net'
[2012-05-20 11:29:48] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:30:08] VERBOSE[-1] dnsmgr.c:        > doing dnsmgr_lookup for 'trunk2.phonebooth.net'
[2012-05-20 11:30:08] NOTICE[-1] chan_sip.c:    -- Registration for '[email protected]' timed out, trying again (Attempt #1)

SkykingOH · May 20, 2012, 5:43pm

Ok, first, while we certainly appreciate you formatting your logs so they can be ready, they are getting too long for a forum thread. Use pastebin.ca please and put the links in your posts.

My opinion is this is not a dial plan issue and that’s all that the verbosity displays. My opinion is this is a SIP problem.

Turn off the verbosity (so it doesn’t clutter stuff up) with ‘core set verbose 0’ then turn on sip debug ‘sip set debug peer xxx’ where xxx is the IP address of the device that is being disconnected.

This is not an easy thing to debug via forum messages.

justinjack · May 21, 2012, 12:49am

What would the ip address of the cell phone be? sip:(cell number)@PBX-ipadress? Or the ip/url of the trunk? What is that talk at the end of the dial plan about hanging up?