Unable to call out on more than one phone at a time

FreePBX version: 2.10.1.16
Asterisk version: 1.8.26.1

 So on my new PBX system I am able to do everything that I want to. Except for use more than one phone to call at the same time... 

 I am using DAHDI trunks which look like this:
      <a>https://www.diigo.com/item/image/4sa6q/e3qh</a>
 Here is what my outbound routes look like:
      <a>https://www.diigo.com/item/image/4sa6q/89u3?k=a660ffc8139f62b1f23b59cd6326951a</a>

 I also have a snippet of the log file from a call that failed while another call was in progress.
[2014-05-19 16:41:00] VERBOSE[31545] pbx.c: == Spawn extension (tc-maint, s, 8) exited non-zero on 'Local/s@tc-maint-0000011e;2' [2014-05-19 16:41:04] VERBOSE[31487] res_musiconhold.c: -- Stopped music on hold on DAHDI/1-1 [2014-05-19 16:41:38] VERBOSE[1904] netsock2.c: == Using SIP RTP TOS bits 184 [2014-05-19 16:41:38] VERBOSE[1904] netsock2.c: == Using SIP RTP CoS mark 5 [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:1] Macro("SIP/707-0000003a", "user-callerid,LIMIT,") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/707-0000003a", "AMPUSER=707") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/707-0000003a", "0?report") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/707-0000003a", "1?Set(REALCALLERIDNUM=707)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/707-0000003a", "AMPUSER=707") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/707-0000003a", "AMPUSERCIDNAME=Molly McIntyre") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/707-0000003a", "0?report") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/707-0000003a", "AMPUSERCID=707") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/707-0000003a", "CALLERID(all)="Molly McIntyre" <707>") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/707-0000003a", "0?limit") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/707-0000003a", "1?Set(GROUP(concurrency_limit)=707)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/707-0000003a", "7?sub-ccss,s,1(from-internal,14356509950)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/707-0000003a", "0?Return()") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/707-0000003a", "CCSS_SETUP=TRUE") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/707-0000003a", "0?monitor_config,1(from-internal,14356509950):monitor_default,1(from-internal,14356509950)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/707-0000003a", "0?is_exten") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/707-0000003a", "") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/707-0000003a", "FALSE") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/707-0000003a", "0?Set(CHANNEL(language)=)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/707-0000003a", "1?continue") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (macro-user-callerid,s,26) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/707-0000003a", "CALLERID(number)=707") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/707-0000003a", "CALLERID(name)=Molly McIntyre") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/707-0000003a", "CHANNEL(language)=en") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:2] Set("SIP/707-0000003a", "MOHCLASS=default") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:3] ExecIf("SIP/707-0000003a", "0?Set(TRUNKCIDOVERRIDE="McIntyre & Golden" <8012663399>)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:4] Set("SIP/707-0000003a", "_NODEST=") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:5] Gosub("SIP/707-0000003a", "sub-record-check,s,1(out,14356509950,)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/707-0000003a", "1?check") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (sub-record-check,s,6) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/707-0000003a", "__MON_FMT=wav") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/707-0000003a", "1?next") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (sub-record-check,s,10) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/707-0000003a", "0?Return()") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/707-0000003a", "0?out,1") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/707-0000003a", "__REC_STATUS=INITIALIZED") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/707-0000003a", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/707-0000003a", "NOW=1400539298") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/707-0000003a", "__DAY=19") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/707-0000003a", "__MONTH=05") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/707-0000003a", "__YEAR=2014") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/707-0000003a", "__TIMESTR=20140519-164138") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/707-0000003a", "__FROMEXTEN=707") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/707-0000003a", "__CALLFILENAME=out-14356509950-707-20140519-164138-1400539298.660") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/707-0000003a", "out,1") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (sub-record-check,out,1) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/707-0000003a", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/707-0000003a", "0?record,1(exten,14356509950,707)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/707-0000003a", "") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [14356509950@from-internal:6] Macro("SIP/707-0000003a", "dialout-trunk,9,14356509950,") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/707-0000003a", "DIAL_TRUNK=9") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/707-0000003a", "0?sub-pincheck,s,1()") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/707-0000003a", "0?disabletrunk,1") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/707-0000003a", "DIAL_NUMBER=14356509950") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/707-0000003a", "DIAL_TRUNK_OPTIONS=trwW") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/707-0000003a", "OUTBOUND_GROUP=OUT_9") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/707-0000003a", "1?nomax") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (macro-dialout-trunk,s,9) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/707-0000003a", "0?skipoutcid") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/707-0000003a", "DIAL_TRUNK_OPTIONS=wW") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/707-0000003a", "outbound-callerid,9") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/707-0000003a", "0?Set(CALLERPRES()=)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/707-0000003a", "0?Set(REALCALLERIDNUM=707)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/707-0000003a", "1?normcid") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/707-0000003a", "USEROUTCID="McIntyre&Golden" <801-266-3399>") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/707-0000003a", "EMERGENCYCID=") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/707-0000003a", "TRUNKOUTCID="McIntyre & Golden" <8012663399>") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/707-0000003a", "1?trunkcid") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Goto (macro-outbound-callerid,s,12) [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/707-0000003a", "1?Set(CALLERID(all)="McIntyre & Golden" <8012663399>)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/707-0000003a", "1?Set(CALLERID(all)="McIntyre&Golden" <801-266-3399>)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/707-0000003a", "0?Set(CALLERID(all)=)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/707-0000003a", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/707-0000003a", "0?sub-flp-9,s,1()") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/707-0000003a", "OUTNUM=w14356509950") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/707-0000003a", "custom=DAHDI/1") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/707-0000003a", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)wW)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/707-0000003a", "0?Set(DIAL_TRUNK_OPTIONS=wWM(confirm))") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/707-0000003a", "dialout-trunk-predial-hook,") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/707-0000003a", "") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/707-0000003a", "0?bypass,1") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/707-0000003a", "1?Set(CONNECTEDLINE(num,i)=14356509950)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/707-0000003a", "1?Set(CONNECTEDLINE(name,i)=CID:8012663399)") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/707-0000003a", "0?customtrunk") in new stack [2014-05-19 16:41:38] VERBOSE[31642] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/707-0000003a", "DAHDI/1/w14356509950,300,wW") in new stack [2014-05-19 16:41:38] WARNING[31642] app_dial.c: Unable to create channel of type 'DAHDI' (cause 17 - User busy) [2014-05-19 16:41:38] VERBOSE[31642] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0)
 Any help would be much apreciated! Thanks!

