FollowMe Sent Direct to VM

General Help
1

I am running;
FreePbx Distro: 1.812.210.58-1,
Core: 2.10.0.8,
FollowMe: 2.10.0.8.
Asterisk: 1.8.12.0

Recently have begun to have issues with FollowMe being sent directly to the users voicemail, without ringing either the primary or secondary extensions.

Around May 25th I updated some modules; however, I am unsure which modules they were now. Prior to the update the FollowMe option worked as expected.

In the Asterisk output below, I made a call from 322 to 309. 309 is an internal extension which is registered with Asterisk. It has a FollowMe configuration of Initial Ring Time of 10s, Ring Strategy ringallv2, FollowMe list of 309 and 3010. 3010 is a softphone which is not currently registered.

Upon placing a call to ext 309 I am sent directly to voicemail; ext 309 is not rung at all. DND is disable on the 309 extension. And the extension rings as expected when FollowMe is disabled.

Any ideas?

[2012-06-05 09:38:15] VERBOSE[2492] netsock2.c: == Using SIP RTP TOS bits 184 [2012-06-05 09:38:15] VERBOSE[2492] netsock2.c: == Using SIP RTP CoS mark 5 [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:1] GotoIf("SIP/322-00000349", "0?ext-local,309,1") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:2] Macro("SIP/322-00000349", "user-callerid,") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/322-00000349", "AMPUSER=322") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/322-00000349", "0?report") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/322-00000349", "1?Set(REALCALLERIDNUM=322)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/322-00000349", "AMPUSER=322") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/322-00000349", "AMPUSERCIDNAME=Nathan") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/322-00000349", "0?report") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/322-00000349", "AMPUSERCID=322") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/322-00000349", "CALLERID(all)="Nathan" <322>") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/322-00000349", "0?limit") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/322-00000349", "0?Set(GROUP(concurrency_limit)=322)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/322-00000349", "7?sub-ccss,s,1(from-internal,309)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/322-00000349", "0?Return()") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/322-00000349", "CCSS_SETUP=TRUE") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/322-00000349", "0?monitor_config,1(from-internal,309):monitor_default,1(from-internal,309)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/322-00000349", "1?is_exten") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (sub-ccss,monitor_default,4) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [monitor_default@sub-ccss:4] Set("SIP/322-00000349", "CALLCOMPLETION(cc_monitor_policy)=generic") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [monitor_default@sub-ccss:5] Set("SIP/322-00000349", "CALLCOMPLETION(cc_max_monitors)=5") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [monitor_default@sub-ccss:6] Return("SIP/322-00000349", "TRUE") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:4] GosubIf("SIP/322-00000349", "7?agent_config,1():agent_default,1()") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:1] Set("SIP/322-00000349", "CALLCOMPLETION(cc_agent_policy)=generic") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:2] Set("SIP/322-00000349", "CALLCOMPLETION(cc_offer_timer)=30") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:3] Set("SIP/322-00000349", "CALLCOMPLETION(ccbs_available_timer)=") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:4] Set("SIP/322-00000349", "CALLCOMPLETION(ccnr_available_timer)=") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:5] Set("SIP/322-00000349", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:6] ExecIf("SIP/322-00000349", "1?Set(CALLCOMPLETION(cc_recall_timer)=)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:7] ExecIf("SIP/322-00000349", "1?Set(CALLCOMPLETION(cc_max_agents)=)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:8] ExecIf("SIP/322-00000349", "0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/322_309@from-ccss-)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:9] Set("SIP/322-00000349", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [agent_config@sub-ccss:10] Return("SIP/322-00000349", "") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:5] Set("SIP/322-00000349", "DB(AMPUSER/322/ccss/last_number)=309") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-ccss:6] Return("SIP/322-00000349", "") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/322-00000349", "0?Set(CHANNEL(language)=)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/322-00000349", "0?continue") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:14] Set("SIP/322-00000349", "__TTL=64") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/322-00000349", "1?continue") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (macro-user-callerid,s,26) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/322-00000349", "CALLERID(number)=322") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/322-00000349", "CALLERID(name)=Nathan") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/322-00000349", "CHANNEL(language)=en") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:3] Set("SIP/322-00000349", "DIAL_OPTIONS=trWwI") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:4] Set("SIP/322-00000349", "CONNECTEDLINE(num)=309") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:5] Set("SIP/322-00000349", "CONNECTEDLINE(name,i)=Mark Kresge") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:6] Set("SIP/322-00000349", "FM_DIALSTATUS=NOT_INUSE") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:7] Set("SIP/322-00000349", "__EXTTOCALL=309") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:8] Set("SIP/322-00000349", "__PICKUPMARK=309") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:9] Macro("SIP/322-00000349", "blkvm-setifempty,") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/322-00000349", "1?init") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (macro-blkvm-setifempty,s,4) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/322-00000349", "__BLKVM_CHANNEL=SIP/322-00000349") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/322-00000349", "SHARED(BLKVM,SIP/322-00000349)=TRUE") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/322-00000349", "GOSUB_RETVAL=TRUE") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/322-00000349", "") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:10] GotoIf("SIP/322-00000349", "1?skipov") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (from-internal,309,13) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:13] Set("SIP/322-00000349", "RRNODEST=") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:14] Set("SIP/322-00000349", "__NODEST=309") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:15] GosubIf("SIP/322-00000349", "0?sub-fmsetcid,s,1()") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:16] Set("SIP/322-00000349", "RecordMethod=Group") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:17] Gosub("SIP/322-00000349", "sub-record-check,s,1(exten,309,)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/322-00000349", "1?check") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (sub-record-check,s,6) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/322-00000349", "__MON_FMT=WAV") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/322-00000349", "1?next") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (sub-record-check,s,10) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/322-00000349", "0?Return()") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/322-00000349", "0?exten,1") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/322-00000349", "__REC_STATUS=INITIALIZED") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/322-00000349", "0?Set(__REC_POLICY_MODE=)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/322-00000349", "NOW=1338903495") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/322-00000349", "__DAY=05") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/322-00000349", "__MONTH=06") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/322-00000349", "__YEAR=2012") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/322-00000349", "__TIMESTR=20120605-093815") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/322-00000349", "__FROMEXTEN=322") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/322-00000349", "__CALLFILENAME=exten-309-322-20120605-093815-1338903495.1613") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/322-00000349", "exten,1") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (sub-record-check,exten,1) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:1] GotoIf("SIP/322-00000349", "0?callee") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:2] Set("SIP/322-00000349", "__REC_POLICY_MODE=") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:3] GotoIf("SIP/322-00000349", "0?caller") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:4] GotoIf("SIP/322-00000349", "0?callee") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:5] ExecIf("SIP/322-00000349", "0?Set(CALLER_PRI=):Set(CALLER_PRI=0)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:6] ExecIf("SIP/322-00000349", "0?Set(CALLEE_PRI=):Set(CALLEE_PRI=0)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:7] GotoIf("SIP/322-00000349", "1?caller:callee") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Goto (sub-record-check,exten,10) [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:10] Set("SIP/322-00000349", "REC_POLICY_MODE=") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:11] GosubIf("SIP/322-00000349", "0?record,1(exten,309,322)") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [exten@sub-record-check:12] Return("SIP/322-00000349", "") in new stack [2012-06-05 09:38:15] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:18] Set("SIP/322-00000349", "RingGroupMethod=ringallv2") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:19] Set("SIP/322-00000349", "_FMGRP=309") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:20] GotoIf("SIP/322-00000349", "0?doconfirm") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:21] Macro("SIP/322-00000349", "dial,30,trWwI,309-3090") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/322-00000349", "1?dial") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-dial,s,3) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/322-00000349", "dialparties.agi") in new stack [2012-06-05 09:38:16] VERBOSE[25828] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi [2012-06-05 09:38:16] VERBOSE[25828] res_agi.c: -- <SIP/322-00000349>AGI Script dialparties.agi completed, returning 0 [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-dial:4] NoOp("SIP/322-00000349", "Returned from dialparties with no extensions to call and DIALSTATUS: ") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:22] Goto("SIP/322-00000349", "nextstep") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (from-internal,309,24) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:24] Set("SIP/322-00000349", "RingGroupMethod=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:25] GotoIf("SIP/322-00000349", "0?nodest") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:26] Set("SIP/322-00000349", "__NODEST=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:27] Set("SIP/322-00000349", "__PICKUPMARK=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:28] Macro("SIP/322-00000349", "blkvm-clr,") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/322-00000349", "SHARED(BLKVM,SIP/322-00000349)=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/322-00000349", "GOSUB_RETVAL=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/322-00000349", "") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:29] Set("SIP/322-00000349", "DIALSTATUS=NOANSWER") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [309@from-internal:30] Goto("SIP/322-00000349", "ext-local,vmu309,1") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (ext-local,vmu309,1) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmu309@ext-local:1] Macro("SIP/322-00000349", "vm,309,NOANSWER,") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-vm:1] Macro("SIP/322-00000349", "user-callerid,SKIPTTL") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/322-00000349", "AMPUSER=322") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/322-00000349", "12?report") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-user-callerid,s,13) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/322-00000349", "1?continue") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-user-callerid,s,26) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/322-00000349", "CALLERID(number)=322") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/322-00000349", "CALLERID(name)=Nathan") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/322-00000349", "CHANNEL(language)=en") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-vm:2] Set("SIP/322-00000349", "VMGAIN=g(10)") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-vm:3] Macro("SIP/322-00000349", "blkvm-check,") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-check:1] Set("SIP/322-00000349", "GOSUB_RETVAL=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-check:2] ExecIf("SIP/322-00000349", "0?Set(GOSUB_RETVAL=TRUE)") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-blkvm-check:3] MacroExit("SIP/322-00000349", "") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-vm:4] GotoIf("SIP/322-00000349", "1?vmx,1") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-vm,vmx,1) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:1] Set("SIP/322-00000349", "MEXTEN=309") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:2] Set("SIP/322-00000349", "MMODE=NOANSWER") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:3] Set("SIP/322-00000349", "RETVM=") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:4] Set("SIP/322-00000349", "MODE=unavail") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:5] GotoIf("SIP/322-00000349", "1?chknomsg") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-vm,vmx,8) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:8] GotoIf("SIP/322-00000349", "0?s-NOANSWER,1") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:9] GotoIf("SIP/322-00000349", "1?notdirect") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-vm,vmx,11) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:11] NoOp("SIP/322-00000349", "Checking if ext 309 is enabled: ") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [vmx@macro-vm:12] GotoIf("SIP/322-00000349", "1?s-NOANSWER,1") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-vm,s-NOANSWER,1) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/322-00000349", "get-vmcontext,309") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/322-00000349", "VMCONTEXT=default") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/322-00000349", "0?200:300") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Goto (macro-get-vmcontext,s,300) [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/322-00000349", "") in new stack [2012-06-05 09:38:16] VERBOSE[25828] pbx.c: -- Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/322-00000349", "309@default,sug(10)") in new stack [2012-06-05 09:38:16] VERBOSE[25828] file.c: -- <SIP/322-00000349> Playing '/var/spool/asterisk/voicemail/default/309/unavail.gsm' (language 'en') [2012-06-05 09:38:19] VERBOSE[25828] app_macro.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/322-00000349' in macro 'vm' [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: == Spawn extension (ext-local, vmu309, 1) exited non-zero on 'SIP/322-00000349' [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: -- Executing [h@ext-local:1] Macro("SIP/322-00000349", "hangupcall,") in new stack [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/322-00000349", "1?theend") in new stack [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: -- Goto (macro-hangupcall,s,3) [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/322-00000349", "0?Set(CDR(recordingfile)=)") in new stack [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/322-00000349", "") in new stack [2012-06-05 09:38:19] VERBOSE[25828] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/322-00000349' in macro 'hangupcall' [2012-06-05 09:38:19] VERBOSE[25828] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/322-00000349'

2

I thought I mentioned in the ticket you filed on this to put the verbosity up to 5 and then provide the CLI output for the section where dialparties.agi is being called so that you can see what it things is going on as it will spit out various internal state information.

In addition to that, turning on AGI debug (if the former does not obviously show what is the problem) will provide more details.

3

The code posted above is with a verbosity of 5.

I did not see anything further about the status of the extension.

Here is the asterisk log output with ‘agi set debug on’, vebose 5.

[2012-06-05 20:14:00] VERBOSE[3484] sig_analog.c: -- Starting simple switch on 'DAHDI/1-1'
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:1] ExecIf("DAHDI/1-1", "1?Set(__FROM_DID=s)") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:2] Gosub("DAHDI/1-1", "cidlookup,cidlookup_2,1()") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [cidlookup_2@cidlookup:1] ExecIf("DAHDI/1-1", "1?Set(CALLERID(name)=Nathan)") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [cidlookup_2@cidlookup:2] Return("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:3] Gosub("DAHDI/1-1", "app-blacklist-check,s,1()") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("DAHDI/1-1", "0?blacklisted") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@app-blacklist-check:2] Set("DAHDI/1-1", "CALLED_BLACKLIST=1") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@app-blacklist-check:3] Return("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:4] Set("DAHDI/1-1", "CDR(did)=s") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:5] ExecIf("DAHDI/1-1", "0 ?Set(CALLERID(name)=6165551212)") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:6] Set("DAHDI/1-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:7] Set("DAHDI/1-1", "CALLERPRES()=allowed_not_screened") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@from-pstn:8] Goto("DAHDI/1-1", "timeconditions,1,1") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Goto (timeconditions,1,1)
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [1@timeconditions:1] GotoIfTime("DAHDI/1-1", "16:45-08:00,mon-fri,*,*?truestate") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Goto (timeconditions,1,9)
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [1@timeconditions:9] GotoIf("DAHDI/1-1", "0?falsegoto") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [1@timeconditions:10] ExecIf("DAHDI/1-1", "0?Set(DB(TC/1)=)") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [1@timeconditions:11] GotoIf("DAHDI/1-1", "1?ivr-3,s,1") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Goto (ivr-3,s,1)
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:1] Set("DAHDI/1-1", "_IVR_CONTEXT_ivr-3=") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:2] Set("DAHDI/1-1", "_IVR_CONTEXT=ivr-3") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:3] Set("DAHDI/1-1", "__IVR_RETVM=") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:4] GotoIf("DAHDI/1-1", "0?skip") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:5] Answer("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:02] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:6] Wait("DAHDI/1-1", "1") in new stack
[2012-06-05 20:14:03] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:7] Set("DAHDI/1-1", "IVR_MSG=custom/New_Afterhours") in new stack
[2012-06-05 20:14:03] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:8] Set("DAHDI/1-1", "TIMEOUT(digit)=3") in new stack
[2012-06-05 20:14:03] VERBOSE[3484] func_timeout.c: -- Digit timeout set to 3.000
[2012-06-05 20:14:03] VERBOSE[3484] pbx.c: -- Executing [s@ivr-3:9] ExecIf("DAHDI/1-1", "1?Background(custom/New_Afterhours)") in new stack
[2012-06-05 20:14:03] VERBOSE[3484] file.c: -- <DAHDI/1-1> Playing 'custom/New_Afterhours.slin' (language 'en')
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: == CDR updated on DAHDI/1-1
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@ivr-3:1] Macro("DAHDI/1-1", "blkvm-clr,") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("DAHDI/1-1", "SHARED(BLKVM,)=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@ivr-3:2] Set("DAHDI/1-1", "__NODEST=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@ivr-3:3] Goto("DAHDI/1-1", "from-did-direct,309,1") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (from-did-direct,309,1)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:1] GotoIf("DAHDI/1-1", "0?ext-local,309,1") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:2] Macro("DAHDI/1-1", "user-callerid,") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:1] Set("DAHDI/1-1", "AMPUSER=6165551212") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("DAHDI/1-1", "0?report") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("DAHDI/1-1", "1?Set(REALCALLERIDNUM=6165551212)") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:4] Set("DAHDI/1-1", "AMPUSER=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:5] Set("DAHDI/1-1", "AMPUSERCIDNAME=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("DAHDI/1-1", "1?report") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (macro-user-callerid,s,13)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("DAHDI/1-1", "0?continue") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:14] Set("DAHDI/1-1", "__TTL=64") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("DAHDI/1-1", "1?continue") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (macro-user-callerid,s,26)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:26] Set("DAHDI/1-1", "CALLERID(number)=6165551212") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:27] Set("DAHDI/1-1", "CALLERID(name)=Nathan") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:28] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:3] Set("DAHDI/1-1", "DIAL_OPTIONS=trWwI") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:4] Set("DAHDI/1-1", "CONNECTEDLINE(num)=309") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:5] Set("DAHDI/1-1", "CONNECTEDLINE(name,i)=Mark Kresge") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:6] Set("DAHDI/1-1", "FM_DIALSTATUS=NOT_INUSE") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:7] Set("DAHDI/1-1", "__EXTTOCALL=309") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:8] Set("DAHDI/1-1", "__PICKUPMARK=309") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:9] Macro("DAHDI/1-1", "blkvm-setifempty,") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("DAHDI/1-1", "1?init") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (macro-blkvm-setifempty,s,4)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("DAHDI/1-1", "__BLKVM_CHANNEL=DAHDI/1-1") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/1-1)=TRUE") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("DAHDI/1-1", "GOSUB_RETVAL=TRUE") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:10] GotoIf("DAHDI/1-1", "1?skipov") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (from-did-direct,309,13)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:13] Set("DAHDI/1-1", "RRNODEST=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:14] Set("DAHDI/1-1", "__NODEST=309") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:15] GosubIf("DAHDI/1-1", "0?sub-fmsetcid,s,1()") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:16] Set("DAHDI/1-1", "RecordMethod=Group") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:17] Gosub("DAHDI/1-1", "sub-record-check,s,1(exten,309,)") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("DAHDI/1-1", "1?check") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (sub-record-check,s,6)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:6] Set("DAHDI/1-1", "__MON_FMT=WAV") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("DAHDI/1-1", "1?next") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (sub-record-check,s,10)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("DAHDI/1-1", "0?Return()") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("DAHDI/1-1", "0?exten,1") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:12] Set("DAHDI/1-1", "__REC_STATUS=INITIALIZED") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("DAHDI/1-1", "0?Set(__REC_POLICY_MODE=)") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:14] Set("DAHDI/1-1", "NOW=1338941651") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:15] Set("DAHDI/1-1", "__DAY=05") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:16] Set("DAHDI/1-1", "__MONTH=06") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:17] Set("DAHDI/1-1", "__YEAR=2012") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:18] Set("DAHDI/1-1", "__TIMESTR=20120605-201411") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:19] Set("DAHDI/1-1", "__FROMEXTEN=6165551212") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:20] Set("DAHDI/1-1", "__CALLFILENAME=exten-309-6165551212-20120605-201411-1338941640.1741") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@sub-record-check:21] Goto("DAHDI/1-1", "exten,1") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (sub-record-check,exten,1)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:1] GotoIf("DAHDI/1-1", "0?callee") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:2] Set("DAHDI/1-1", "__REC_POLICY_MODE=") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:3] GotoIf("DAHDI/1-1", "0?caller") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:4] GotoIf("DAHDI/1-1", "1?callee") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (sub-record-check,exten,8)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:8] GosubIf("DAHDI/1-1", "0?record,1(exten,309,6165551212)") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [exten@sub-record-check:9] Return("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:18] Set("DAHDI/1-1", "RingGroupMethod=ringallv2") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:19] Set("DAHDI/1-1", "_FMGRP=309") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:20] GotoIf("DAHDI/1-1", "0?doconfirm") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:21] Macro("DAHDI/1-1", "dial,30,trWwI,309-3090") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-dial:1] GotoIf("DAHDI/1-1", "1?dial") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Goto (macro-dial,s,3)
[2012-06-05 20:14:11] VERBOSE[3484] pbx.c: -- Executing [s@macro-dial:3] AGI("DAHDI/1-1", "dialparties.agi") in new stack
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_request: dialparties.agi
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_channel: DAHDI/1-1
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_language: en
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_type: DAHDI
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_uniqueid: 1338941640.1741
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_version: 1.8.12.0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_callerid: 6165551212
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_calleridname: Nathan
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_callingpres: 0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_callingani2: 0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_callington: 0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_callingtns: 0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_dnid: unknown
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_rdnis: unknown
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_context: macro-dial
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_extension: s
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_priority: 3
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_enhanced: 0.0
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_accountcode: 
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> agi_threadid: -1218872432
[2012-06-05 20:14:11] VERBOSE[3484] res_agi.c: <DAHDI/1-1>AGI Tx >> 
[2012-06-05 20:14:12] VERBOSE[3484] res_agi.c: -- <DAHDI/1-1>AGI Script dialparties.agi completed, returning 0
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-dial:4] NoOp("DAHDI/1-1", "Returned from dialparties with no extensions to call and DIALSTATUS: ") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:22] Goto("DAHDI/1-1", "nextstep") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (from-did-direct,309,24)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:24] Set("DAHDI/1-1", "RingGroupMethod=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:25] GotoIf("DAHDI/1-1", "0?nodest") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:26] Set("DAHDI/1-1", "__NODEST=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:27] Set("DAHDI/1-1", "__PICKUPMARK=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:28] Macro("DAHDI/1-1", "blkvm-clr,") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("DAHDI/1-1", "SHARED(BLKVM,DAHDI/1-1)=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:29] Set("DAHDI/1-1", "DIALSTATUS=NOANSWER") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [309@from-did-direct:30] Goto("DAHDI/1-1", "ext-local,vmu309,1") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (ext-local,vmu309,1)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmu309@ext-local:1] Macro("DAHDI/1-1", "vm,309,NOANSWER,") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-vm:1] Macro("DAHDI/1-1", "user-callerid,SKIPTTL") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:1] Set("DAHDI/1-1", "AMPUSER=6165551212") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("DAHDI/1-1", "0?report") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("DAHDI/1-1", "0?Set(REALCALLERIDNUM=6165551212)") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:4] Set("DAHDI/1-1", "AMPUSER=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:5] Set("DAHDI/1-1", "AMPUSERCIDNAME=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("DAHDI/1-1", "1?report") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-user-callerid,s,13)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("DAHDI/1-1", "1?continue") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-user-callerid,s,26)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:26] Set("DAHDI/1-1", "CALLERID(number)=6165551212") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:27] Set("DAHDI/1-1", "CALLERID(name)=Nathan") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-user-callerid:28] Set("DAHDI/1-1", "CHANNEL(language)=en") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-vm:2] Set("DAHDI/1-1", "VMGAIN=g(10)") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-vm:3] Macro("DAHDI/1-1", "blkvm-check,") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-check:1] Set("DAHDI/1-1", "GOSUB_RETVAL=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-check:2] ExecIf("DAHDI/1-1", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-blkvm-check:3] MacroExit("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-vm:4] GotoIf("DAHDI/1-1", "1?vmx,1") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-vm,vmx,1)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:1] Set("DAHDI/1-1", "MEXTEN=309") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:2] Set("DAHDI/1-1", "MMODE=NOANSWER") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:3] Set("DAHDI/1-1", "RETVM=") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:4] Set("DAHDI/1-1", "MODE=unavail") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:5] GotoIf("DAHDI/1-1", "1?chknomsg") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-vm,vmx,8)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:8] GotoIf("DAHDI/1-1", "0?s-NOANSWER,1") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:9] GotoIf("DAHDI/1-1", "1?notdirect") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-vm,vmx,11)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:11] NoOp("DAHDI/1-1", "Checking if ext 309 is enabled: ") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [vmx@macro-vm:12] GotoIf("DAHDI/1-1", "1?s-NOANSWER,1") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-vm,s-NOANSWER,1)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("DAHDI/1-1", "get-vmcontext,309") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-get-vmcontext:1] Set("DAHDI/1-1", "VMCONTEXT=default") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("DAHDI/1-1", "0?200:300") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Goto (macro-get-vmcontext,s,300)
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s@macro-get-vmcontext:300] NoOp("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] pbx.c: -- Executing [s-NOANSWER@macro-vm:2] VoiceMail("DAHDI/1-1", "309@default,sug(10)") in new stack
[2012-06-05 20:14:12] VERBOSE[3484] file.c: -- <DAHDI/1-1> Playing '/var/spool/asterisk/voicemail/default/309/unavail.gsm' (language 'en')
[2012-06-05 20:14:17] VERBOSE[3484] app_macro.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'DAHDI/1-1' in macro 'vm'
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: == Spawn extension (ext-local, vmu309, 1) exited non-zero on 'DAHDI/1-1'
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: -- Executing [h@ext-local:1] Macro("DAHDI/1-1", "hangupcall,") in new stack
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("DAHDI/1-1", "1?theend") in new stack
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: -- Goto (macro-hangupcall,s,3)
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("DAHDI/1-1", "0?Set(CDR(recordingfile)=)") in new stack
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("DAHDI/1-1", "") in new stack
[2012-06-05 20:14:17] VERBOSE[3484] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'DAHDI/1-1' in macro 'hangupcall'
[2012-06-05 20:14:17] VERBOSE[3484] pbx.c: == Spawn extension (ext-local, h, 1) exited non-zero on 'DAHDI/1-1'
[2012-06-05 20:14:17] VERBOSE[3484] sig_analog.c: -- Hanging up on 'DAHDI/1-1'
[2012-06-05 20:14:17] VERBOSE[3484] chan_dahdi.c: -- Hungup 'DAHDI/1-1'