[2011-01-26 12:12:03] DEBUG[15253]: acl.c:355 ast_append_ha: 127.0.0.1/255.255.255.255 appended to acl for peer
[2011-01-26 12:12:03] DEBUG[15253]: acl.c:370 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.1
[2011-01-26 12:12:03] DEBUG[15253]: manager.c:2277 process_message: Manager received command 'Command'
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for aeda8eda-1717c855-dd8b1374@192.168.30.86 - SUBSCRIBE (No RTP)
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6057@192.168.30.86:5060>
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:9050 build_route: build_route: Retaining previous route: <sip:6057@192.168.30.86:5060>
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:16754 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 192.168.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 10.0.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 172.16.0.0
[2011-01-26 12:12:03] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 169.254.0.0
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for a68bb34f-d651657e-fbb52ee1@192.168.30.150 - SUBSCRIBE (No RTP)
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6003@192.168.30.150:5060>
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:9050 build_route: build_route: Retaining previous route: <sip:6003@192.168.30.150:5060>
[2011-01-26 12:12:03] DEBUG[32071]: chan_sip.c:16754 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary
[2011-01-26 12:12:04] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:04] DEBUG[32063]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:04] DEBUG[32062]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:04] DEBUG[32061]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:05] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:05] DEBUG[32064]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:06] DEBUG[32058]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:06] DEBUG[32059]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:07]     -- Accepting call from '1800555123' to '6010' on channel 0/23, span 1
[2011-01-26 12:12:07] DEBUG[32096]: chan_dahdi.c:1846 dahdi_enable_ec: Enabled echo cancellation on channel 23
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:1] Set("Zap/23-1", "__INCOMING_DNIS=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:2] Set("Zap/23-1", "LINE_TENANT=default") in new stack
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:3] Set("Zap/23-1", "LINE_LANGUAGE=en") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:4] Set("Zap/23-1", "LINE_CLID_NUM=0000000000") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:5] Set("Zap/23-1", "LINE_CLID_NAME=") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:6] Set("Zap/23-1", "LINE_CLID_NUM_DEF=91800555123") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'BCM50bob'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:7] Set("Zap/23-1", "LINE_CLID_NAME_DEF=David Brillert:BCM50bob") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:8] Set("Zap/23-1", "LINE_MOH=default") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Gosub'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:9] Gosub("Zap/23-1", "all-incoming-check|s|1") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'BCM50bob'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'NoOp'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:1] NoOp("Zap/23-1", ""INCOMING CALL FROM CALLER ID: 1800555123 (BCM50bob)"") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '7'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:2] GotoIf("Zap/23-1", "1?7") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,7)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '10'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:7] GotoIf("Zap/23-1", "1?10") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,10)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '12'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:10] GotoIf("Zap/23-1", "1?12") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,12)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '14'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:12] GotoIf("Zap/23-1", "1?14") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,14)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '16'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:14] GotoIf("Zap/23-1", "1?16") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,16)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '18'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:16] GotoIf("Zap/23-1", "0?18") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:17] Set("Zap/23-1", "CHANNEL(musicclass)=default") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:18] Set("Zap/23-1", "CALLERID(dnid)=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:19] Set("Zap/23-1", "CDR(userfield)=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:20] Set("Zap/23-1", "__EXTCONTEXT=default-default") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:21] Set("Zap/23-1", "__INCOMINGLINE=1") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1296061927.4'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:22] Set("Zap/23-1", "__ORGCALLID=1296061927.4") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '25'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:23] GotoIf("Zap/23-1", "1?25") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,25)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '27'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:25] GotoIf("Zap/23-1", "1?27") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,27)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '29'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:27] GotoIf("Zap/23-1", "1?29") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,29)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '31'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:29] GotoIf("Zap/23-1", "1?31") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,31)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'AGI'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:31] AGI("Zap/23-1", "agi://127.0.0.1:4573/fixcidname") in new stack
[2011-01-26 12:12:07]     -- AGI Script agi://127.0.0.1:4573/fixcidname completed, returning 0
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '34'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:32] GotoIf("Zap/23-1", "1?34") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,34)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '36'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:34] GotoIf("Zap/23-1", "0?36") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:35] Set("Zap/23-1", "CHANNEL(language)=en") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:36] Set("Zap/23-1", "FAXNUMBER=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '39'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:37] GotoIf("Zap/23-1", "1?39") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,39)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '41'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:39] GotoIf("Zap/23-1", "1?41") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,41)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '44'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:41] GotoIf("Zap/23-1", "1?44") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,44)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '49'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:44] GotoIf("Zap/23-1", "0?49") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '47'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:45] GotoIf("Zap/23-1", "1?47") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,47)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '49'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:47] GotoIf("Zap/23-1", "1?49") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,49)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '54'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:49] GotoIf("Zap/23-1", "1?54") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,54)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '56'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:54] GotoIf("Zap/23-1", "0?56") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:55] Set("Zap/23-1", "CALLERID(number)=91800555123") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '58'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:56] GotoIf("Zap/23-1", "0?58") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:57] Set("Zap/23-1", "CALLERID(name)=David Brillert:BCM50bob") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '60'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:58] GotoIf("Zap/23-1", "1?60") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,60)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '62'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:60] GotoIf("Zap/23-1", "1?62") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,62)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:62] Set("Zap/23-1", "CALLFILENAME=1296061927.4") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '65'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:63] GotoIf("Zap/23-1", "1?65") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,65)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '67'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:65] GotoIf("Zap/23-1", "1?67") in new stack
[2011-01-26 12:12:07]     -- Goto (all-incoming-check,s,67)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Return'
[2011-01-26 12:12:07]     -- Executing [s@all-incoming-check:67] Return("Zap/23-1", "") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Answer'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:10] Answer("Zap/23-1", "") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/23
[2011-01-26 12:12:07] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Goto'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:11] Goto("Zap/23-1", "20") in new stack
[2011-01-26 12:12:07]     -- Goto (zap-incoming,6010,20)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Zap/23 - state 2 (In use)
[2011-01-26 12:12:07] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Zap/23' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '23'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:20] GotoIf("Zap/23-1", "0?23") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'cidname/91800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is ''
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '22'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '23'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:21] GotoIf("Zap/23-1", "0?22:23") in new stack
[2011-01-26 12:12:07]     -- Goto (zap-incoming,6010,23)
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '25'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:23] GotoIf("Zap/23-1", "0?25") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'blacklist/91800555123'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is ''
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:24] GotoIf("Zap/23-1", "0?all-blacklisted|s|1") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:25] Set("Zap/23-1", "__CALLDIVERT=YES") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Dial'
[2011-01-26 12:12:07]     -- Executing [6010@zap-incoming:26] Dial("Zap/23-1", "Local/6010@default-local/n|") in new stack
[2011-01-26 12:12:07] DEBUG[15303]: rtp.c:1697 ast_rtp_make_compatible: Channel 'Local/6010@default-local-1671,1' has no RTP, not doing anything
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable CALLDIVERT.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable CALLFILENAME.
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable FAXNUMBER.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable ORGCALLID.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable EXTCONTEXT.
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_MOH.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_CLID_NAME_DEF.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_CLID_NUM_DEF.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_CLID_NAME.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_CLID_NUM.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_LANGUAGE.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LINE_TENANT.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable CALLEDTON.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable PRIREDIRECTREASON.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ANI2.
[2011-01-26 12:12:07] DEBUG[15303]: channel.c:4107 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY.
[2011-01-26 12:12:07]     -- Called 6010@default-local/n
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@default-local:1] Set("Local/6010@default-local-1671,2", "LOCAL_EXTEN=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@default-local:2] Set("Local/6010@default-local-1671,2", "LOCAL_LIMIT=1") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Gosub'
[2011-01-26 12:12:07]     -- Executing [6010@default-local:3] Gosub("Local/6010@default-local-1671,2", "all-local-extension|s|1") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:1] Set("Local/6010@default-local-1671,2", "__PICKUPMARK=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '4'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:2] GotoIf("Local/6010@default-local-1671,2", "0?4") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:3] Set("Local/6010@default-local-1671,2", "GROUP(OUTGOING)=91800555123") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:4] Set("Local/6010@default-local-1671,2", "OUTBOUND_GROUP_ONCE=6010@INCOMING") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '8'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:5] GotoIf("Local/6010@default-local-1671,2", "0?8") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '0'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:6] Set("Local/6010@default-local-1671,2", "GROUPCOUNT=0") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '0'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:7] Set("Local/6010@default-local-1671,2", "GROUPCOUNT2=0") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Return'
[2011-01-26 12:12:07]     -- Executing [s@all-local-extension:8] Return("Local/6010@default-local-1671,2", "") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [6010@default-local:4] Set("Local/6010@default-local-1671,2", "SCOPSERV_DBPUT(default/wrapup/6010/lastcall)=1296061927.6") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1296061927.6'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'default/wrapup/6010/lastcall'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Macro'
[2011-01-26 12:12:07]     -- Executing [6010@default-local:5] Macro("Local/6010@default-local-1671,2", "default-dial|SIP/6010|6010|default|20|en|b6010@default|tkK||default||Local/s@default-aa-operator-6010|disa") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'David Brillert:BCM50bob'
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'NoOp'
[2011-01-26 12:12:07]     -- Executing [s@macro-default-dial:1] NoOp("Local/6010@default-local-1671,2", ""CALL TO LOCAL EXTENSION FROM 91800555123(David Brillert:BCM50bob)"") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: app_macro.c:379 _macro_exec: Executed application: NoOp
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'Set'
[2011-01-26 12:12:07]     -- Executing [s@macro-default-dial:2] Set("Local/6010@default-local-1671,2", "__PICKUPMARK=6010") in new stack
[2011-01-26 12:12:07] DEBUG[15309]: app_macro.c:379 _macro_exec: Executed application: Set
[2011-01-26 12:12:07] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'AGI'
[2011-01-26 12:12:07]     -- Executing [s@macro-default-dial:3] AGI("Local/6010@default-local-1671,2", "agi://127.0.0.1:4573/dial") in new stack
[2011-01-26 12:12:07] DEBUG[32066]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15311]: manager.c:2277 process_message: Manager received command 'login'
[2011-01-26 12:12:07]   == Parsing '/etc/asterisk/manager.conf': [2011-01-26 12:12:07] DEBUG[15311]: config.c:895 config_text_file_load: Parsing /etc/asterisk/manager.conf
[2011-01-26 12:12:07] Found
[2011-01-26 12:12:07] DEBUG[15311]: acl.c:355 ast_append_ha: 127.0.0.1/255.255.255.255 appended to acl for peer
[2011-01-26 12:12:07] DEBUG[15311]: acl.c:370 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.1
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG1' result is SIP/6010
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG2' result is 6010
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG3' result is default
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG4' result is 20
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG5' result is en
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG6' result is b6010@default
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG7' result is tkK
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG8' result is 
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG9' result is default
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG10' result is 
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG11' result is Local/s@default-aa-operator-6010
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'ARG12' result is disa
[2011-01-26 12:12:07] DEBUG[32065]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'EXT_ACCODE' result is not defined!!!
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'MACRO_PRIORITY' result is 5
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'CALLBACK_ON_HANGUP' result is not defined!!!
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'CLID_BLOCK' result is not defined!!!
[2011-01-26 12:12:07] DEBUG[15309]: db.c:196 ast_db_get: Unable to find key 'SIP/6010' in family 'DND'
[2011-01-26 12:12:07] DEBUG[15309]: db.c:196 ast_db_get: Unable to find key '6010' in family 'DND'
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'INCOMINGLINE' result is 1
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'MONITOR_OPTION' result is not defined!!!
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'AUTO_RECORDING' result is not defined!!!
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'FORCE_RECORDING' result is not defined!!!
[2011-01-26 12:12:07]     -- AGI Script Executing Application: (MixMonitor) Options: (default-super_1296061927.6.WAV|b)
[2011-01-26 12:12:07]   == Begin MixMonitor Recording Local/6010@default-local-1671,2
[2011-01-26 12:12:07] DEBUG[15309]: func_audiohookinherit.c:146 setup_inheritable_audiohook: Set audiohook MixMonitor to be inheritable
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'LIMIT_IN_DEFAULT_6010' result is 8
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'GROUPCOUNT' result is 0
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07]   agi://127.0.0.1:4573/dial: Variable 'GROUPCOUNT2' result is 0
[2011-01-26 12:12:07] DEBUG[15311]: manager.c:2277 process_message: Manager received command 'ExtensionState'
[2011-01-26 12:12:07] DEBUG[15311]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07]     -- AGI Script Executing Application: (NoOp) Options: (STATUS:)
[2011-01-26 12:12:07]     -- AGI Script Executing Application: (Dial) Options: (SIP/6010|20|tkKT|)
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:17865 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:3030 do_setnat: Setting NAT on RTP to Off
[2011-01-26 12:12:07] DEBUG[15309]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 192.168.0.0
[2011-01-26 12:12:07] DEBUG[15309]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 10.0.0.0
[2011-01-26 12:12:07] DEBUG[15309]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 172.16.0.0
[2011-01-26 12:12:07] DEBUG[15309]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 169.254.0.0
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4389 sip_new: *** Our native formats are 0x4 (ulaw) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4390 sip_new: *** Joint capabilities are 0x0 (nothing) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4391 sip_new: *** Our capabilities are 0x4 (ulaw) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4392 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4394 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:4415 sip_new: This channel will not be able to handle video.
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable TOUCH_MIXMONITOR.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable TOUCH_MONITOR.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG12.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG11.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG10.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG9.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG8.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG7.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG6.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG5.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG4.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG3.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG2.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ARG1.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable ODBCROWS.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable GROUPCOUNT2.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable GROUPCOUNT.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LOCAL_LIMIT.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4107 ast_channel_inherit_variables: Not copying variable LOCAL_EXTEN.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable CALLDIVERT.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable ORGCALLID.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable EXTCONTEXT.
[2011-01-26 12:12:07] DEBUG[15309]: channel.c:4102 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS.
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:3315 sip_call: Outgoing Call for 6010
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:3534 update_call_counter: Updating call counter for outgoing call
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:3611 update_call_counter: Call to peer '6010' is 1 out of 8
[2011-01-26 12:12:07] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:07] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 6 (Ringing)
[2011-01-26 12:12:07] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '6' (Ringing)
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:3330 sip_call: Our T38 capability (16144), joint T38 capability (16144)
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:7118 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:7119 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:7243 add_sdp: -- Done with adding codecs to SDP
[2011-01-26 12:12:07] DEBUG[15309]: chan_sip.c:7342 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[2011-01-26 12:12:07]     -- Called 6010
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2367 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254' Request 102: Found
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07]  Extension Changed 6010[default-local] new state Ringing for Notify User 6010 
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07]  Extension Changed 6010[default-local] new state Ringing for Notify User 6002 
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 106
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '3e66e857-47074f7a-161befb9@192.168.30.107' of Request 106: Match Found
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 106
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on 'b3fd928b-69799260-270db259@192.168.30.194' of Request 106: Match Found
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[32071]: chan_sip.c:2367 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254' Request 102: Found
[2011-01-26 12:12:07] DEBUG[32071]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:07] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 6 (Ringing)
[2011-01-26 12:12:07] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:07] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '6' (Ringing)
[2011-01-26 12:12:07]     -- SIP/6010-00000001 is ringing
[2011-01-26 12:12:07] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-local
[2011-01-26 12:12:07] DEBUG[32047]: chan_local.c:216 local_devicestate: Checking if extension 6010@default-local exists (devicestate)
[2011-01-26 12:12:07] DEBUG[32047]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x8e9af78'
[2011-01-26 12:12:07] DEBUG[32047]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x8e9af78'
[2011-01-26 12:12:07] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-local - state 2 (In use)
[2011-01-26 12:12:07]     -- Local/6010@default-local-1671,1 is ringing
[2011-01-26 12:12:07] DEBUG[15303]: rtp.c:1615 ast_rtp_early_bridge: Channel 'Zap/23-1' has no RTP, not doing anything
[2011-01-26 12:12:07] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 3 on channel Zap/23-1
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Local/6010@default-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:07] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[32063]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 102
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254' of Request 102: Match Found
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP o=- 1296061920 1296061920 IN IP4 192.168.30.194... UNSUPPORTED.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.194... OK.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5758 process_sdp: T38 state changed to 0 on channel SIP/6010-00000001
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:5891 process_sdp: We're settling with these formats: 0x4 (ulaw)
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:3534 update_call_counter: Updating call counter for outgoing call
[2011-01-26 12:12:08] DEBUG[32071]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:08] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 2 (In use)
[2011-01-26 12:12:08] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '2' (In use)
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6010@192.168.30.194:5060>
[2011-01-26 12:12:08] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:08]     -- SIP/6010-00000001 answered Local/6010@default-local-1671,2
[2011-01-26 12:12:08] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-local
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:08]     -- Local/6010@default-local-1671,1 stopped sounds
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-local
[2011-01-26 12:12:08] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 2 (In use)
[2011-01-26 12:12:08] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08] DEBUG[32047]: chan_local.c:216 local_devicestate: Checking if extension 6010@default-local exists (devicestate)
[2011-01-26 12:12:08] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-local - state 2 (In use)
[2011-01-26 12:12:08] DEBUG[32047]: chan_local.c:216 local_devicestate: Checking if extension 6010@default-local exists (devicestate)
[2011-01-26 12:12:08] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-local - state 2 (In use)
[2011-01-26 12:12:08] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '2' (In use)
[2011-01-26 12:12:08] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Local/6010@default-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:08] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Local/6010@default-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:08]     -- Local/6010@default-local-1671,1 answered Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: rtp.c:1615 ast_rtp_early_bridge: Channel 'Zap/23-1' has no RTP, not doing anything
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: channel.c:4686 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/6010@default-local-1671,1
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:08] DEBUG[15303]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/6010@default-local-1671,1
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2970 ast_rtp_write: Ooh, format changed from unknown to ulaw
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15309]: rtp.c:2987 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08]  Extension Changed 6010[default-local] new state InUse for Notify User 6010 
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:08]  Extension Changed 6010[default-local] new state InUse for Notify User 6002 
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 107
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '3e66e857-47074f7a-161befb9@192.168.30.107' of Request 107: Match Found
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 107
[2011-01-26 12:12:08] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on 'b3fd928b-69799260-270db259@192.168.30.194' of Request 107: Match Found
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[32069]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[32062]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[32061]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:08] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[32064]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:09] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP o=- 1296061920 1296061921 IN IP4 192.168.30.194... UNSUPPORTED.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.194... OK.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP a=sendonly... OK.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=sendonly... OK.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5758 process_sdp: T38 state changed to 0 on channel SIP/6010-00000001
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:5891 process_sdp: We're settling with these formats: 0x4 (ulaw)
[2011-01-26 12:12:09] DEBUG[32071]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:09] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:09] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 8 (On Hold)
[2011-01-26 12:12:09] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '8' (On Hold)
[2011-01-26 12:12:09] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:15716 handle_request_invite: SIP/6010-00000001: This call is UP.... 
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:7400 transmit_response_with_sdp: Setting framing from config on incoming call
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:7118 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:7119 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:7243 add_sdp: -- Done with adding codecs to SDP
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:7342 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[2011-01-26 12:12:09] DEBUG[15309]: channel.c:3469 set_format: Set channel Local/6010@default-local-1671,2 to write format slin
[2011-01-26 12:12:09]     -- Started music on hold, class 'default', on channel 'Local/6010@default-local-1671,2'
[2011-01-26 12:12:09] DEBUG[15309]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals
[2011-01-26 12:12:09] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:09] DEBUG[15309]: channel.c:2135 ast_read_generator_actions: Generator got voice, switching to phase locked mode
[2011-01-26 12:12:09] DEBUG[15309]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:09]  Extension Changed 6010[default-local] new state Hold for Notify User 6010 
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:09]  Extension Changed 6010[default-local] new state Hold for Notify User 6002 
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 108
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '3e66e857-47074f7a-161befb9@192.168.30.107' of Request 108: Match Found
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254' of Response 1: Match Found
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 108
[2011-01-26 12:12:09] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on 'b3fd928b-69799260-270db259@192.168.30.194' of Request 108: Match Found
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:09] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:231 audiohook_read_frame_both: Write factory 0x8ea7aac was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5369 __dahdi_exception: Exception on 54, channel 23
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0)
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0'
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: channel.c:4709 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1)
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/6010@default-local-1671,1
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5369 __dahdi_exception: Exception on 54, channel 23
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0)
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0'
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 192.168.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 10.0.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 172.16.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 169.254.0.0
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3030 do_setnat: Setting NAT on RTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3035 do_setnat: Setting NAT on VRTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3040 do_setnat: Setting NAT on UDPTL to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for 76abb80e-191f669f-a2cea604@192.168.30.194 - INVITE (With RTP)
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3030 do_setnat: Setting NAT on RTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3035 do_setnat: Setting NAT on VRTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3040 do_setnat: Setting NAT on UDPTL to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '76abb80e-191f669f-a2cea604@192.168.30.194' of Response 1: Match Found
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3030 do_setnat: Setting NAT on RTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3035 do_setnat: Setting NAT on VRTP to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3040 do_setnat: Setting NAT on UDPTL to Off
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP o=- 1296061922 1296061922 IN IP4 192.168.30.194... UNSUPPORTED.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP c=IN IP4 192.168.30.194... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5585 process_sdp: Processing session-level SDP a=sendrecv... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5733 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5758 process_sdp: T38 state changed to 0 on channel <none>
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:5891 process_sdp: We're settling with these formats: 0x4 (ulaw)
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:15538 handle_request_invite: Checking SIP call limits for device 6010
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3534 update_call_counter: Updating call counter for incoming call
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:3611 update_call_counter: Call from peer '6010' is 2 out of 8
[2011-01-26 12:12:10] DEBUG[32071]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 8 (On Hold)
[2011-01-26 12:12:10] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '8' (On Hold)
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4389 sip_new: *** Our native formats are 0x4 (ulaw) 
[2011-01-26 12:12:10] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4390 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4391 sip_new: *** Our capabilities are 0x4 (ulaw) 
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4392 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4415 sip_new: This channel will not be able to handle video.
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6010@192.168.30.194:5060>
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:15642 handle_request_invite: SIP/6010-00000002: New call is still down.... Trying... 
[2011-01-26 12:12:10] DEBUG[32071]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 8 (On Hold)
[2011-01-26 12:12:10] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '8' (On Hold)
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[15303]: channel.c:4709 ast_generic_bridge: Got DTMF end on channel (Zap/23-1)
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[15303]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/6010@default-local-1671,1
[2011-01-26 12:12:10] DEBUG[15303]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/6010@default-local-1671,1, code=0, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-*
[2011-01-26 12:12:10] DEBUG[15315]: pbx.c:1873 pbx_extension_helper: Launching 'Park'
[2011-01-26 12:12:10]     -- Executing [7000@default-super:1] Park("SIP/6010-00000002", "") in new stack
[2011-01-26 12:12:10] DEBUG[15315]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 8 (On Hold)
[2011-01-26 12:12:10] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '8' (On Hold)
[2011-01-26 12:12:10] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:4014 sip_answer: SIP answering channel: SIP/6010-00000002
[2011-01-26 12:12:10] DEBUG[15315]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:7400 transmit_response_with_sdp: Setting framing from config on incoming call
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:7118 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:7119 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:7243 add_sdp: -- Done with adding codecs to SDP
[2011-01-26 12:12:10] DEBUG[15315]: chan_sip.c:7342 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[2011-01-26 12:12:10] DEBUG[32058]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '76abb80e-191f669f-a2cea604@192.168.30.194' of Response 2: Match Found
[2011-01-26 12:12:10] DEBUG[15309]: channel.c:4709 ast_generic_bridge: Got DTMF begin on channel (Local/6010@default-local-1671,2)
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[15309]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Local/6010@default-local-1671,2 and SIP/6010-00000001
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 192.168.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 10.0.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 172.16.0.0
[2011-01-26 12:12:10] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 169.254.0.0
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for 50a85830-f55e37eb-5e2b56a@192.168.30.150 - SUBSCRIBE (No RTP)
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6003@192.168.30.150:5060>
[2011-01-26 12:12:10] DEBUG[32059]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:9050 build_route: build_route: Retaining previous route: <sip:6003@192.168.30.150:5060>
[2011-01-26 12:12:10] DEBUG[32071]: chan_sip.c:16754 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary
[2011-01-26 12:12:10] DEBUG[15309]: channel.c:4709 ast_generic_bridge: Got DTMF end on channel (Local/6010@default-local-1671,2)
[2011-01-26 12:12:10] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:10] DEBUG[15309]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Local/6010@default-local-1671,2 and SIP/6010-00000001
[2011-01-26 12:12:10] DEBUG[15309]: res_features.c:1769 feature_interpret: Feature interpret: chan=Local/6010@default-local-1671,2, peer=SIP/6010-00000001, code=0, sense=1, features=34, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-*
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:278 audiohook_read_frame_both: Failed to get 160 samples from write factory 0x8ea7aac
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:10] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:224 audiohook_read_frame_both: Read factory 0x8ea7090 and write factory 0x8ea7aac both fail to provide 160 samples
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:11] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:11] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[32066]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[32065]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4031 ast_channel_masquerade: Planning to masquerade channel SIP/6010-00000002 into the structure of Parked/SIP/6010-00000002
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4040 ast_channel_masquerade: Done planning to masquerade channel SIP/6010-00000002 into the structure of Parked/SIP/6010-00000002
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4196 ast_do_masquerade: Got clone lock for masquerade on 'SIP/6010-00000002' at 0x8ec6da8
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4382 ast_do_masquerade: Putting channel SIP/6010-00000002 in 4/4 formats
[2011-01-26 12:12:11] DEBUG[15315]: chan_sip.c:4159 sip_fixup: SIP Fixup: New owner for dialogue 76abb80e-191f669f-a2cea604@192.168.30.194: SIP/6010-00000002 (Old parent: Parked/SIP/6010-00000002<ZOMBIE>)
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4430 ast_do_masquerade: Released clone lock on 'Parked/SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:4440 ast_do_masquerade: Done Masquerading SIP/6010-00000002 (6)
[2011-01-26 12:12:11] DEBUG[15315]: rtp.c:2131 ast_rtp_change_source: Changing ssrc from 1706261706 to 359237445 due to a source change
[2011-01-26 12:12:11]   == Parked SIP/6010-00000002 on 7001@parkedcalls. Will timeout back to extension [default-super] s, 1 in 45 seconds
[2011-01-26 12:12:11] DEBUG[15315]: pbx.c:4996 ast_add_extension2: Added extension '7001' priority 1 to parkedcalls
[2011-01-26 12:12:11]     -- Added extension '7001' priority 1 to parkedcalls
[2011-01-26 12:12:11] DEBUG[15315]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel park:7001@parkedcalls
[2011-01-26 12:12:11] DEBUG[15315]: rtp.c:2970 ast_rtp_write: Ooh, format changed from unknown to ulaw
[2011-01-26 12:12:11] DEBUG[15315]: rtp.c:2987 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[2011-01-26 12:12:11] DEBUG[15315]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals
[2011-01-26 12:12:11]     -- <SIP/6010-00000002> Playing 'digits/7' (language 'en')
[2011-01-26 12:12:11] DEBUG[32047]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 7001@parkedcalls
[2011-01-26 12:12:11] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for park:7001@parkedcalls - state 2 (In use)
[2011-01-26 12:12:11] DEBUG[32068]: manager.c:2277 process_message: Manager received command 'GetVar'
[2011-01-26 12:12:11] DEBUG[32047]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 7001@parkedcalls
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[32071]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 7001@parkedcalls
[2011-01-26 12:12:11]  Extension Changed 7001[default-local] new state InUse for Notify User 6002 
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 103
[2011-01-26 12:12:11] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on 'a3cdb6ca-a76df349-99587794@192.168.30.107' of Request 103: Match Found
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:11] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:10198 get_refer_info: Attended transfer: Will use Replace-Call-ID : 76abb80e-191f669f-a2cea604@192.168.30.194 (No check of from/to tags)
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:14546 attempt_transfer: SIP transfer: Four channels to handle
[2011-01-26 12:12:12] DEBUG[32071]: channel.c:3469 set_format: Set channel Local/6010@default-local-1671,2 to write format ulaw
[2011-01-26 12:12:12]     -- Stopped music on hold on Local/6010@default-local-1671,2
[2011-01-26 12:12:12] DEBUG[32071]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals
[2011-01-26 12:12:12] DEBUG[32071]: channel.c:4031 ast_channel_masquerade: Planning to masquerade channel Local/6010@default-local-1671,2 into the structure of SIP/6010-00000002
[2011-01-26 12:12:12] DEBUG[32071]: channel.c:4040 ast_channel_masquerade: Done planning to masquerade channel Local/6010@default-local-1671,2 into the structure of SIP/6010-00000002
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:14569 attempt_transfer: SIP transfer: Succeeded to masquerade channels.
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:15918 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/6010-00000002
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:4196 ast_do_masquerade: Got clone lock for masquerade on 'Local/6010@default-local-1671,2' at 0x8e9aff0
[2011-01-26 12:12:12] DEBUG[15315]: chan_sip.c:4159 sip_fixup: SIP Fixup: New owner for dialogue 76abb80e-191f669f-a2cea604@192.168.30.194: Local/6010@default-local-1671,2<MASQ> (Old parent: Local/6010@default-local-1671,2)
[2011-01-26 12:12:12] DEBUG[15315]: chan_sip.c:3852 sip_hangup: Hangup call Local/6010@default-local-1671,2<MASQ>, SIP callid 76abb80e-191f669f-a2cea604@192.168.30.194)
[2011-01-26 12:12:12] DEBUG[15315]: chan_sip.c:3534 update_call_counter: Updating call counter for incoming call
[2011-01-26 12:12:12] DEBUG[15315]: chan_sip.c:3585 update_call_counter: Call from peer '6010' removed from call limit 8
[2011-01-26 12:12:12] DEBUG[15315]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:12] DEBUG[15315]: func_audiohookinherit.c:70 audiohook_inheritance_fixup: inheritance fixup occurring for channels SIP/6010-00000002<ZOMBIE>(0x8e9af78) and Local/6010@default-local-1671,2(0x8ed0108)[2011-01-26 12:12:12] DEBUG[15315]: func_audiohookinherit.c:76 audiohook_inheritance_fixup: Moved audiohook MixMonitor from SIP/6010-00000002<ZOMBIE>(0x8e9af78) to Local/6010@default-local-1671,2(0x8ed0108)
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:4382 ast_do_masquerade: Putting channel Local/6010@default-local-1671,2 in 4/4 formats
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:4430 ast_do_masquerade: Released clone lock on 'SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15314]: audiohook.c:238 audiohook_read_frame_both: Read factory 0x8ea7090 was pretty quick last time, waiting for them.
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 8 (On Hold)
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:4907 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/6010-00000002<ZOMBIE>, c1=SIP/6010-00000001, flags: Yes,Yes,No,No
[2011-01-26 12:12:12] DEBUG[15309]: rtp.c:2119 ast_rtp_new_source: Setting the marker bit due to a source update
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels SIP/6010-00000002<ZOMBIE> and SIP/6010-00000001
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '8' (On Hold)
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'ResetCDR'
[2011-01-26 12:12:12]     -- Executing [h@macro-default-dial:1] ResetCDR("SIP/6010-00000002<ZOMBIE>", "w") in new stack
[2011-01-26 12:12:12] DEBUG[15309]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '"David Brillert:BCM50bob" <1800555123>'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '6010'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'default-local'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/6010@default-local-1671,2'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'SIP/6010-00000001'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Dial'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'SIP/6010|20|tkKT|'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:07'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:08'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:12'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '5'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '4'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '_NONE_'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1296061927.6'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '(null)'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:1873 pbx_extension_helper: Launching 'NoCDR'
[2011-01-26 12:12:12]     -- Executing [h@macro-default-dial:2] NoCDR("SIP/6010-00000002<ZOMBIE>", "") in new stack
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x8ed0108'
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x8ed0108'
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254' of Request 103: Match Found
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:4440 ast_do_masquerade: Done Masquerading Local/6010@default-local-1671,2 (6)
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:3469 set_format: Set channel Local/6010@default-local-1671,2 to write format slin
[2011-01-26 12:12:12]     -- Started music on hold, class 'default', on channel 'Local/6010@default-local-1671,2'
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals
[2011-01-26 12:12:12] DEBUG[15315]: pbx.c:2480 __ast_pbx_run: Spawn extension (default-super,s,1) exited non-zero on 'Parked/SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12]   == Spawn extension (default-super, s, 1) exited non-zero on 'Parked/SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:1603 ast_softhangup_nolock: Soft-Hanging up channel 'Parked/SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15303]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 21 on channel Zap/23-1
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:14223 handle_response: Got 200 OK on NOTIFY for transfer
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:1761 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 52f73ce87cae73bb0e685eb619b832f1@192.168.30.254
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:16474 handle_request_bye: Received bye, issuing owner hangup
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:1706 ast_hangup: Hanging up channel 'SIP/6010-00000001'
[2011-01-26 12:12:12] DEBUG[15309]: chan_sip.c:3534 update_call_counter: Updating call counter for outgoing call
[2011-01-26 12:12:12] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:12] DEBUG[15309]: chan_sip.c:3585 update_call_counter: Call to peer '6010' removed from call limit 8
[2011-01-26 12:12:12] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:12] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:12] DEBUG[15309]: rtp.c:1623 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[2011-01-26 12:12:12] DEBUG[15309]: app_dial.c:1938 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[2011-01-26 12:12:12] DEBUG[15309]: res_agi.c:1925 run_agi: SIP/6010-00000002<ZOMBIE> hungup
[2011-01-26 12:12:12] DEBUG[15309]: app_macro.c:372 _macro_exec: Spawn extension (macro-default-dial,s,3) exited non-zero on 'SIP/6010-00000002<ZOMBIE>' in macro 'default-dial'
[2011-01-26 12:12:12] DEBUG[15309]: pbx.c:2480 __ast_pbx_run: Spawn extension (default-local,6010,5) exited non-zero on 'SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12]   == Spawn extension (default-local, 6010, 5) exited non-zero on 'SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:1603 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15309]: channel.c:1711 ast_hangup: Hanging up zombie 'SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15309]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6010
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for SIP/6010 - state 1 (Not in use)
[2011-01-26 12:12:12] DEBUG[32047]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '76abb80e-191f669f-a2cea604@192.168.30.194' of Request 102: Match Found
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use)
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use)
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use)
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:718 handle_statechange: Device 'SIP/6010' changed to state '1' (Not in use)
[2011-01-26 12:12:12] DEBUG[15315]: channel.c:1711 ast_hangup: Hanging up zombie 'Parked/SIP/6010-00000002<ZOMBIE>'
[2011-01-26 12:12:12] DEBUG[15315]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Parked/SIP/6010
[2011-01-26 12:12:12] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Parked/SIP/6010 - state 4 (Invalid)
[2011-01-26 12:12:12] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Parked/SIP/6010' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12]  Extension Changed 6010[default-local] new state Idle for Notify User 6010 
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:17789 sip_devicestate: Checking device state for peer 6010
[2011-01-26 12:12:12]  Extension Changed 6010[default-local] new state Idle for Notify User 6002 
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 109
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '3e66e857-47074f7a-161befb9@192.168.30.107' of Request 109: Match Found
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2293 __sip_ack: Acked pending invite 109
[2011-01-26 12:12:12] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on 'b3fd928b-69799260-270db259@192.168.30.194' of Request 109: Match Found
[2011-01-26 12:12:12] DEBUG[32063]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:12] DEBUG[32062]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:12] DEBUG[32061]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:13] DEBUG[32064]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:13] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:14] WARNING[15303]: channel.c:985 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/6010@default-local-1671,2
[2011-01-26 12:12:14] DEBUG[32058]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:14] DEBUG[32059]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:15] DEBUG[32066]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:15] WARNING[15303]: channel.c:985 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/6010@default-local-1671,2
[2011-01-26 12:12:15] DEBUG[32065]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32063]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16]     -- Channel 0/23, span 1 got hangup request, cause 16
[2011-01-26 12:12:16] DEBUG[15303]: channel.c:4658 ast_generic_bridge: Didn't get a frame from channel: Zap/23-1
[2011-01-26 12:12:16] DEBUG[15303]: channel.c:5024 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/6010@default-local-1671,1
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'Goto'
[2011-01-26 12:12:16]     -- Executing [h@zap-incoming:1] Goto("Zap/23-1", "all-hangup|s|1") in new stack
[2011-01-26 12:12:16]     -- Goto (all-hangup,s,1)
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '2'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf'
[2011-01-26 12:12:16]     -- Executing [s@all-hangup:1] GotoIf("Zap/23-1", "0?all-faxnotify|s|1:2") in new stack
[2011-01-26 12:12:16]     -- Goto (all-hangup,s,2)
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'ResetCDR'
[2011-01-26 12:12:16]     -- Executing [s@all-hangup:2] ResetCDR("Zap/23-1", "w") in new stack
[2011-01-26 12:12:16] DEBUG[15303]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded!
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '"David Brillert:BCM50bob" <1800555123>'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '6010'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'zap-incoming'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Zap/23-1'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/6010@default-local-1671,1'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Dial'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/6010@default-local/n|'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:07'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:08'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-01-26 12:12:16'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '9'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '8'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '_NONE_'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1296061927.4'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '6010'
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:1873 pbx_extension_helper: Launching 'NoCDR'
[2011-01-26 12:12:16]     -- Executing [s@all-hangup:3] NoCDR("Zap/23-1", "") in new stack
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[15303]: channel.c:1706 ast_hangup: Hanging up channel 'Local/6010@default-local-1671,1'
[2011-01-26 12:12:16] DEBUG[15303]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6010@default-local
[2011-01-26 12:12:16] DEBUG[15303]: rtp.c:1615 ast_rtp_early_bridge: Channel 'Zap/23-1' has no RTP, not doing anything
[2011-01-26 12:12:16] DEBUG[15303]: app_dial.c:1938 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[2011-01-26 12:12:16] DEBUG[15303]: pbx.c:2480 __ast_pbx_run: Spawn extension (all-hangup,6010,26) exited non-zero on 'Zap/23-1'
[2011-01-26 12:12:16]   == Spawn extension (all-hangup, 6010, 26) exited non-zero on 'Zap/23-1'
[2011-01-26 12:12:16] DEBUG[15303]: channel.c:1603 ast_softhangup_nolock: Soft-Hanging up channel 'Zap/23-1'
[2011-01-26 12:12:16] DEBUG[15303]: channel.c:1706 ast_hangup: Hanging up channel 'Zap/23-1'
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:2893 dahdi_hangup: dahdi_hangup(Zap/23-1)
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:3499 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/23-1
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:2928 dahdi_hangup: Hangup: channel: 23 index = 0, normal = 54, callwait = -1, thirdcall = -1
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:3127 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:1878 dahdi_disable_ec: disabled echo cancellation on channel 23
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:3413 dahdi_setoption: Set option TDD MODE, value: OFF(0) on Zap/23-1
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:1814 update_conf: Updated conferencing on 23, with 0 conference users
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:3495 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/23-1
[2011-01-26 12:12:16] DEBUG[15303]: chan_dahdi.c:1878 dahdi_disable_ec: disabled echo cancellation on channel 23
[2011-01-26 12:12:16]     -- Hungup 'Zap/23-1'
[2011-01-26 12:12:16] DEBUG[32047]: chan_local.c:216 local_devicestate: Checking if extension 6010@default-local exists (devicestate)
[2011-01-26 12:12:16] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Local/6010@default-local - state 2 (In use)
[2011-01-26 12:12:16] DEBUG[15303]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/23
[2011-01-26 12:12:16] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Local/6010@default-local' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:16] DEBUG[32047]: devicestate.c:287 do_state_change: Changing state for Zap/23 - state 0 (Unknown)
[2011-01-26 12:12:16] DEBUG[32101]: app_queue.c:713 handle_statechange: Device 'Zap/23' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32062]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32061]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:16] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32064]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0
[2011-01-26 12:12:17] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0
[2011-01-26 12:12:17] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0
[2011-01-26 12:12:17] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0
[2011-01-26 12:12:17] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for f50bbacf-a0d9f9e6-f59b0b71@192.168.30.86 - SUBSCRIBE (No RTP)
[2011-01-26 12:12:17] DEBUG[32071]: chan_sip.c:9112 build_route: build_route: Contact hop: <sip:6057@192.168.30.86:5060>
[2011-01-26 12:12:17] DEBUG[32071]: chan_sip.c:9050 build_route: build_route: Retaining previous route: <sip:6057@192.168.30.86:5060>
[2011-01-26 12:12:17] DEBUG[32071]: chan_sip.c:16754 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:17] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32058]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32071]: chan_sip.c:2215 __sip_autodestruct: Auto destroying SIP dialog '52f73ce87cae73bb0e685eb619b832f1@192.168.30.254'
[2011-01-26 12:12:18] DEBUG[32071]: chan_sip.c:3643 sip_destroy: Destroying SIP dialog 52f73ce87cae73bb0e685eb619b832f1@192.168.30.254
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32059]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32069]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:18] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[2011-01-26 12:12:18] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 192.168.0.0
[2011-01-26 12:12:18] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 10.0.0.0
[2011-01-26 12:12:18] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 172.16.0.0
[2011-01-26 12:12:18] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 169.254.0.0
[2011-01-26 12:12:18] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '1351291a65e4d897731f30b23ed955ae@192.168.30.254' of Request 102: Match Found
[2011-01-26 12:12:18] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32066]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32065]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:19] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32063]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32062]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32061]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:20] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32064]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32060]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
lab*CLI> core show channels
Channel              Location             State   Application(Data)             
Local/6010@default-l s@default-super:1    Up      Parked Call()                 
1 active channel
0 of 460 max active calls ( 0.00% of capacity)
[2011-01-26 12:12:21] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:21] DEBUG[32071]: chan_sip.c:4947 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[2011-01-26 12:12:21] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 192.168.0.0
[2011-01-26 12:12:21] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 10.0.0.0
[2011-01-26 12:12:21] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 172.16.0.0
[2011-01-26 12:12:21] DEBUG[32071]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 169.254.0.0
[2011-01-26 12:12:22] DEBUG[32071]: chan_sip.c:2325 __sip_ack: Stopping retransmission on '4bcf5f0d5a37bdc373eff0b53e48cfc0@192.168.30.254' of Request 102: Match Found
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32058]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32059]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:22] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32066]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32065]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:23] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32072]: manager.c:2277 process_message: Manager received command 'Ping'
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe
[2011-01-26 12:12:24] DEBUG[32051]: res_musiconhold.c:613 monmp3thread: Only wrote -1 of 640 bytes to pipe