Stuck DAHDI Channel Cause?

Hello

I have just spotted that an outgoing DAHDI call has been stuck since the 5th June. Closing the channel has logged the call as a duration of 4848:06

I’ve dug back the logs and found the call which has a few strange things going on, I’m hoping that someone can shed some light as to what happened.

Looking at the log it seems that the 0845 number was dialled but received a PROGRESS with cause code 31 received which I have never seen before. The call then progresses but for some reason MOH kicks in. The call then seems to redial with the same PROGRESS message followed by a Got OK on REFER Notify message which, again, I’ve never seen before.

The call never ‘hangs up’ from this point on

Another question is whether it’s possible for Asterisk to alert by email or drop any call that’s x minutes duration? - In my organisation no call should be longer than 2hrs

Can anyone explain?

[2014-06-05 11:58:33] VERBOSE[15951][C-00000d89] netsock2.c: == Using SIP RTP TOS bits 184 [2014-06-05 11:58:33] VERBOSE[15951][C-00000d89] netsock2.c: == Using SIP RTP CoS mark 5 [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@from-internal:1] Macro("SIP/5038-00000eef", "user-callerid,LIMIT,EXTERNAL,") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/5038-00000eef", "TOUCH_MONITOR=1401965913.10566") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/5038-00000eef", "AMPUSER=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/5038-00000eef", "0?report") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/5038-00000eef", "1?Set(REALCALLERIDNUM=5038)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/5038-00000eef", "AMPUSER=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/5038-00000eef", "0?limit") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/5038-00000eef", "AMPUSERCIDNAME=Dance Office") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/5038-00000eef", "0?report") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/5038-00000eef", "AMPUSERCID=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/5038-00000eef", "__DIAL_OPTIONS=trw") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/5038-00000eef", "CALLERID(all)="Dance Office" <5038>") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/5038-00000eef", "0?limit") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/5038-00000eef", "1?Set(GROUP(concurrency_limit)=5038)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:14] GosubIf("SIP/5038-00000eef", "7?sub-ccss,s,1(from-internal,90845xxxxxxx)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/5038-00000eef", "0?Return()") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/5038-00000eef", "CCSS_SETUP=TRUE") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/5038-00000eef", "0?monitor_config,1(from-internal,90845xxxxxxx):monitor_default,1(from-internal,90845xxxxxxx)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/5038-00000eef", "0?is_exten") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/5038-00000eef", "") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/5038-00000eef", "FALSE") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:15] ExecIf("SIP/5038-00000eef", "0?Set(CHANNEL(language)=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/5038-00000eef", "1?continue") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/5038-00000eef", "CALLERID(number)=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/5038-00000eef", "CALLERID(name)=Dance Office") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/5038-00000eef", "CDR(cnum)=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/5038-00000eef", "CDR(cnam)=Dance Office") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/5038-00000eef", "CHANNEL(language)=en") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@from-internal:2] Set("SIP/5038-00000eef", "MOHCLASS=default") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@from-internal:3] Set("SIP/5038-00000eef", "_NODEST=") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@from-internal:4] Gosub("SIP/5038-00000eef", "sub-record-check,s,1(out,90845xxxxxxx,)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/5038-00000eef", "REC_POLICY_MODE_SAVE=") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/5038-00000eef", "1?check") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (sub-record-check,s,7) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/5038-00000eef", "__MON_FMT=wav") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/5038-00000eef", "1?next") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (sub-record-check,s,11) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/5038-00000eef", "0?Return()") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/5038-00000eef", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/5038-00000eef", "0?out,1") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/5038-00000eef", "__REC_STATUS=INITIALIZED") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/5038-00000eef", "NOW=1401965913") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/5038-00000eef", "__DAY=05") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/5038-00000eef", "__MONTH=06") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/5038-00000eef", "__YEAR=2014") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/5038-00000eef", "__TIMESTR=20140605-115833") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/5038-00000eef", "__FROMEXTEN=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/5038-00000eef", "__CALLFILENAME=out-90845xxxxxxx-5038-20140605-115833-1401965913.10566") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/5038-00000eef", "out,1") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (sub-record-check,out,1) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/5038-00000eef", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/5038-00000eef", "0?record,1(exten,90845xxxxxxx,5038)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/5038-00000eef", "") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@from-internal:5] Macro("SIP/5038-00000eef", "dialout-trunk,6,90845xxxxxxx,,off") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/5038-00000eef", "DIAL_TRUNK=6") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/5038-00000eef", "0?sub-pincheck,s,1()") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/5038-00000eef", "0?disabletrunk,1") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/5038-00000eef", "DIAL_NUMBER=90845xxxxxxx") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/5038-00000eef", "DIAL_TRUNK_OPTIONS=trw") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/5038-00000eef", "OUTBOUND_GROUP=OUT_6") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/5038-00000eef", "1?nomax") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (macro-dialout-trunk,s,9) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/5038-00000eef", "0?skipoutcid") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/5038-00000eef", "DIAL_TRUNK_OPTIONS=W") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/5038-00000eef", "outbound-callerid,6") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/5038-00000eef", "0?Set(CALLERPRES()=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/5038-00000eef", "0?Set(REALCALLERIDNUM=5038)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/5038-00000eef", "1?normcid") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/5038-00000eef", "USEROUTCID=") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/5038-00000eef", "EMERGENCYCID=") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/5038-00000eef", "TRUNKOUTCID=") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/5038-00000eef", "1?trunkcid") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (macro-outbound-callerid,s,14) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/5038-00000eef", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/5038-00000eef", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/5038-00000eef", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/5038-00000eef", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:18] Set("SIP/5038-00000eef", "CDR(outbound_cnum)=5038") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-outbound-callerid:19] Set("SIP/5038-00000eef", "CDR(outbound_cnam)=Dance Office") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/5038-00000eef", "0?sub-flp-6,s,1()") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/5038-00000eef", "OUTNUM=90845xxxxxxx") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/5038-00000eef", "custom=AMP") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/5038-00000eef", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)W)") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/5038-00000eef", "0?Set(DIAL_TRUNK_OPTIONS=WM(confirm))") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/5038-00000eef", "dialout-trunk-predial-hook,") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] GotoIf("SIP/5038-00000eef", "1?custom-freepbx-a2billing,90845xxxxxxx,1:2") in new stack [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Goto (custom-freepbx-a2billing,0845xxxxxxx,1) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] app_macro.c: == Channel 'SIP/5038-00000eef' jumping out of macro 'dialout-trunk-predial-hook' [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] app_macro.c: == Channel 'SIP/5038-00000eef' jumping out of macro 'dialout-trunk' [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] pbx.c: -- Executing [90845xxxxxxx@custom-freepbx-a2billing:1] DeadAGI("SIP/5038-00000eef", "a2billing.php,3") in new stack [2014-06-05 11:58:33] WARNING[34007][C-00000d89] res_agi.c: DeadAGI has been deprecated, please use AGI in all cases! [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] res_agi.c: -- AGI Script Executing Application: (DIAL) Options: (DAHDI/g0/90845xxxxxxx,14400,) [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] sig_pri.c: -- Requested transfer capability: 0x00 - SPEECH [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] app_dial.c: -- Called DAHDI/g0/90845xxxxxxx [2014-06-05 11:58:33] VERBOSE[34007][C-00000d89] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb3 is proceeding passing it to SIP/5038-00000eef [2014-06-05 11:58:34] VERBOSE[15935][C-00000d89] sig_pri.c: -- PROGRESS with cause code 31 received [2014-06-05 11:58:37] VERBOSE[34007][C-00000d89] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb3 is ringing [2014-06-05 11:58:37] VERBOSE[34007][C-00000d89] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb3 is making progress passing it to SIP/5038-00000eef [2014-06-05 11:58:45] VERBOSE[34007][C-00000d89] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb3 answered SIP/5038-00000eef [2014-06-05 11:59:00] VERBOSE[34007][C-00000d89] res_musiconhold.c: -- Started music on hold, class 'default', on DAHDI/i1/90845xxxxxxx-eb3 [2014-06-05 11:59:14] VERBOSE[15951][C-00000d8a] netsock2.c: == Using SIP RTP TOS bits 184 [2014-06-05 11:59:14] VERBOSE[15951][C-00000d8a] netsock2.c: == Using SIP RTP CoS mark 5 [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@from-internal:1] Macro("SIP/5038-00000ef0", "user-callerid,LIMIT,EXTERNAL,") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/5038-00000ef0", "TOUCH_MONITOR=1401965954.10568") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/5038-00000ef0", "AMPUSER=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/5038-00000ef0", "0?report") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/5038-00000ef0", "1?Set(REALCALLERIDNUM=5038)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/5038-00000ef0", "AMPUSER=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/5038-00000ef0", "0?limit") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/5038-00000ef0", "AMPUSERCIDNAME=Dance Office") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/5038-00000ef0", "0?report") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/5038-00000ef0", "AMPUSERCID=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/5038-00000ef0", "__DIAL_OPTIONS=trw") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/5038-00000ef0", "CALLERID(all)="Dance Office" <5038>") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/5038-00000ef0", "0?limit") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/5038-00000ef0", "1?Set(GROUP(concurrency_limit)=5038)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:14] GosubIf("SIP/5038-00000ef0", "7?sub-ccss,s,1(from-internal,90845xxxxxxx)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/5038-00000ef0", "0?Return()") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/5038-00000ef0", "CCSS_SETUP=TRUE") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/5038-00000ef0", "0?monitor_config,1(from-internal,90845xxxxxxx):monitor_default,1(from-internal,90845xxxxxxx)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/5038-00000ef0", "0?is_exten") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/5038-00000ef0", "") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/5038-00000ef0", "FALSE") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:15] ExecIf("SIP/5038-00000ef0", "0?Set(CHANNEL(language)=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/5038-00000ef0", "1?continue") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/5038-00000ef0", "CALLERID(number)=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/5038-00000ef0", "CALLERID(name)=Dance Office") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/5038-00000ef0", "CDR(cnum)=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/5038-00000ef0", "CDR(cnam)=Dance Office") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/5038-00000ef0", "CHANNEL(language)=en") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@from-internal:2] Set("SIP/5038-00000ef0", "MOHCLASS=default") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@from-internal:3] Set("SIP/5038-00000ef0", "_NODEST=") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@from-internal:4] Gosub("SIP/5038-00000ef0", "sub-record-check,s,1(out,90845xxxxxxx,)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/5038-00000ef0", "REC_POLICY_MODE_SAVE=") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/5038-00000ef0", "1?check") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (sub-record-check,s,7) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/5038-00000ef0", "__MON_FMT=wav") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/5038-00000ef0", "1?next") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (sub-record-check,s,11) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/5038-00000ef0", "0?Return()") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/5038-00000ef0", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/5038-00000ef0", "0?out,1") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/5038-00000ef0", "__REC_STATUS=INITIALIZED") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/5038-00000ef0", "NOW=1401965954") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/5038-00000ef0", "__DAY=05") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/5038-00000ef0", "__MONTH=06") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/5038-00000ef0", "__YEAR=2014") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/5038-00000ef0", "__TIMESTR=20140605-115914") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/5038-00000ef0", "__FROMEXTEN=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/5038-00000ef0", "__CALLFILENAME=out-90845xxxxxxx-5038-20140605-115914-1401965954.10568") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/5038-00000ef0", "out,1") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (sub-record-check,out,1) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/5038-00000ef0", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/5038-00000ef0", "0?record,1(exten,90845xxxxxxx,5038)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/5038-00000ef0", "") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@from-internal:5] Macro("SIP/5038-00000ef0", "dialout-trunk,6,90845xxxxxxx,,off") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/5038-00000ef0", "DIAL_TRUNK=6") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/5038-00000ef0", "0?sub-pincheck,s,1()") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/5038-00000ef0", "0?disabletrunk,1") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/5038-00000ef0", "DIAL_NUMBER=90845xxxxxxx") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/5038-00000ef0", "DIAL_TRUNK_OPTIONS=trw") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/5038-00000ef0", "OUTBOUND_GROUP=OUT_6") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/5038-00000ef0", "1?nomax") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (macro-dialout-trunk,s,9) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/5038-00000ef0", "0?skipoutcid") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/5038-00000ef0", "DIAL_TRUNK_OPTIONS=W") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/5038-00000ef0", "outbound-callerid,6") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/5038-00000ef0", "0?Set(CALLERPRES()=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/5038-00000ef0", "0?Set(REALCALLERIDNUM=5038)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/5038-00000ef0", "1?normcid") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/5038-00000ef0", "USEROUTCID=") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/5038-00000ef0", "EMERGENCYCID=") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/5038-00000ef0", "TRUNKOUTCID=") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/5038-00000ef0", "1?trunkcid") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (macro-outbound-callerid,s,14) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/5038-00000ef0", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/5038-00000ef0", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/5038-00000ef0", "0?Set(CALLERID(all)=)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/5038-00000ef0", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:18] Set("SIP/5038-00000ef0", "CDR(outbound_cnum)=5038") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-outbound-callerid:19] Set("SIP/5038-00000ef0", "CDR(outbound_cnam)=Dance Office") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/5038-00000ef0", "0?sub-flp-6,s,1()") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/5038-00000ef0", "OUTNUM=90845xxxxxxx") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/5038-00000ef0", "custom=AMP") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/5038-00000ef0", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)W)") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/5038-00000ef0", "0?Set(DIAL_TRUNK_OPTIONS=WM(confirm))") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/5038-00000ef0", "dialout-trunk-predial-hook,") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] GotoIf("SIP/5038-00000ef0", "1?custom-freepbx-a2billing,90845xxxxxxx,1:2") in new stack [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Goto (custom-freepbx-a2billing,90845xxxxxxx,1) [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] app_macro.c: == Channel 'SIP/5038-00000ef0' jumping out of macro 'dialout-trunk-predial-hook' [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] app_macro.c: == Channel 'SIP/5038-00000ef0' jumping out of macro 'dialout-trunk' [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] pbx.c: -- Executing [90845xxxxxxx@custom-freepbx-a2billing:1] DeadAGI("SIP/5038-00000ef0", "a2billing.php,3") in new stack [2014-06-05 11:59:14] WARNING[34030][C-00000d8a] res_agi.c: DeadAGI has been deprecated, please use AGI in all cases! [2014-06-05 11:59:14] VERBOSE[34030][C-00000d8a] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php [2014-06-05 11:59:15] VERBOSE[34030][C-00000d8a] res_agi.c: -- AGI Script Executing Application: (DIAL) Options: (DAHDI/g0/90845xxxxxxx,14400,) [2014-06-05 11:59:15] VERBOSE[34030][C-00000d8a] sig_pri.c: -- Requested transfer capability: 0x00 - SPEECH [2014-06-05 11:59:15] VERBOSE[34030][C-00000d8a] app_dial.c: -- Called DAHDI/g0/90845xxxxxxx [2014-06-05 11:59:15] VERBOSE[34030][C-00000d8a] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb4 is proceeding passing it to SIP/5038-00000ef0 [2014-06-05 11:59:15] VERBOSE[15935][C-00000d8a] sig_pri.c: -- PROGRESS with cause code 31 received [2014-06-05 11:59:18] VERBOSE[34030][C-00000d8a] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb4 is ringing [2014-06-05 11:59:18] VERBOSE[34030][C-00000d8a] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb4 is making progress passing it to SIP/5038-00000ef0 [2014-06-05 11:59:26] VERBOSE[34030][C-00000d8a] app_dial.c: -- DAHDI/i1/90845xxxxxxx-eb4 answered SIP/5038-00000ef0 [2014-06-05 11:59:32] VERBOSE[15951][C-00000d8a] res_musiconhold.c: -- Stopped music on hold on DAHDI/i1/90845xxxxxxx-eb3 [2014-06-05 11:59:32] NOTICE[15951][C-00000d8a] chan_sip.c: Got OK on REFER Notify message [2014-06-05 11:59:32] VERBOSE[34030][C-00000d8a] res_agi.c: -- <SIP/5038-00000ef0>AGI Script a2billing.php completed, returning 4 [2014-06-05 11:59:32] VERBOSE[34030][C-00000d8a] pbx.c: == Spawn extension (custom-freepbx-a2billing, 90845xxxxxxx, 1) exited non-zero on 'SIP/5038-00000ef0'