[Dec 22 09:52:52] DEBUG[493]: rtp.c:924 ast_rtcp_read: Got RTCP report of 84 bytes
    -- Accepting call from '5555551234' to '4554' on channel 0/15, span 1
[Dec 22 09:52:52] DEBUG[23870]: chan_dahdi.c:1784 dahdi_enable_ec: Enabled echo cancellation on channel 15
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '1'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '1261493572.724'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:1] Set("Zap/15-1", "__ORGCALLID=1261493572.724") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:2] Set("Zap/15-1", "__EXTCONTEXT=cust-local") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Answer'
    -- Executing [4554@zap-incoming:3] Answer("Zap/15-1", "") in new stack
[Dec 22 09:52:52] DEBUG[3128]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/15
[Dec 22 09:52:52] DEBUG[23851]: channel.c:1133 channel_find_locked: Avoiding initial deadlock for channel '0x9c6dda8'
[Dec 22 09:52:52] DEBUG[3128]: chan_dahdi.c:5476 dahdi_indicate: Requested indication -1 on channel Zap/15-1
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:4] Set("Zap/15-1", "CHANNEL(musicclass)=default") in new stack
[Dec 22 09:52:52] DEBUG[23851]: devicestate.c:287 do_state_change: Changing state for Zap/15 - state 2 (In use)
[Dec 22 09:52:52] DEBUG[23905]: app_queue.c:682 handle_statechange: Device 'Zap/15' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '5555551234'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Private'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'NoOp'
    -- Executing [4554@zap-incoming:5] NoOp("Zap/15-1", ""INCOMING CALL FROM CALLER ID: 5555551234 (Private)"") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:6] Set("Zap/15-1", "__INCOMING_DNIS=4554") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:7] Set("Zap/15-1", "CALLERID(dnid)=4554") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:8] Set("Zap/15-1", "CDR(userfield)=4554") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Goto'
    -- Executing [4554@zap-incoming:9] Goto("Zap/15-1", "20") in new stack
    -- Goto (zap-incoming,4554,20)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'AGI'
    -- Executing [4554@zap-incoming:20] AGI("Zap/15-1", "/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack
    -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php
AGI Tx >> agi_request: /var/www/scopserv/telephony/scripts/agi/fixcidname.php
AGI Tx >> agi_channel: Zap/15-1
AGI Tx >> agi_language: en
AGI Tx >> agi_type: Zap
AGI Tx >> agi_uniqueid: 1261493572.724
AGI Tx >> agi_callerid: 5555551234
AGI Tx >> agi_calleridname: Private
AGI Tx >> agi_callingpres: 1
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 33
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 4554
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: zap-incoming
AGI Tx >> agi_extension: 4554
AGI Tx >> agi_priority: 20
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode: _NONE_
AGI Tx >>
AGI Rx << SET CALLERID "Private"<5555551234>
AGI Tx >> 200 result=1
    -- AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php completed, returning 0
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '22'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '24'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [4554@zap-incoming:21] GotoIf("Zap/15-1", "0?22:24") in new stack
    -- Goto (zap-incoming,4554,24)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:24] Set("Zap/15-1", "__INCOMINGLINE=1") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '5555551234'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [4554@zap-incoming:25] GotoIf("Zap/15-1", "0?26:27") in new stack
    -- Goto (zap-incoming,4554,27)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '5555551234'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [4554@zap-incoming:27] GotoIf("Zap/15-1", "0?28:29") in new stack
    -- Goto (zap-incoming,4554,29)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Private'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [4554@zap-incoming:29] GotoIf("Zap/15-1", "0?30:31") in new stack
    -- Goto (zap-incoming,4554,31)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is 'Private'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1777 pbx_substitute_variables_helper_full: Expression result is '0'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [4554@zap-incoming:31] GotoIf("Zap/15-1", "0?32:33") in new stack
    -- Goto (zap-incoming,4554,33)
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1709 pbx_substitute_variables_helper_full: Function result is '5555551234'
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:33] Set("Zap/15-1", "CALLERID(number)=95555551234") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [4554@zap-incoming:34] Set("Zap/15-1", "CHANNEL(language)=en") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Gosub'
    -- Executing [4554@zap-incoming:35] Gosub("Zap/15-1", "cust-aa-test|s|1") in new stack
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Answer'
    -- Executing [s@cust-aa-test:1] Answer("Zap/15-1", "") in new stack
[Dec 22 09:52:52] DEBUG[3128]: chan_dahdi.c:5476 dahdi_indicate: Requested indication -1 on channel Zap/15-1
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'AGI'
    -- Executing [s@cust-aa-test:2] AGI("Zap/15-1", "/var/www/scopserv/telephony/scripts/agi/ivr.php|5406") in new stack
    -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/ivr.php
AGI Tx >> agi_request: /var/www/scopserv/telephony/scripts/agi/ivr.php
AGI Tx >> agi_channel: Zap/15-1
[Dec 22 09:52:52] NOTICE[3128]: utils.c:938 __ast_carefulwrite: Timed out trying to write at line 152 of agi_debug_cli in file res_agi.c
AGI Tx >> agi_language: en
[Dec 22 09:52:52] NOTICE[3128]: utils.c:938 __ast_carefulwrite: Timed out trying to write at line 152 of agi_debug_cli in file res_agi.c
AGI Tx >> agi_type: Zap
[Dec 22 09:52:52] DEBUG[2969]: rtp.c:924 ast_rtcp_read: Got RTCP report of 84 bytes
AGI Tx >> agi_uniqueid: 1261493572.724
AGI Tx >> agi_callerid: 95555551234
AGI Tx >> agi_calleridname: Private
AGI Tx >> agi_callingpres: 1
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 33
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: 4554
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: cust-aa-test
AGI Tx >> agi_extension: s
AGI Tx >> agi_priority: 2
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode: _NONE_
AGI Tx >>
    -- AGI Script /var/www/scopserv/telephony/scripts/agi/ivr.php completed, returning 0
[Dec 22 09:52:52] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Wait'
    -- Executing [s@cust-aa-test:3] Wait("Zap/15-1", "1") in new stack
[Dec 22 09:52:53] DEBUG[31461]: rtp.c:924 ast_rtcp_read: Got RTCP report of 84 bytes
[Dec 22 09:52:54] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@cust-aa-test:4] Set("Zap/15-1", "__IVRNAME=cust-aa-test") in new stack
[Dec 22 09:52:54] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@cust-aa-test:5] Set("Zap/15-1", "TIMEOUT(digit)=3") in new stack
    -- Digit timeout set to 3
[Dec 22 09:52:54] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@cust-aa-test:6] Set("Zap/15-1", "TIMEOUT(response)=5") in new stack
    -- Response timeout set to 5
[Dec 22 09:52:54] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'Set'
    -- Executing [s@cust-aa-test:7] Set("Zap/15-1", "CHANNEL(language)=en") in new stack
[Dec 22 09:52:54] DEBUG[3128]: pbx.c:1861 pbx_extension_helper: Launching 'BackGround'
    -- Executing [s@cust-aa-test:8] BackGround("Zap/15-1", "custom/0002") in new stack
[Dec 22 09:52:54] DEBUG[3128]: channel.c:3156 set_format: Set channel Zap/15-1 to write format slin
    -- <Zap/15-1> Playing 'custom/0002' (language 'en')