[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [069060481@from-internal:1] Macro("SIP/101-00000001", "user-callerid,SKIPTTL,") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/101-00000001", "AMPUSER=101") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/101-00000001", "0?report") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/101-00000001", "1?Set(REALCALLERIDNUM=101)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/101-00000001", "AMPUSER=101") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'am'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/101-00000001", "AMPUSERCIDNAME=am") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/101-00000001", "0?report") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/101-00000001", "AMPUSERCID=101") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/101-00000001", "CALLERID(all)="am" <101>") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:9] ExecIf("SIP/101-00000001", "0?Set(CHANNEL(language)=)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/101-00000001", "1?continue") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-user-callerid,s,19)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '"am" <101>'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'NoOp'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/101-00000001", "Using CallerID "am" <101>") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Noop
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [069060481@from-internal:2] Set("SIP/101-00000001", "_NODEST=") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [069060481@from-internal:3] Macro("SIP/101-00000001", "record-enable,101,OUT,") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/101-00000001", "1?check") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-record-enable,s,4)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '20100701-152032'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'AGI'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/101-00000001", "recordingcheck,20100701-152032,1277986832.2") in new stack
[Jul  1 15:20:32] VERBOSE[19163] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul  1 15:20:32] VERBOSE[19163] res_agi.c:  recordingcheck,20100701-152032,1277986832.2: Outbound recording enabled.
[Jul  1 15:20:32] VERBOSE[19163] res_agi.c:  recordingcheck,20100701-152032,1277986832.2: CALLFILENAME=OUT101-20100701-152032-1277986832.2
[Jul  1 15:20:32] VERBOSE[19163] res_agi.c:     -- <SIP/101-00000001>AGI Script recordingcheck completed, returning 0
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: AGI
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'MixMonitor'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-record-enable:999] MixMonitor("SIP/101-00000001", "OUT101-20100701-152032-1277986832.2.wav,,") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: MixMonitor
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [069060481@from-internal:4] Macro("SIP/101-00000001", "dialout-trunk,3,069060481,,") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/101-00000001", "DIAL_TRUNK=3") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] db.c: Unable to find key '101/pinless' in family 'AMPUSER'
[Jul  1 15:20:32] DEBUG[19163] func_db.c: DB: AMPUSER/101/pinless not found in database.
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GosubIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/101-00000001", "0?sub-pincheck,s,1") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GosubIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] db.c: Unable to find key '101/pinless' in family 'AMPUSER'
[Jul  1 15:20:32] DEBUG[19163] func_db.c: DB: AMPUSER/101/pinless not found in database.
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/101-00000001", "0?disabletrunk,1") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/101-00000001", "DIAL_NUMBER=069060481") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/101-00000001", "DIAL_TRUNK_OPTIONS=tTrwW") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/101-00000001", "OUTBOUND_GROUP=OUT_3") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/101-00000001", "0?nomax") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/101-00000001", "0?chanfull") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/101-00000001", "0?skipoutcid") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/101-00000001", "DIAL_TRUNK_OPTIONS=tTwW") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/101-00000001", "outbound-callerid,3") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/101-00000001", "0?Set(CALLERPRES()=)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/101-00000001", "0?Set(REALCALLERIDNUM=101)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is '101'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/101-00000001", "1?normcid") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/101-00000001", "USEROUTCID=") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] db.c: Unable to find key '101/emergency_cid' in family 'DEVICE'
[Jul  1 15:20:32] DEBUG[19163] func_db.c: DB: DEVICE/101/emergency_cid not found in database.
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/101-00000001", "EMERGENCYCID=") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/101-00000001", "TRUNKOUTCID=") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/101-00000001", "1?trunkcid") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/101-00000001", "0?Set(CALLERID(all)=)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/101-00000001", "0?Set(CALLERID(all)=)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'am'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/101-00000001", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'am'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Macro
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/101-00000001", "0?AGI(fixlocalprefix)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/101-00000001", "OUTNUM=069060481") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'AMP'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/101-00000001", "custom=AMP") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'ExecIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/101-00000001", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^)tTwW)") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: ExecIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:16] Macro("SIP/101-00000001", "dialout-trunk-predial-hook,") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'MacroExit'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/101-00000001", "") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Macro
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/101-00000001", "0?bypass,1") in new stack
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/101-00000001", "1?customtrunk") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-dialout-trunk,s,21)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'AMP:Mobile/Orange/'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:21] Set("SIP/101-00000001", "pre_num=AMP:Mobile/Orange/") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is 'OUTNUM'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Set("SIP/101-00000001", "the_num=OUTNUM") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Function result is ''
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:23] Set("SIP/101-00000001", "post_num=") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/101-00000001", "1?outnum:skipoutnum") in new stack
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Goto (macro-dialout-trunk,s,25)
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Set'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:25] Set("SIP/101-00000001", "the_num=069060481") in new stack
[Jul  1 15:20:32] DEBUG[19163] app_macro.c: Executed application: Set
[Jul  1 15:20:32] DEBUG[19163] pbx.c: Launching 'Dial'
[Jul  1 15:20:32] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:26] Dial("SIP/101-00000001", "Mobile/Orange/069060481,300,tTwW") in new stack
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIALEDTIME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable ANSWEREDTIME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIALEDPEERNAME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIALEDPEERNUMBER.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIALSTATUS.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable MACRO_DEPTH.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable the_num.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable post_num.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable pre_num.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable MACRO_PRIORITY.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable MACRO_CONTEXT.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable MACRO_EXTEN.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable ARG1.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable custom.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable OUTNUM.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable TRUNKOUTCID.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable EMERGENCYCID.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable USEROUTCID.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DB_RESULT.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIAL_TRUNK_OPTIONS.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable OUTBOUND_GROUP.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIAL_NUMBER.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable DIAL_TRUNK.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable ARG4.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable ARG3.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable ARG2.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable AGISTATUS.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable CALLFILENAME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Copying soft-transferable variable NODEST.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable AMPUSERCID.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable AMPUSERCIDNAME.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable AMPUSER.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable REALCALLERIDNUM.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable SIPCALLID.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable SIPDOMAIN.
[Jul  1 15:20:32] DEBUG[19163] channel.c: Not copying variable SIPURI.
[Jul  1 15:20:32] DEBUG[19163] chan_mobile.c: Calling Orange/069060481 on Mobile/Orange-cbea
[Jul  1 15:20:32] DEBUG[19163] chan_mobile.c: rfcomm_write() (39) [ATD069060481;
]
[Jul  1 15:20:32] VERBOSE[19163] app_dial.c:     -- Called Orange/069060481
[Jul  1 15:20:32] DEBUG[19163] channel.c: Set channel Mobile/Orange-cbea to read format ulaw
[Jul  1 15:20:32] DEBUG[19163] channel.c: Set channel SIP/101-00000001 to read format slin
[Jul  1 15:20:34] DEBUG[19163] channel.c: Hanging up channel 'Mobile/Orange-cbea'
[Jul  1 15:20:34] DEBUG[19163] chan_mobile.c: [Orange] hanging up device
[Jul  1 15:20:34] VERBOSE[19163] app_dial.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul  1 15:20:34] DEBUG[19163] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jul  1 15:20:34] DEBUG[19163] app_macro.c: Executed application: Dial
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'Goto'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [s@macro-dialout-trunk:27] Goto("SIP/101-00000001", "s-CHANUNAVAIL,1") in new stack
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Jul  1 15:20:34] DEBUG[19163] app_macro.c: Executed application: Goto
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Expression result is '0'
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/101-00000001", "0?noreport") in new stack
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Not taking any branch
[Jul  1 15:20:34] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'AGI'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] AGI("SIP/101-00000001", "trunk_monitor.agi") in new stack
[Jul  1 15:20:34] VERBOSE[19163] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/trunk_monitor.agi
[Jul  1 15:20:34] VERBOSE[19163] res_agi.c:     -- <SIP/101-00000001>AGI Script trunk_monitor.agi completed, returning 0
[Jul  1 15:20:34] DEBUG[19163] app_macro.c: Executed application: AGI
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'NoOp'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/101-00000001", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Jul  1 15:20:34] DEBUG[19163] app_macro.c: Executed application: Noop
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [069060481@from-internal:5] Macro("SIP/101-00000001", "outisbusy,") in new stack
[Jul  1 15:20:34] DEBUG[19163] pbx.c: Launching 'Playback'
[Jul  1 15:20:34] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outisbusy:1] Playback("SIP/101-00000001", "all-circuits-busy-now,noanswer") in new stack
[Jul  1 15:20:34] DEBUG[19163] channel.c: Set channel SIP/101-00000001 to write format gsm
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 15:20:34] VERBOSE[19163] file.c:     -- <SIP/101-00000001> Playing 'all-circuits-busy-now.gsm' (language 'en')
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:34] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:35] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:36] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:36] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:36] DEBUG[19163] channel.c: Set channel SIP/101-00000001 to write format ulaw
[Jul  1 15:20:36] DEBUG[19163] app_macro.c: Executed application: Playback
[Jul  1 15:20:36] DEBUG[19163] pbx.c: Launching 'Playback'
[Jul  1 15:20:36] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outisbusy:2] Playback("SIP/101-00000001", "pls-try-call-later,noanswer") in new stack
[Jul  1 15:20:36] DEBUG[19163] channel.c: Set channel SIP/101-00000001 to write format gsm
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 15:20:36] VERBOSE[19163] file.c:     -- <SIP/101-00000001> Playing 'pls-try-call-later.gsm' (language 'en')
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:36] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:37] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] rtp.c: Setting the marker bit due to a source update
[Jul  1 15:20:38] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:38] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:38] DEBUG[19163] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 15:20:38] DEBUG[19163] channel.c: Set channel SIP/101-00000001 to write format ulaw
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: Playback
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-outisbusy:3] Macro("SIP/101-00000001", "hangupcall") in new stack
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/101-00000001", "1?skiprg") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/101-00000001", "1?skipblkvm") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/101-00000001", "1?theend") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'Hangup'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/101-00000001", "") in new stack
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/101-00000001' in macro 'hangupcall'
[Jul  1 15:20:38] VERBOSE[19163] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/101-00000001' in macro 'hangupcall'
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Spawn extension (macro-outisbusy,s,3) exited non-zero on 'SIP/101-00000001' in macro 'outisbusy'
[Jul  1 15:20:38] VERBOSE[19163] app_macro.c:   == Spawn extension (macro-outisbusy, s, 3) exited non-zero on 'SIP/101-00000001' in macro 'outisbusy'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Spawn extension (from-internal,069060481,5) exited non-zero on 'SIP/101-00000001'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:   == Spawn extension (from-internal, 069060481, 5) exited non-zero on 'SIP/101-00000001'
[Jul  1 15:20:38] DEBUG[19163] channel.c: Soft-Hanging up channel 'SIP/101-00000001'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'Macro'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [h@from-internal:1] Macro("SIP/101-00000001", "hangupcall") in new stack
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/101-00000001", "1?skiprg") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/101-00000001", "1?skipblkvm") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Expression result is '1'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'GotoIf'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/101-00000001", "1?theend") in new stack
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Executed application: GotoIf
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Launching 'Hangup'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/101-00000001", "") in new stack
[Jul  1 15:20:38] DEBUG[19163] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/101-00000001' in macro 'hangupcall'
[Jul  1 15:20:38] VERBOSE[19163] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/101-00000001' in macro 'hangupcall'
[Jul  1 15:20:38] DEBUG[19163] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/101-00000001'
[Jul  1 15:20:38] VERBOSE[19163] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/101-00000001'
[Jul  1 15:20:38] DEBUG[19163] channel.c: Hanging up channel 'SIP/101-00000001'
[Jul  1 15:20:38] DEBUG[19163] chan_sip.c: Hangup call SIP/101-00000001, SIP callid OGU5OGQ0MThiMWUwNTI3OWRjNTU4ZjliMzkzYTJmMTU.
[Jul  1 15:20:38] DEBUG[19163] chan_sip.c: Updating call counter for incoming call
[Jul  1 15:20:38] DEBUG[19163] chan_sip.c: Hanging up channel in state Ring (not UP)
[Jul  1 15:20:38] DEBUG[19163] chan_sip.c: AST hangup cause 16 (no match found in SIP)
[Jul  1 15:20:38] DEBUG[19163] chan_sip.c: Trying to put 'SIP/2.0 603' onto UDP socket destined for 172.16.0.101:47486
[Jul  1 15:20:38] DEBUG[19163] cdr_addon_mysql.c: Inserting a CDR record.
[Jul  1 15:20:38] DEBUG[19163] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,duration,billsec,disposition,amaflags,uniqueid) VALUES ('2010-07-01 15:20:32','\"am\" <101>','101','069060481','from-internal','SIP/101-00000001','Mobile/Orange-cbea','Hangup','6','0','NO ANSWER','3','1277986832.2')