– T-Apgood

Some additional information:
I was using Zap trunks at first and was having the same issue. So I switched to DAHDI trunks (because they are the successor to Zap) and have the same problem. I do believe that my problem has to do with how the outbound routes search for an open trunk to use.

Here is a log snippet from the newer DAHDI trunks

[2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:1] Macro("SIP/714-0000000f", "user-callerid,LIMIT,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/714-0000000f", "1?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/714-0000000f", "AMPUSERCIDNAME=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/714-0000000f", "AMPUSERCID=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/714-0000000f", "CALLERID(all)="Legal" <714>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/714-0000000f", "0?limit") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/714-0000000f", "1?Set(GROUP(concurrency_limit)=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/714-0000000f", "7?sub-ccss,s,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/714-0000000f", "CCSS_SETUP=TRUE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/714-0000000f", "0?monitor_config,1(from-internal,8018031867):monitor_default,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/714-0000000f", "0?is_exten") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/714-0000000f", "FALSE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/714-0000000f", "0?Set(CHANNEL(language)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/714-0000000f", "1?continue") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-user-callerid,s,26) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/714-0000000f", "CALLERID(number)=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/714-0000000f", "CALLERID(name)=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/714-0000000f", "CHANNEL(language)=en") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:2] Set("SIP/714-0000000f", "MOHCLASS=default") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:3] ExecIf("SIP/714-0000000f", "0?Set(TRUNKCIDOVERRIDE="McIntyre & Golden" <8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:4] Set("SIP/714-0000000f", "_NODEST=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:5] Gosub("SIP/714-0000000f", "sub-record-check,s,1(out,8018031867,)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/714-0000000f", "1?check") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/714-0000000f", "__MON_FMT=wav") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/714-0000000f", "1?next") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,10) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/714-0000000f", "0?out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/714-0000000f", "__REC_STATUS=INITIALIZED") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/714-0000000f", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/714-0000000f", "NOW=1400616843") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/714-0000000f", "__DAY=20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/714-0000000f", "__MONTH=05") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/714-0000000f", "__YEAR=2014") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/714-0000000f", "__TIMESTR=20140520-141403") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/714-0000000f", "__FROMEXTEN=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/714-0000000f", "__CALLFILENAME=out-8018031867-714-20140520-141403-1400616843.276") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/714-0000000f", "out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,out,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/714-0000000f", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/714-0000000f", "0?record,1(exten,8018031867,714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:6] Macro("SIP/714-0000000f", "dialout-trunk,1,8018031867,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/714-0000000f", "DIAL_TRUNK=1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/714-0000000f", "0?sub-pincheck,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/714-0000000f", "0?disabletrunk,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/714-0000000f", "DIAL_NUMBER=8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=trwW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/714-0000000f", "OUTBOUND_GROUP=OUT_1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/714-0000000f", "0?nomax") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/714-0000000f", "0?chanfull") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/714-0000000f", "0?skipoutcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=wW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/714-0000000f", "outbound-callerid,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/714-0000000f", "0?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/714-0000000f", "1?normcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/714-0000000f", "USEROUTCID=8012663399") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/714-0000000f", "EMERGENCYCID=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/714-0000000f", "TRUNKOUTCID="McIntyre & Golden"<8012663399>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/714-0000000f", "1?trunkcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,12) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)="McIntyre & Golden"<8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)=8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/714-0000000f", "0?Set(CALLERID(all)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/714-0000000f", "0?sub-flp-1,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/714-0000000f", "OUTNUM=w8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/714-0000000f", "custom=DAHDI/1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)wW)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=wWM(confirm))") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/714-0000000f", "dialout-trunk-predial-hook,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/714-0000000f", "0?bypass,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(num,i)=8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(name,i)=CID:8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/714-0000000f", "0?customtrunk") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/714-0000000f", "DAHDI/1/w8018031867,300,wW") in new stack [2014-05-20 14:14:03] WARNING[1909] app_dial.c: Unable to create channel of type 'DAHDI' (cause 17 - User busy) [2014-05-20 14:14:03] VERBOSE[1909] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/714-0000000f", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:24] Goto("SIP/714-0000000f", "s-BUSY,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-dialout-trunk,s-BUSY,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:1] NoOp("SIP/714-0000000f", "Dial failed due to trunk reporting BUSY - giving up") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("SIP/714-0000000f", "busy") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("SIP/714-0000000f", "20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] app_macro.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'SIP/714-0000000f' in macro 'dialout-trunk' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, 8018031867, 6) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:06] VERBOSE[1921] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-0000007e;2", "TCMAINT=RETURN") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,6,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "09:00-12:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/6)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC6)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,8,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "00:00-23:59,sat-sun,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/8)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC8)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,6,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:5] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,7,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "13:00-17:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Goto (timeconditions,7,9) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:9] GotoIf("Local/s@tc-maint-0000007e;2", "0?falsegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:10] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/7)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:11] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC7)=NOT_INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:12] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:13] GotoIf("Local/s@tc-maint-0000007e;2", "0?ext-group,601,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:14] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=true") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:15] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:6] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,9,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "12:00-12:59,*,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/9)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC9)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:7] System("Local/s@tc-maint-0000007e;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:8] Answer("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:07] NOTICE[1921] pbx_spool.c: Call completed to Local/s@tc-maint [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: == Spawn extension (tc-maint, s, 8) exited non-zero on 'Local/s@tc-maint-0000007e;2'

Some additional information:
I was using Zap trunks at first and was having the same issue. So I switched to DAHDI trunks (because they are the successor to Zap) and have the same problem. I do believe that my problem has to do with how the outbound routes search for an open trunk to use.

Here is a log snippet from the newer DAHDI trunks

[2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:1] Macro("SIP/714-0000000f", "user-callerid,LIMIT,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/714-0000000f", "1?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/714-0000000f", "AMPUSERCIDNAME=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/714-0000000f", "AMPUSERCID=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/714-0000000f", "CALLERID(all)="Legal" <714>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/714-0000000f", "0?limit") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/714-0000000f", "1?Set(GROUP(concurrency_limit)=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/714-0000000f", "7?sub-ccss,s,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/714-0000000f", "CCSS_SETUP=TRUE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/714-0000000f", "0?monitor_config,1(from-internal,8018031867):monitor_default,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/714-0000000f", "0?is_exten") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/714-0000000f", "FALSE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/714-0000000f", "0?Set(CHANNEL(language)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/714-0000000f", "1?continue") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-user-callerid,s,26) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/714-0000000f", "CALLERID(number)=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/714-0000000f", "CALLERID(name)=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/714-0000000f", "CHANNEL(language)=en") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:2] Set("SIP/714-0000000f", "MOHCLASS=default") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:3] ExecIf("SIP/714-0000000f", "0?Set(TRUNKCIDOVERRIDE="McIntyre & Golden" <8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:4] Set("SIP/714-0000000f", "_NODEST=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:5] Gosub("SIP/714-0000000f", "sub-record-check,s,1(out,8018031867,)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/714-0000000f", "1?check") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/714-0000000f", "__MON_FMT=wav") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/714-0000000f", "1?next") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,10) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/714-0000000f", "0?out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/714-0000000f", "__REC_STATUS=INITIALIZED") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/714-0000000f", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/714-0000000f", "NOW=1400616843") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/714-0000000f", "__DAY=20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/714-0000000f", "__MONTH=05") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/714-0000000f", "__YEAR=2014") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/714-0000000f", "__TIMESTR=20140520-141403") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/714-0000000f", "__FROMEXTEN=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/714-0000000f", "__CALLFILENAME=out-8018031867-714-20140520-141403-1400616843.276") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/714-0000000f", "out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,out,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/714-0000000f", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/714-0000000f", "0?record,1(exten,8018031867,714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:6] Macro("SIP/714-0000000f", "dialout-trunk,1,8018031867,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/714-0000000f", "DIAL_TRUNK=1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/714-0000000f", "0?sub-pincheck,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/714-0000000f", "0?disabletrunk,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/714-0000000f", "DIAL_NUMBER=8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=trwW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/714-0000000f", "OUTBOUND_GROUP=OUT_1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/714-0000000f", "0?nomax") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/714-0000000f", "0?chanfull") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/714-0000000f", "0?skipoutcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=wW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/714-0000000f", "outbound-callerid,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/714-0000000f", "0?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/714-0000000f", "1?normcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/714-0000000f", "USEROUTCID=8012663399") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/714-0000000f", "EMERGENCYCID=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/714-0000000f", "TRUNKOUTCID="McIntyre & Golden"<8012663399>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/714-0000000f", "1?trunkcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,12) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)="McIntyre & Golden"<8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)=8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/714-0000000f", "0?Set(CALLERID(all)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/714-0000000f", "0?sub-flp-1,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/714-0000000f", "OUTNUM=w8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/714-0000000f", "custom=DAHDI/1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)wW)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=wWM(confirm))") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/714-0000000f", "dialout-trunk-predial-hook,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/714-0000000f", "0?bypass,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(num,i)=8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(name,i)=CID:8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/714-0000000f", "0?customtrunk") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/714-0000000f", "DAHDI/1/w8018031867,300,wW") in new stack [2014-05-20 14:14:03] WARNING[1909] app_dial.c: Unable to create channel of type 'DAHDI' (cause 17 - User busy) [2014-05-20 14:14:03] VERBOSE[1909] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/714-0000000f", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:24] Goto("SIP/714-0000000f", "s-BUSY,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-dialout-trunk,s-BUSY,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:1] NoOp("SIP/714-0000000f", "Dial failed due to trunk reporting BUSY - giving up") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("SIP/714-0000000f", "busy") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("SIP/714-0000000f", "20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] app_macro.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'SIP/714-0000000f' in macro 'dialout-trunk' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, 8018031867, 6) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:06] VERBOSE[1921] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-0000007e;2", "TCMAINT=RETURN") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,6,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "09:00-12:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/6)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC6)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,8,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "00:00-23:59,sat-sun,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/8)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC8)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,6,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:5] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,7,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "13:00-17:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Goto (timeconditions,7,9) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:9] GotoIf("Local/s@tc-maint-0000007e;2", "0?falsegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:10] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/7)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:11] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC7)=NOT_INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:12] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:13] GotoIf("Local/s@tc-maint-0000007e;2", "0?ext-group,601,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:14] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=true") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:15] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:6] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,9,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "12:00-12:59,*,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/9)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC9)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:7] System("Local/s@tc-maint-0000007e;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:8] Answer("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:07] NOTICE[1921] pbx_spool.c: Call completed to Local/s@tc-maint [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: == Spawn extension (tc-maint, s, 8) exited non-zero on 'Local/s@tc-maint-0000007e;2'

Some additional information:
I was using Zap trunks at first and was having the same issue. So I switched to DAHDI trunks (because they are the successor to Zap) and have the same problem. I do believe that my problem has to do with how the outbound routes search for an open trunk to use.

Here is a log snippet from the newer DAHDI trunks

[2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:1] Macro("SIP/714-0000000f", "user-callerid,LIMIT,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/714-0000000f", "1?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/714-0000000f", "AMPUSER=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/714-0000000f", "AMPUSERCIDNAME=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/714-0000000f", "0?report") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/714-0000000f", "AMPUSERCID=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/714-0000000f", "CALLERID(all)="Legal" <714>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/714-0000000f", "0?limit") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/714-0000000f", "1?Set(GROUP(concurrency_limit)=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/714-0000000f", "7?sub-ccss,s,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/714-0000000f", "CCSS_SETUP=TRUE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/714-0000000f", "0?monitor_config,1(from-internal,8018031867):monitor_default,1(from-internal,8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/714-0000000f", "0?is_exten") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/714-0000000f", "FALSE") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/714-0000000f", "0?Set(CHANNEL(language)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/714-0000000f", "1?continue") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-user-callerid,s,26) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/714-0000000f", "CALLERID(number)=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/714-0000000f", "CALLERID(name)=Legal") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/714-0000000f", "CHANNEL(language)=en") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:2] Set("SIP/714-0000000f", "MOHCLASS=default") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:3] ExecIf("SIP/714-0000000f", "0?Set(TRUNKCIDOVERRIDE="McIntyre & Golden" <8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:4] Set("SIP/714-0000000f", "_NODEST=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:5] Gosub("SIP/714-0000000f", "sub-record-check,s,1(out,8018031867,)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/714-0000000f", "1?check") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/714-0000000f", "__MON_FMT=wav") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:7] GotoIf("SIP/714-0000000f", "1?next") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,s,10) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:10] ExecIf("SIP/714-0000000f", "0?Return()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:11] GotoIf("SIP/714-0000000f", "0?out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/714-0000000f", "__REC_STATUS=INITIALIZED") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/714-0000000f", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/714-0000000f", "NOW=1400616843") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/714-0000000f", "__DAY=20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/714-0000000f", "__MONTH=05") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/714-0000000f", "__YEAR=2014") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/714-0000000f", "__TIMESTR=20140520-141403") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/714-0000000f", "__FROMEXTEN=714") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/714-0000000f", "__CALLFILENAME=out-8018031867-714-20140520-141403-1400616843.276") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@sub-record-check:21] Goto("SIP/714-0000000f", "out,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (sub-record-check,out,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/714-0000000f", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/714-0000000f", "0?record,1(exten,8018031867,714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [8018031867@from-internal:6] Macro("SIP/714-0000000f", "dialout-trunk,1,8018031867,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/714-0000000f", "DIAL_TRUNK=1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/714-0000000f", "0?sub-pincheck,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/714-0000000f", "0?disabletrunk,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/714-0000000f", "DIAL_NUMBER=8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=trwW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/714-0000000f", "OUTBOUND_GROUP=OUT_1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/714-0000000f", "0?nomax") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/714-0000000f", "0?chanfull") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/714-0000000f", "0?skipoutcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/714-0000000f", "DIAL_TRUNK_OPTIONS=wW") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/714-0000000f", "outbound-callerid,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/714-0000000f", "0?Set(REALCALLERIDNUM=714)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/714-0000000f", "1?normcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/714-0000000f", "USEROUTCID=8012663399") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/714-0000000f", "EMERGENCYCID=") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/714-0000000f", "TRUNKOUTCID="McIntyre & Golden"<8012663399>") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/714-0000000f", "1?trunkcid") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-outbound-callerid,s,12) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)="McIntyre & Golden"<8012663399>)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/714-0000000f", "1?Set(CALLERID(all)=8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/714-0000000f", "0?Set(CALLERID(all)=)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/714-0000000f", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/714-0000000f", "0?sub-flp-1,s,1()") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/714-0000000f", "OUTNUM=w8018031867") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/714-0000000f", "custom=DAHDI/1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)wW)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/714-0000000f", "0?Set(DIAL_TRUNK_OPTIONS=wWM(confirm))") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/714-0000000f", "dialout-trunk-predial-hook,") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/714-0000000f", "0?bypass,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(num,i)=8018031867)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/714-0000000f", "1?Set(CONNECTEDLINE(name,i)=CID:8012663399)") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/714-0000000f", "0?customtrunk") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/714-0000000f", "DAHDI/1/w8018031867,300,wW") in new stack [2014-05-20 14:14:03] WARNING[1909] app_dial.c: Unable to create channel of type 'DAHDI' (cause 17 - User busy) [2014-05-20 14:14:03] VERBOSE[1909] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/714-0000000f", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s@macro-dialout-trunk:24] Goto("SIP/714-0000000f", "s-BUSY,1") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Goto (macro-dialout-trunk,s-BUSY,1) [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:1] NoOp("SIP/714-0000000f", "Dial failed due to trunk reporting BUSY - giving up") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("SIP/714-0000000f", "busy") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("SIP/714-0000000f", "20") in new stack [2014-05-20 14:14:03] VERBOSE[1909] app_macro.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'SIP/714-0000000f' in macro 'dialout-trunk' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, 8018031867, 6) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/714-0000000f", "") in new stack [2014-05-20 14:14:03] VERBOSE[1909] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/714-0000000f' [2014-05-20 14:14:06] VERBOSE[1921] pbx_spool.c: -- Attempting call on Local/s@tc-maint for application NoCDR() (Retry 1) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:1] NoCDR("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:2] Set("Local/s@tc-maint-0000007e;2", "TCMAINT=RETURN") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:3] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,6,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "09:00-12:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/6)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC6)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [6@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:4] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,8,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "00:00-23:59,sat-sun,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/8)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC8)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,6,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [8@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:5] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,7,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "13:00-17:00,mon-fri,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Goto (timeconditions,7,9) [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:9] GotoIf("Local/s@tc-maint-0000007e;2", "0?falsegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:10] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/7)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:11] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC7)=NOT_INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:12] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:13] GotoIf("Local/s@tc-maint-0000007e;2", "0?ext-group,601,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:14] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=true") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [7@timeconditions:15] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:6] Gosub("Local/s@tc-maint-0000007e;2", "timeconditions,9,1()") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:1] GotoIfTime("Local/s@tc-maint-0000007e;2", "12:00-12:59,*,*,*?truestate") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:2] GotoIf("Local/s@tc-maint-0000007e;2", "0?truegoto") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:3] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DB(TC/9)=)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:4] Set("Local/s@tc-maint-0000007e;2", "DEVICE_STATE(Custom:TC9)=INUSE") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:5] ExecIf("Local/s@tc-maint-0000007e;2", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:6] GotoIf("Local/s@tc-maint-0000007e;2", "0?timeconditions,7,1") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:7] Set("Local/s@tc-maint-0000007e;2", "TCSTATE=false") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [9@timeconditions:8] Return("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:06] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:7] System("Local/s@tc-maint-0000007e;2", "/var/lib/asterisk/bin/schedtc.php 60 /var/spool/asterisk/outgoing 1") in new stack [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: -- Executing [s@tc-maint:8] Answer("Local/s@tc-maint-0000007e;2", "") in new stack [2014-05-20 14:14:07] NOTICE[1921] pbx_spool.c: Call completed to Local/s@tc-maint [2014-05-20 14:14:07] VERBOSE[1922] pbx.c: == Spawn extension (tc-maint, s, 8) exited non-zero on 'Local/s@tc-maint-0000007e;2'