[2011-05-17 16:07:32] VERBOSE[32271] netsock.c: == Using UDPTL TOS bits 184
[2011-05-17 16:07:32] VERBOSE[32271] netsock.c: == Using UDPTL CoS mark 5
[2011-05-17 16:07:32] VERBOSE[32271] netsock2.c: == Using SIP RTP TOS bits 184
[2011-05-17 16:07:32] VERBOSE[32271] netsock2.c: == Using SIP RTP CoS mark 5
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:1] Set("SIP/voipms-0000004d", "__FROM_DID=9063790022") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:2] Gosub("SIP/voipms-0000004d", "app-blacklist-check,s,1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/voipms-0000004d", "0?blacklisted") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/voipms-0000004d", "CALLED_BLACKLIST=1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/voipms-0000004d", "") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:3] ExecIf("SIP/voipms-0000004d", "0 ?Set(CALLERID(name)=5174491468)") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:4] Set("SIP/voipms-0000004d", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:5] Set("SIP/voipms-0000004d", "CALLERPRES()=allowed_not_screened") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [9063790022@from-trunk:6] Goto("SIP/voipms-0000004d", "ext-group,600,1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (ext-group,600,1)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:1] Macro("SIP/voipms-0000004d", "user-callerid,") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/voipms-0000004d", "AMPUSER=5174491468") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/voipms-0000004d", "0?report") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/voipms-0000004d", "1?Set(REALCALLERIDNUM=5174491468)") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/voipms-0000004d", "AMPUSER=") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/voipms-0000004d", "AMPUSERCIDNAME=") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/voipms-0000004d", "1?report") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-user-callerid,s,10)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/voipms-0000004d", "0?continue") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/voipms-0000004d", "__TTL=64") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-user-callerid,s,19)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:19] Set("SIP/voipms-0000004d", "CALLERID(number)=5174491468") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:20] Set("SIP/voipms-0000004d", "CALLERID(name)=Mike Cell") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/voipms-0000004d", "Using CallerID "Mike Cell" <5174491468>") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:2] GotoIf("SIP/voipms-0000004d", "1?skipdb") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (ext-group,600,4)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:4] Set("SIP/voipms-0000004d", "__NODEST=") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:5] Set("SIP/voipms-0000004d", "__BLKVM_OVERRIDE=BLKVM/600/SIP/voipms-0000004d") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:6] Set("SIP/voipms-0000004d", "__BLKVM_BASE=600") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:7] Set("SIP/voipms-0000004d", "DB(BLKVM/600/SIP/voipms-0000004d)=TRUE") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:8] Set("SIP/voipms-0000004d", "RRNODEST=") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:9] Set("SIP/voipms-0000004d", "__NODEST=600") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:10] GosubIf("SIP/voipms-0000004d", "0?sub-rgsetcid,s,1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:11] Set("SIP/voipms-0000004d", "RecordMethod=Group") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:12] Macro("SIP/voipms-0000004d", "record-enable,6001,Group") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/voipms-0000004d", "1?check") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,4)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:4] ExecIf("SIP/voipms-0000004d", "0?MacroExit()") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:5] GotoIf("SIP/voipms-0000004d", "1?Group:OUT") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,6)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:6] Set("SIP/voipms-0000004d", "LOOPCNT=1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:7] Set("SIP/voipms-0000004d", "ITER=1") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:8] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,13)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:13] Set("SIP/voipms-0000004d", "ITER=2") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:14] GotoIf("SIP/voipms-0000004d", "0?begin") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:15] GotoIf("SIP/voipms-0000004d", "0?IN") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:16] ExecIf("SIP/voipms-0000004d", "1?MacroExit()") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:13] Set("SIP/voipms-0000004d", "RingGroupMethod=ringall") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:14] Macro("SIP/voipms-0000004d", "dial,30,tr,6001") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/voipms-0000004d", "1?dial") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Goto (macro-dial,s,3)
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/voipms-0000004d", "dialparties.agi") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: dialparties.agi: Caller ID name is 'Mike Cell' number is '517XXXXXXX'
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE'
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: > dialparties.agi: RINGGROUP_INDEX: ''
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- dialparties.agi: Added extension 6001 to extension map
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6001 cf is disabled
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6001 do not disturb is disabled
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: > dialparties.agi: extnum 6001 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6001 to 5174491468
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- dialparties.agi: Filtered ARG3: 6001
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: > dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: trM(auto-blkvm)
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: > dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: trM(auto-blkvm)
[2011-05-17 16:07:32] VERBOSE[5047] res_agi.c: -- <SIP/voipms-0000004d>AGI Script dialparties.agi completed, returning 0
[2011-05-17 16:07:32] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:7] Dial("SIP/voipms-0000004d", "SIP/6001,30,trM(auto-blkvm)") in new stack
[2011-05-17 16:07:32] VERBOSE[5047] netsock.c: == Using UDPTL TOS bits 184
[2011-05-17 16:07:32] VERBOSE[5047] netsock.c: == Using UDPTL CoS mark 5
[2011-05-17 16:07:32] VERBOSE[5047] netsock2.c: == Using SIP RTP TOS bits 184
[2011-05-17 16:07:32] VERBOSE[5047] netsock2.c: == Using SIP RTP CoS mark 5
[2011-05-17 16:07:32] VERBOSE[5047] app_dial.c: -- Called SIP/6001
[2011-05-17 16:07:33] VERBOSE[5047] app_dial.c: -- SIP/6001-0000004e is ringing
[2011-05-17 16:08:02] VERBOSE[5047] app_dial.c: -- Nobody picked up in 30000 ms
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:8] Set("SIP/voipms-0000004d", "DIALSTATUS=NOANSWER") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:9] GosubIf("SIP/voipms-0000004d", "0?NOANSWER,1") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:15] Set("SIP/voipms-0000004d", "RingGroupMethod=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:16] GotoIf("SIP/voipms-0000004d", "0?nodest") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:17] Set("SIP/voipms-0000004d", "__NODEST=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:18] NoOp("SIP/voipms-0000004d", "Deleting: BLKVM/600/SIP/voipms-0000004d TRUE") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [600@ext-group:19] Goto("SIP/voipms-0000004d", "ext-group,601,1") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (ext-group,601,1)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:1] Macro("SIP/voipms-0000004d", "user-callerid,") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/voipms-0000004d", "AMPUSER=5174491468") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/voipms-0000004d", "0?report") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/voipms-0000004d", "0?Set(REALCALLERIDNUM=5174491468)") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/voipms-0000004d", "AMPUSER=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/voipms-0000004d", "AMPUSERCIDNAME=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/voipms-0000004d", "1?report") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-user-callerid,s,10)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/voipms-0000004d", "0?continue") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/voipms-0000004d", "__TTL=63") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-user-callerid,s,19)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:19] Set("SIP/voipms-0000004d", "CALLERID(number)=5174491468") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:20] Set("SIP/voipms-0000004d", "CALLERID(name)=Mike Cell") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/voipms-0000004d", "Using CallerID "Mike Cell" <5174491468>") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:2] GotoIf("SIP/voipms-0000004d", "0?skipdb") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:3] GotoIf("SIP/voipms-0000004d", "0?skipov") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:4] Set("SIP/voipms-0000004d", "__NODEST=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:5] Set("SIP/voipms-0000004d", "__BLKVM_OVERRIDE=BLKVM/601/SIP/voipms-0000004d") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:6] Set("SIP/voipms-0000004d", "__BLKVM_BASE=601") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:7] Set("SIP/voipms-0000004d", "DB(BLKVM/601/SIP/voipms-0000004d)=TRUE") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:8] Set("SIP/voipms-0000004d", "RRNODEST=") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:9] Set("SIP/voipms-0000004d", "__NODEST=601") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:10] GosubIf("SIP/voipms-0000004d", "0?sub-rgsetcid,s,1") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:11] Set("SIP/voipms-0000004d", "RecordMethod=Group") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:12] Macro("SIP/voipms-0000004d", "record-enable,6001-6002-6003,Group") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/voipms-0000004d", "1?check") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,4)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:4] ExecIf("SIP/voipms-0000004d", "0?MacroExit()") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:5] GotoIf("SIP/voipms-0000004d", "1?Group:OUT") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,6)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:6] Set("SIP/voipms-0000004d", "LOOPCNT=3") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:7] Set("SIP/voipms-0000004d", "ITER=1") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:8] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,13)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:13] Set("SIP/voipms-0000004d", "ITER=2") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:14] GotoIf("SIP/voipms-0000004d", "1?begin") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,8)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:8] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,13)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:13] Set("SIP/voipms-0000004d", "ITER=3") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:14] GotoIf("SIP/voipms-0000004d", "1?begin") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,8)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:8] GotoIf("SIP/voipms-0000004d", "1?continue") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-record-enable,s,13)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:13] Set("SIP/voipms-0000004d", "ITER=4") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:14] GotoIf("SIP/voipms-0000004d", "0?begin") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:15] GotoIf("SIP/voipms-0000004d", "0?IN") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-record-enable:16] ExecIf("SIP/voipms-0000004d", "1?MacroExit()") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:13] Set("SIP/voipms-0000004d", "RingGroupMethod=ringall") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:14] Macro("SIP/voipms-0000004d", "dial,20,tr,6001-6002-6003") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/voipms-0000004d", "1?dial") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Goto (macro-dial,s,3)
[2011-05-17 16:08:02] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/voipms-0000004d", "dialparties.agi") in new stack
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: dialparties.agi: Caller ID name is 'Mike Cell' number is '517XXXXXXX'
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE'
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: > dialparties.agi: RINGGROUP_INDEX: ''
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- dialparties.agi: Added extension 6001 to extension map
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- dialparties.agi: Added extension 6002 to extension map
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- dialparties.agi: Added extension 6003 to extension map
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6001 cf is disabled
[2011-05-17 16:08:02] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6002 cf is disabled
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6003 cf is disabled
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6001 do not disturb is disabled
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6002 do not disturb is disabled
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: Extension 6003 do not disturb is disabled
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: > dialparties.agi: extnum 6001 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6001 to 5174491468
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: > dialparties.agi: extnum 6002 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6002 to 5174491468
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: > dialparties.agi: extnum 6003 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: dbset CALLTRACE/6003 to 5174491468
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- dialparties.agi: Filtered ARG3: 6001-6002-6003
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: > dialparties.agi: NODEST: 601 adding M(auto-blkvm) to dialopts: trM(auto-blkvm)
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: > dialparties.agi: NODEST: 601 blkvm enabled macro already in dialopts: trM(auto-blkvm)
[2011-05-17 16:08:03] VERBOSE[5047] res_agi.c: -- <SIP/voipms-0000004d>AGI Script dialparties.agi completed, returning 0
[2011-05-17 16:08:03] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:7] Dial("SIP/voipms-0000004d", "SIP/6001&SIP/6002&SIP/6003,20,trM(auto-blkvm)") in new stack
[2011-05-17 16:08:03] WARNING[5047] app_dial.c: Skipping dialing interface 'SIP/6001' again since it has already been dialed
[2011-05-17 16:08:03] VERBOSE[5047] netsock.c: == Using UDPTL TOS bits 184
[2011-05-17 16:08:03] VERBOSE[5047] netsock.c: == Using UDPTL CoS mark 5
[2011-05-17 16:08:03] VERBOSE[5047] netsock2.c: == Using SIP RTP TOS bits 184
[2011-05-17 16:08:03] VERBOSE[5047] netsock2.c: == Using SIP RTP CoS mark 5
[2011-05-17 16:08:03] VERBOSE[5047] app_dial.c: -- Called SIP/6002
[2011-05-17 16:08:03] VERBOSE[5047] netsock.c: == Using UDPTL TOS bits 184
[2011-05-17 16:08:03] VERBOSE[5047] netsock.c: == Using UDPTL CoS mark 5
[2011-05-17 16:08:03] WARNING[5047] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2011-05-17 16:08:03] VERBOSE[5047] app_dial.c: -- SIP/6002-0000004f is ringing
[2011-05-17 16:08:03] VERBOSE[5047] app_dial.c: -- SIP/6002-0000004f is ringing
[2011-05-17 16:08:23] VERBOSE[5047] app_dial.c: -- Nobody picked up in 20000 ms
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:8] Set("SIP/voipms-0000004d", "DIALSTATUS=NOANSWER") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@macro-dial:9] GosubIf("SIP/voipms-0000004d", "0?NOANSWER,1") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:15] Set("SIP/voipms-0000004d", "RingGroupMethod=") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:16] GotoIf("SIP/voipms-0000004d", "0?nodest") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:17] Set("SIP/voipms-0000004d", "__NODEST=") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:18] NoOp("SIP/voipms-0000004d", "Deleting: BLKVM/601/SIP/voipms-0000004d TRUE") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [601@ext-group:19] Goto("SIP/voipms-0000004d", "ivr-4,s,1") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Goto (ivr-4,s,1)
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:1] Set("SIP/voipms-0000004d", "MSG=custom/Mike-press1cell") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:2] Set("SIP/voipms-0000004d", "LOOPCOUNT=0") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:3] Set("SIP/voipms-0000004d", "__DIR-CONTEXT=default") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:4] Set("SIP/voipms-0000004d", "_IVR_CONTEXT_ivr-4=") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:5] Set("SIP/voipms-0000004d", "_IVR_CONTEXT=ivr-4") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:6] GotoIf("SIP/voipms-0000004d", "0?begin") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:7] Answer("SIP/voipms-0000004d", "") in new stack
[2011-05-17 16:08:23] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:8] Wait("SIP/voipms-0000004d", "1") in new stack
[2011-05-17 16:08:24] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:9] Set("SIP/voipms-0000004d", "TIMEOUT(digit)=3") in new stack
[2011-05-17 16:08:24] VERBOSE[5047] func_timeout.c: -- Digit timeout set to 3.000
[2011-05-17 16:08:24] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:10] Set("SIP/voipms-0000004d", "TIMEOUT(response)=3") in new stack
[2011-05-17 16:08:24] VERBOSE[5047] func_timeout.c: -- Response timeout set to 3.000
[2011-05-17 16:08:24] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:11] Set("SIP/voipms-0000004d", "__IVR_RETVM=") in new stack
[2011-05-17 16:08:24] VERBOSE[5047] pbx.c: -- Executing [s@ivr-4:12] ExecIf("SIP/voipms-0000004d", "1?Background(custom/Mike-press1cell)") in new stack