[2011-02-07 13:53:11] -- Accepting call from '1800555123' to '6900' on channel 0/23, span 1 [2011-02-07 13:53:11] DEBUG[4069]: chan_dahdi.c:1846 dahdi_enable_ec: Enabled echo cancellation on channel 23 [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:1] Set("Zap/23-1", "__INCOMING_DNIS=6900") in new stack [2011-02-07 13:53:11] DEBUG[4080]: manager.c:2277 process_message: Manager received command 'GetVar' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:2] Set("Zap/23-1", "LINE_TENANT=default") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:3] Set("Zap/23-1", "LINE_LANGUAGE=en") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:4] Set("Zap/23-1", "LINE_CLID_NUM=0000000000") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:5] Set("Zap/23-1", "LINE_CLID_NAME=") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:6] Set("Zap/23-1", "LINE_CLID_NUM_DEF=91800555123") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:7] Set("Zap/23-1", "LINE_MOH=default") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Gosub' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:8] Gosub("Zap/23-1", "all-incoming-check|s|1") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'BCM50bob' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'NoOp' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:1] NoOp("Zap/23-1", ""INCOMING CALL FROM CALLER ID: 1800555123 (BCM50bob)"") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '7' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:2] GotoIf("Zap/23-1", "1?7") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,7) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '10' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:7] GotoIf("Zap/23-1", "1?10") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,10) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '12' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:10] GotoIf("Zap/23-1", "1?12") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,12) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '14' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:12] GotoIf("Zap/23-1", "1?14") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,14) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '16' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:14] GotoIf("Zap/23-1", "1?16") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,16) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '18' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:16] GotoIf("Zap/23-1", "0?18") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:17] Set("Zap/23-1", "CHANNEL(musicclass)=default") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:18] Set("Zap/23-1", "CALLERID(dnid)=6900") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:19] Set("Zap/23-1", "CDR(userfield)=6900") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:20] Set("Zap/23-1", "__EXTCONTEXT=default-default") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:21] Set("Zap/23-1", "__INCOMINGLINE=1") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1297104791.76' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:22] Set("Zap/23-1", "__ORGCALLID=1297104791.76") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '25' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:23] GotoIf("Zap/23-1", "1?25") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,25) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '27' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:25] GotoIf("Zap/23-1", "1?27") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,27) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '29' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:27] GotoIf("Zap/23-1", "1?29") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,29) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '31' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:29] GotoIf("Zap/23-1", "1?31") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,31) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'AGI' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:31] AGI("Zap/23-1", "agi://127.0.0.1:4573/fixcidname") in new stack [2011-02-07 13:53:11] -- AGI Script agi://127.0.0.1:4573/fixcidname completed, returning 0 [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '34' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:32] GotoIf("Zap/23-1", "1?34") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,34) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '36' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:34] GotoIf("Zap/23-1", "0?36") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:35] Set("Zap/23-1", "CHANNEL(language)=en") in new stack [2011-02-07 13:53:11] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0 [2011-02-07 13:53:11] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0 [2011-02-07 13:53:11] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0 [2011-02-07 13:53:11] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0 [2011-02-07 13:53:11] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for 5e6a7cd5-bc778df4-55d1d6e7@192.168.30.86 - SUBSCRIBE (No RTP) [2011-02-07 13:53:11] DEBUG[4046]: chan_sip.c:9307 build_route: build_route: Contact hop: [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:36] Set("Zap/23-1", "FAXNUMBER=6900") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '39' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:37] GotoIf("Zap/23-1", "1?39") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,39) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '41' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:39] GotoIf("Zap/23-1", "1?41") in new stack [2011-02-07 13:53:11] DEBUG[4046]: chan_sip.c:9245 build_route: build_route: Retaining previous route: [2011-02-07 13:53:11] DEBUG[4046]: chan_sip.c:16949 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,41) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '44' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:41] GotoIf("Zap/23-1", "1?44") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,44) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '49' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:44] GotoIf("Zap/23-1", "0?49") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '47' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:45] GotoIf("Zap/23-1", "1?47") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,47) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '49' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:47] GotoIf("Zap/23-1", "1?49") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,49) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '54' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:49] GotoIf("Zap/23-1", "1?54") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,54) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '56' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:54] GotoIf("Zap/23-1", "0?56") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:55] Set("Zap/23-1", "CALLERID(number)=91800555123") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '58' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:56] GotoIf("Zap/23-1", "1?58") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,58) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '60' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:58] GotoIf("Zap/23-1", "1?60") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,60) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '62' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:60] GotoIf("Zap/23-1", "1?62") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,62) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:62] Set("Zap/23-1", "CALLFILENAME=1297104791.76") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '65' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:63] GotoIf("Zap/23-1", "1?65") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,65) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '1' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '67' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:65] GotoIf("Zap/23-1", "1?67") in new stack [2011-02-07 13:53:11] -- Goto (all-incoming-check,s,67) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Return' [2011-02-07 13:53:11] -- Executing [s@all-incoming-check:67] Return("Zap/23-1", "") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Answer' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:9] Answer("Zap/23-1", "") in new stack [2011-02-07 13:53:11] DEBUG[31844]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/23 [2011-02-07 13:53:11] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c3f8e0' [2011-02-07 13:53:11] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1 [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Goto' [2011-02-07 13:53:11] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Zap/23 - state 2 (In use) [2011-02-07 13:53:11] DEBUG[4074]: 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-02-07 13:53:11] -- Executing [6900@zap-incoming:10] Goto("Zap/23-1", "20") in new stack [2011-02-07 13:53:11] -- Goto (zap-incoming,6900,20) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '23' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:20] GotoIf("Zap/23-1", "0?23") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'cidname/91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '22' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '23' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:21] GotoIf("Zap/23-1", "0?22:23") in new stack [2011-02-07 13:53:11] -- Goto (zap-incoming,6900,23) [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '25' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:23] GotoIf("Zap/23-1", "0?25") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'blacklist/91800555123' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:24] GotoIf("Zap/23-1", "0?all-blacklisted|s|1") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:6197 pbx_builtin_gotoif: Not taking any branch [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Gosub' [2011-02-07 13:53:11] -- Executing [6900@zap-incoming:25] Gosub("Zap/23-1", "default-aa-servicemainmenubutton1englishsubmenu|s|1") in new stack [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Answer' [2011-02-07 13:53:11] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:1] Answer("Zap/23-1", "") in new stack [2011-02-07 13:53:11] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1 [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'AGI' [2011-02-07 13:53:11] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:2] AGI("Zap/23-1", "agi://127.0.0.1:4573/ivr?arg1=4894") in new stack [2011-02-07 13:53:11] -- AGI Script agi://127.0.0.1:4573/ivr?arg1=4894 completed, returning 0 [2011-02-07 13:53:11] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Wait' [2011-02-07 13:53:11] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:3] Wait("Zap/23-1", "1") in new stack [2011-02-07 13:53:12] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:12] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 66.252.148.166 with 192.168.0.0 [2011-02-07 13:53:12] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 66.252.148.166 with 10.0.0.0 [2011-02-07 13:53:12] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 66.252.148.166 with 172.16.0.0 [2011-02-07 13:53:12] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 66.252.148.166 with 169.254.0.0 [2011-02-07 13:53:12] DEBUG[4046]: chan_sip.c:1952 ast_sip_ouraddrfor: Target address 66.252.148.166 is not local, substituting externip [2011-02-07 13:53:12] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '0644233152d450686989b8710ce2906b@216.235.14.204' of Request 102: Match Found [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:4] Set("Zap/23-1", "MAXCOUNT_TIMEOUT=3") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:5] Set("Zap/23-1", "COUNT_TIMEOUT=0") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:6] Set("Zap/23-1", "MAXCOUNT_INVALID=3") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:7] Set("Zap/23-1", "COUNT_INVALID=0") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:8] Set("Zap/23-1", "__IVRNAME=default-aa-servicemainmenubutton1englishsubmenu") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:9] Set("Zap/23-1", "TIMEOUT(digit)=3") in new stack [2011-02-07 13:53:12] -- Digit timeout set to 3 [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:10] Set("Zap/23-1", "TIMEOUT(response)=5") in new stack [2011-02-07 13:53:12] -- Response timeout set to 5 [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:11] Set("Zap/23-1", "CHANNEL(language)=en") in new stack [2011-02-07 13:53:12] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'BackGround' [2011-02-07 13:53:12] -- Executing [s@default-aa-servicemainmenubutton1englishsubmenu:12] BackGround("Zap/23-1", "custom/0003") in new stack [2011-02-07 13:53:12] DEBUG[31844]: channel.c:3474 set_format: Set channel Zap/23-1 to write format slin [2011-02-07 13:53:12] DEBUG[31844]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals [2011-02-07 13:53:12] -- Playing 'custom/0003' (language 'en') [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 10.0.0.122 with 192.168.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 10.0.0.122 with 10.0.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 10.0.0.122 with 172.16.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 10.0.0.122 with 169.254.0.0 [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '533c713428870dd02fc5e6b207174c55@10.0.0.138' of Request 102: Match Found [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.80 with 192.168.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.80 with 10.0.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.80 with 172.16.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.80 with 169.254.0.0 [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0 [2011-02-07 13:53:13] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0 [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '17d5d1d92222dad1101ab3c97b25808c@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:13] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '137e4cc34970f7171ba474523fdaa1f5@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 192.168.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 10.0.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 172.16.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.194 with 169.254.0.0 [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '750c98bc54e98e251e53a4c84d2b2716@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 192.168.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 10.0.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 172.16.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 169.254.0.0 [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '1cdd181c4590b7e10ed57d2c3ba46e93@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.188 with 192.168.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.188 with 10.0.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.188 with 172.16.0.0 [2011-02-07 13:53:14] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.188 with 169.254.0.0 [2011-02-07 13:53:14] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '03940280384dd95e2fed18b17117c425@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '0833ac9f541ab7a13448c10b4233cca6@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.107 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '64fd4d1657a0c9e3627b00596b173be0@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '2c762c2d45eaf41b6c893eff3744d9a9@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '58dbabd601c9add67872a9f876364632@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.118 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '1863ab5e75c597945c4186514790005e@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 192.168.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 10.0.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 172.16.0.0 [2011-02-07 13:53:15] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.129 with 169.254.0.0 [2011-02-07 13:53:15] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '16b2940f04f08f351f41cf3a4a8529bc@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131114(131114) on channel 23 (index 0) [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '*' [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x2A '*' on Zap/23-1 [2011-02-07 13:53:16] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '*' received on Zap/23-1 [2011-02-07 13:53:16] DTMF[31844]: channel.c:2549 __ast_read: DTMF begin ignored '*' on Zap/23-1 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262186(262186) on channel 23 (index 0) [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '*' [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x2A '*' on Zap/23-1 [2011-02-07 13:53:16] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '*' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:16] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '*' on Zap/23-1 [2011-02-07 13:53:16] DEBUG[31844]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:16] DEBUG[31844]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:16] DEBUG[31844]: channel.c:3474 set_format: Set channel Zap/23-1 to write format ulaw [2011-02-07 13:53:16] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'AGI' [2011-02-07 13:53:16] -- Executing [*@default-aa-servicemainmenubutton1englishsubmenu:1] AGI("Zap/23-1", "agi://127.0.0.1:4573/ivr?arg1=4894&arg2=star") in new stack [2011-02-07 13:53:16] -- AGI Script agi://127.0.0.1:4573/ivr?arg1=4894&arg2=star completed, returning 0 [2011-02-07 13:53:16] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Dial' [2011-02-07 13:53:16] -- Executing [*@default-aa-servicemainmenubutton1englishsubmenu:2] Dial("Zap/23-1", "Local/*844@default-application") in new stack [2011-02-07 13:53:16] DEBUG[31844]: rtp.c:1697 ast_rtp_make_compatible: Channel 'Local/*844@default-application-9017,1' has no RTP, not doing anything [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable AGISTATUS. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4107 ast_channel_inherit_variables: Copying hard-transferable variable IVRNAME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable COUNT_INVALID. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable MAXCOUNT_INVALID. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable COUNT_TIMEOUT. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable MAXCOUNT_TIMEOUT. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable CALLFILENAME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable FAXNUMBER. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4107 ast_channel_inherit_variables: Copying hard-transferable variable ORGCALLID. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4107 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4107 ast_channel_inherit_variables: Copying hard-transferable variable EXTCONTEXT. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_MOH. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_CLID_NUM_DEF. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_CLID_NAME. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_CLID_NUM. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_LANGUAGE. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable LINE_TENANT. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4107 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable CALLEDTON. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable PRIREDIRECTREASON. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable ANI2. [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4112 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY. [2011-02-07 13:53:16] -- Called *844@default-application [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '91800555123' [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:16] -- Executing [*844@default-application:1] Set("Local/*844@default-application-9017,2", "GROUP(OUTGOING)=91800555123") in new stack [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1873 pbx_extension_helper: Launching 'Answer' [2011-02-07 13:53:16] -- Executing [*844@default-application:2] Answer("Local/*844@default-application-9017,2", "") in new stack [2011-02-07 13:53:16] DEBUG[31876]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/*844@default-application [2011-02-07 13:53:16] DEBUG[4022]: chan_local.c:216 local_devicestate: Checking if extension *844@default-application exists (devicestate) [2011-02-07 13:53:16] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c42788' [2011-02-07 13:53:16] DEBUG[31844]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/*844@default-application [2011-02-07 13:53:16] -- Local/*844@default-application-9017,1 answered Zap/23-1 [2011-02-07 13:53:16] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c42788' [2011-02-07 13:53:16] DEBUG[31844]: rtp.c:1615 ast_rtp_early_bridge: Channel 'Zap/23-1' has no RTP, not doing anything [2011-02-07 13:53:16] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c42788' [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1 [2011-02-07 13:53:16] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c42788' [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:16] DEBUG[4022]: channel.c:1172 channel_find_locked: Avoiding initial deadlock for channel '0x9c42788' [2011-02-07 13:53:16] DEBUG[31844]: channel.c:4691 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/*844@default-application-9017,1 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:16] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Local/*844@default-application - state 2 (In use) [2011-02-07 13:53:16] DEBUG[4022]: chan_local.c:216 local_devicestate: Checking if extension *844@default-application exists (devicestate) [2011-02-07 13:53:16] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication -1 on channel Zap/23-1 [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:16] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Local/*844@default-application - state 2 (In use) [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:16] -- Executing [*844@default-application:3] Set("Local/*844@default-application-9017,2", "TIMEOUT(digit)=5") in new stack [2011-02-07 13:53:16] -- Digit timeout set to 5 [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1873 pbx_extension_helper: Launching 'Set' [2011-02-07 13:53:16] DEBUG[4074]: app_queue.c:713 handle_statechange: Device 'Local/*844@default-application' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2011-02-07 13:53:16] DEBUG[4074]: app_queue.c:713 handle_statechange: Device 'Local/*844@default-application' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2011-02-07 13:53:16] -- Executing [*844@default-application:4] Set("Local/*844@default-application-9017,2", "TIMEOUT(response)=10") in new stack [2011-02-07 13:53:16] -- Response timeout set to 10 [2011-02-07 13:53:16] DEBUG[31876]: pbx.c:1873 pbx_extension_helper: Launching 'VoiceMailMain' [2011-02-07 13:53:16] -- Executing [*844@default-application:5] VoiceMailMain("Local/*844@default-application-9017,2", "@default") in new stack [2011-02-07 13:53:16] DEBUG[31876]: res_adsi.c:378 ast_adsi_transmit_message_full: Switch to data is sent! [2011-02-07 13:53:16] DEBUG[31844]: chan_dahdi.c:5732 my_dahdi_write: Write returned -1 (Resource temporarily unavailable) on channel 23 [2011-02-07 13:53:16] DEBUG[4080]: manager.c:2277 process_message: Manager received command 'GetVar' [2011-02-07 13:53:16] DEBUG[4080]: manager.c:2277 process_message: Manager received command 'GetVar' [2011-02-07 13:53:16] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:16] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 192.168.0.0 [2011-02-07 13:53:16] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 10.0.0.0 [2011-02-07 13:53:16] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 172.16.0.0 [2011-02-07 13:53:16] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.152 with 169.254.0.0 [2011-02-07 13:53:16] DEBUG[4080]: manager.c:2277 process_message: Manager received command 'GetVar' [2011-02-07 13:53:16] DEBUG[4080]: manager.c:2277 process_message: Manager received command 'GetVar' [2011-02-07 13:53:16] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '1d1fa02d0e422ce96cd931cf196824c4@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:16] DEBUG[31876]: res_adsi.c:235 __adsi_transmit_messages: No ADSI CPE detected (0) [2011-02-07 13:53:16] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals [2011-02-07 13:53:16] -- Playing 'vm-login' (language 'en') [2011-02-07 13:53:17] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.142 with 192.168.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.142 with 10.0.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.142 with 172.16.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.142 with 169.254.0.0 [2011-02-07 13:53:17] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '5e9d09567a340a305e2c00c145694bef@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:17] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.197 with 192.168.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.197 with 10.0.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.197 with 172.16.0.0 [2011-02-07 13:53:17] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.197 with 169.254.0.0 [2011-02-07 13:53:17] DEBUG[4046]: chan_sip.c:2339 __sip_ack: Stopping retransmission on '707c476753bb40b22fc9844453303d5a@192.168.30.254' of Request 102: Match Found [2011-02-07 13:53:18] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0 [2011-02-07 13:53:18] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0 [2011-02-07 13:53:18] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0 [2011-02-07 13:53:18] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0 [2011-02-07 13:53:18] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for 87994b63-98d161ea-775fa25@192.168.30.86 - SUBSCRIBE (No RTP) [2011-02-07 13:53:18] DEBUG[4046]: chan_sip.c:9307 build_route: build_route: Contact hop: [2011-02-07 13:53:18] DEBUG[4046]: chan_sip.c:9245 build_route: build_route: Retaining previous route: [2011-02-07 13:53:18] DEBUG[4046]: chan_sip.c:16949 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary [2011-02-07 13:53:19] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 2 sample intervals [2011-02-07 13:53:19] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:19] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:19] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131126(131126) on channel 23 (index 0) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '6' [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '6' received on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '6' on Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262198(262198) on channel 23 (index 0) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '6' [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '6' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:19] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '6' on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:19] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=6, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:19] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '6' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:19] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:19] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:19] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Zap/23-1 [2011-02-07 13:53:19] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '6' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:19] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:19] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:19] DTMF[4661]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:19] DTMF[4661]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131121(131121) on channel 23 (index 0) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '1' [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '1' received on Zap/23-1 [2011-02-07 13:53:19] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '1' on Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:19] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:19] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262193(262193) on channel 23 (index 0) [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '1' [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:20] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '1' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:20] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '1' on Zap/23-1 [2011-02-07 13:53:20] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '1' on Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:20] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=1, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:20] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '1' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '1' on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '1' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:20] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '1' on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:20] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:20] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:20] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:20] DTMF[31844]: channel.c:2489 __ast_read: DTMF begin emulation of '0' with duration 80 queued on Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DTMF[31844]: channel.c:2622 __ast_read: DTMF end emulation of '0' queued on Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:20] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=0, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:20] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '0' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131107(131107) on channel 23 (index 0) [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '#' [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x23 '#' on Zap/23-1 [2011-02-07 13:53:20] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '#' received on Zap/23-1 [2011-02-07 13:53:20] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '#' on Zap/23-1 [2011-02-07 13:53:20] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '0' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:20] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262179(262179) on channel 23 (index 0) [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '#' [2011-02-07 13:53:20] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x23 '#' on Zap/23-1 [2011-02-07 13:53:20] DTMF[4661]: channel.c:2463 __ast_read: DTMF end '#' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:20] DTMF[4661]: channel.c:2529 __ast_read: DTMF end passthrough '#' on Zap/23-1 [2011-02-07 13:53:20] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:21] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 192.168.0.0 [2011-02-07 13:53:21] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 10.0.0.0 [2011-02-07 13:53:21] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 172.16.0.0 [2011-02-07 13:53:21] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.150 with 169.254.0.0 [2011-02-07 13:53:21] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for bc1ec9d4-4101d5f5-ea6e9876@192.168.30.150 - SUBSCRIBE (No RTP) [2011-02-07 13:53:21] DEBUG[4046]: chan_sip.c:9307 build_route: build_route: Contact hop: [2011-02-07 13:53:21] DEBUG[4046]: chan_sip.c:9245 build_route: build_route: Retaining previous route: [2011-02-07 13:53:21] DEBUG[4046]: chan_sip.c:16949 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary [2011-02-07 13:53:22] DEBUG[31876]: app_voicemail.c:7656 vm_authenticate: Before find user for mailbox 610 [2011-02-07 13:53:22] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals [2011-02-07 13:53:22] -- Playing 'vm-password' (language 'en') [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131126(131126) on channel 23 (index 0) [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '6' [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:23] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '6' received on Zap/23-1 [2011-02-07 13:53:23] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '6' on Zap/23-1 [2011-02-07 13:53:23] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:23] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:23] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 80 sample intervals [2011-02-07 13:53:23] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:23] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:23] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262198(262198) on channel 23 (index 0) [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '6' [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:23] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '6' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:23] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '6' on Zap/23-1 [2011-02-07 13:53:23] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Zap/23-1 [2011-02-07 13:53:23] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:23] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:23] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=6, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:23] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '6' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:23] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:23] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:23] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Zap/23-1 [2011-02-07 13:53:23] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '6' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:23] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:23] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:23] DTMF[4661]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:23] DTMF[4661]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Zap/23-1 [2011-02-07 13:53:23] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131121(131121) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '1' [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '1' received on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '1' on Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262193(262193) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '1' [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '1' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:24] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '1' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '1' on Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:24] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=1, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:24] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '1' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:24] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '1' on Local/*844@default-application-9017,2 [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:24] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:24] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '1' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:24] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '1' on Local/*844@default-application-9017,2 [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:24] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:24] DTMF[4661]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:24] DTMF[4661]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131126(131126) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '6' [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '6' received on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '6' on Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262198(262198) on channel 23 (index 0) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '6' [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x36 '6' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '6' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:24] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '6' on Zap/23-1 [2011-02-07 13:53:24] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:24] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:24] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:24] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=6, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:24] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '6' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:24] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '6' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:25] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '6' on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:25] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:25] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:25] DTMF[31844]: channel.c:2489 __ast_read: DTMF begin emulation of '0' with duration 80 queued on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2622 __ast_read: DTMF end emulation of '0' queued on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:25] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=0, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:25] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '0' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131121(131121) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '1' [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:25] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '1' received on Zap/23-1 [2011-02-07 13:53:25] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '1' on Zap/23-1 [2011-02-07 13:53:25] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '0' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:25] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262193(262193) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '1' [2011-02-07 13:53:25] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x31 '1' on Zap/23-1 [2011-02-07 13:53:25] DTMF[4661]: channel.c:2463 __ast_read: DTMF end '1' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:25] DTMF[4661]: channel.c:2529 __ast_read: DTMF end passthrough '1' on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131120(131120) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '0' [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2545 __ast_read: DTMF begin '0' received on Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2555 __ast_read: DTMF begin passthrough '0' on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 192.168.0.0 [2011-02-07 13:53:25] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 10.0.0.0 [2011-02-07 13:53:25] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 172.16.0.0 [2011-02-07 13:53:25] DEBUG[4046]: acl.c:370 ast_apply_ha: ##### Testing 192.168.30.86 with 169.254.0.0 [2011-02-07 13:53:25] DEBUG[4046]: chan_sip.c:4961 sip_alloc: Allocating new SIP dialog for b1750a0c-1048b1f-3d6f8ff6@192.168.30.86 - SUBSCRIBE (No RTP) [2011-02-07 13:53:25] DEBUG[4046]: chan_sip.c:9307 build_route: build_route: Contact hop: [2011-02-07 13:53:25] DEBUG[4046]: chan_sip.c:9245 build_route: build_route: Retaining previous route: [2011-02-07 13:53:25] DEBUG[4046]: chan_sip.c:16949 handle_request_subscribe: Received SIP subscribe for unknown event package: missed-call-summary [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262192(262192) on channel 23 (index 0) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '0' [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x30 '0' on Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '0' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:25] DTMF[31844]: channel.c:2500 __ast_read: DTMF end accepted with begin '0' on Zap/23-1 [2011-02-07 13:53:25] DTMF[31844]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:25] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:25] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:25] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=0, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:25] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '0' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:25] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:26] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '0' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:26] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '0' on Local/*844@default-application-9017,2 [2011-02-07 13:53:26] DEBUG[4661]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:26] DEBUG[4661]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 131107(131107) on channel 23 (index 0) [2011-02-07 13:53:26] DEBUG[4661]: chan_dahdi.c:4430 dahdi_handle_event: DTMF Down '#' [2011-02-07 13:53:26] DEBUG[4661]: chan_dahdi.c:4252 dahdi_handle_dtmf: Begin DTMF digit: 0x23 '#' on Zap/23-1 [2011-02-07 13:53:26] DTMF[4661]: channel.c:2545 __ast_read: DTMF begin '#' received on Zap/23-1 [2011-02-07 13:53:26] DTMF[4661]: channel.c:2549 __ast_read: DTMF begin ignored '#' on Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5369 __dahdi_exception: Exception on 50, channel 23 [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:4406 dahdi_handle_event: Got event Event 262179(262179) on channel 23 (index 0) [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:4411 dahdi_handle_event: Detected digit '#' [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:4252 dahdi_handle_dtmf: End DTMF digit: 0x23 '#' on Zap/23-1 [2011-02-07 13:53:26] DTMF[31844]: channel.c:2463 __ast_read: DTMF end '#' received on Zap/23-1, duration 80 ms [2011-02-07 13:53:26] DTMF[31844]: channel.c:2489 __ast_read: DTMF begin emulation of '#' with duration 80 queued on Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF begin on channel (Zap/23-1) [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:26] DTMF[31844]: channel.c:2622 __ast_read: DTMF end emulation of '#' queued on Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: channel.c:4714 ast_generic_bridge: Got DTMF end on channel (Zap/23-1) [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:26] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:26] DEBUG[31844]: res_features.c:1769 feature_interpret: Feature interpret: chan=Zap/23-1, peer=Local/*844@default-application-9017,1, code=#, sense=1, features=0, dynamic=atxfer#atdxfer#blindxfer#automon#automixmon#hookflash#supervisor#conference#tagcode-*1000#tagcode-*1001#tagcode-*1002#tagcode-* [2011-02-07 13:53:26] DTMF[31876]: channel.c:2545 __ast_read: DTMF begin '#' received on Local/*844@default-application-9017,2 [2011-02-07 13:53:26] DTMF[31876]: channel.c:2549 __ast_read: DTMF begin ignored '#' on Local/*844@default-application-9017,2 [2011-02-07 13:53:26] DTMF[31876]: channel.c:2463 __ast_read: DTMF end '#' received on Local/*844@default-application-9017,2, duration 100 ms [2011-02-07 13:53:26] DTMF[31876]: channel.c:2529 __ast_read: DTMF end passthrough '#' on Local/*844@default-application-9017,2 [2011-02-07 13:53:26] -- Incorrect password '61600' for user '610' (context = default) [2011-02-07 13:53:26] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 160 sample intervals [2011-02-07 13:53:26] -- Playing 'vm-incorrect-mailbox' (language 'en') [2011-02-07 13:53:26] DEBUG[31844]: chan_dahdi.c:5820 dahdi_indicate: Requested indication 20 on channel Zap/23-1 [2011-02-07 13:53:29] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 59 sample intervals [2011-02-07 13:53:29] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:29] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:29] DEBUG[31876]: channel.c:2038 ast_settimeout: Scheduling timer at 0 sample intervals [2011-02-07 13:53:30] -- Channel 0/23, span 1 got hangup request, cause 16 [2011-02-07 13:53:30] DEBUG[31844]: channel.c:4663 ast_generic_bridge: Didn't get a frame from channel: Zap/23-1 [2011-02-07 13:53:30] DEBUG[31844]: channel.c:5029 ast_channel_bridge: Bridge stops bridging channels Zap/23-1 and Local/*844@default-application-9017,1 [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'Goto' [2011-02-07 13:53:30] -- Executing [h@default-aa-servicemainmenubutton1englishsubmenu:1] Goto("Zap/23-1", "all-hangup|s|1") in new stack [2011-02-07 13:53:30] -- Goto (all-hangup,s,1) [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '0' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1789 pbx_substitute_variables_helper_full: Expression result is '2' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'GotoIf' [2011-02-07 13:53:30] -- Executing [s@all-hangup:1] GotoIf("Zap/23-1", "0?all-faxnotify|s|1:2") in new stack [2011-02-07 13:53:30] -- Goto (all-hangup,s,2) [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'ResetCDR' [2011-02-07 13:53:30] -- Executing [s@all-hangup:2] ResetCDR("Zap/23-1", "w") in new stack [2011-02-07 13:53:30] DEBUG[31844]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded! [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '"BCM50bob" <1800555123>' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '*' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'default-aa-servicemainmenubutton1englishsubmenu' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Zap/23-1' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/*844@default-application-9017,1' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Dial' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/*844@default-application' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:11' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:16' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:30' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '19' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '14' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '_NONE_' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1297104791.76' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '6900' [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:1873 pbx_extension_helper: Launching 'NoCDR' [2011-02-07 13:53:30] -- Executing [s@all-hangup:3] NoCDR("Zap/23-1", "") in new stack [2011-02-07 13:53:30] DEBUG[31844]: channel.c:1706 ast_hangup: Hanging up channel 'Local/*844@default-application-9017,1' [2011-02-07 13:53:30] DEBUG[31844]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/*844@default-application [2011-02-07 13:53:30] DEBUG[4022]: chan_local.c:216 local_devicestate: Checking if extension *844@default-application exists (devicestate) [2011-02-07 13:53:30] WARNING[31876]: app_voicemail.c:7633 vm_authenticate: Couldn't read username [2011-02-07 13:53:30] DEBUG[31876]: app_voicemail.c:7834 vm_execmain: After vm_authenticate [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:2503 __ast_pbx_run: Extension *844, priority 5 returned normally even though call was hung up [2011-02-07 13:53:30] DEBUG[31876]: channel.c:1603 ast_softhangup_nolock: Soft-Hanging up channel 'Local/*844@default-application-9017,2' [2011-02-07 13:53:30] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Local/*844@default-application - state 2 (In use) [2011-02-07 13:53:30] DEBUG[31844]: rtp.c:1615 ast_rtp_early_bridge: Channel 'Zap/23-1' has no RTP, not doing anything [2011-02-07 13:53:30] DEBUG[31844]: app_dial.c:1938 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [2011-02-07 13:53:30] DEBUG[31844]: pbx.c:2480 __ast_pbx_run: Spawn extension (all-hangup,*,2) exited non-zero on 'Zap/23-1' [2011-02-07 13:53:30] == Spawn extension (all-hangup, *, 2) exited non-zero on 'Zap/23-1' [2011-02-07 13:53:30] DEBUG[31844]: channel.c:1603 ast_softhangup_nolock: Soft-Hanging up channel 'Zap/23-1' [2011-02-07 13:53:30] DEBUG[31844]: channel.c:1706 ast_hangup: Hanging up channel 'Zap/23-1' [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:2893 dahdi_hangup: dahdi_hangup(Zap/23-1) [2011-02-07 13:53:30] DEBUG[31876]: channel.c:1706 ast_hangup: Hanging up channel 'Local/*844@default-application-9017,2' [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:3499 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/23-1 [2011-02-07 13:53:30] DEBUG[4074]: app_queue.c:713 handle_statechange: Device 'Local/*844@default-application' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:2928 dahdi_hangup: Hangup: channel: 23 index = 0, normal = 50, callwait = -1, thirdcall = -1 [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:3127 dahdi_hangup: Not yet hungup... Calling hangup once with icause, and clearing call [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:1878 dahdi_disable_ec: disabled echo cancellation on channel 23 [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:3413 dahdi_setoption: Set option TDD MODE, value: OFF(0) on Zap/23-1 [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:1814 update_conf: Updated conferencing on 23, with 0 conference users [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:3495 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/23-1 [2011-02-07 13:53:30] DEBUG[31844]: chan_dahdi.c:1878 dahdi_disable_ec: disabled echo cancellation on channel 23 [2011-02-07 13:53:30] -- Hungup 'Zap/23-1' [2011-02-07 13:53:30] DEBUG[31876]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded! [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '"BCM50bob" <1800555123>' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1800555123' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '*844' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'default-application' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'Local/*844@default-application-9017,2' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '(null)' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'VoiceMailMain' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '@default' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:16' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:16' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '2011-02-07 13:53:30' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '14' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '14' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '_NONE_' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '1297104796.78' [2011-02-07 13:53:30] DEBUG[31876]: pbx.c:1721 pbx_substitute_variables_helper_full: Function result is '(null)' [2011-02-07 13:53:30] DEBUG[31876]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/*844@default-application [2011-02-07 13:53:30] DEBUG[4022]: chan_local.c:216 local_devicestate: Checking if extension *844@default-application exists (devicestate) [2011-02-07 13:53:30] DEBUG[31844]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/23 [2011-02-07 13:53:30] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Local/*844@default-application - state 1 (Not in use) [2011-02-07 13:53:30] DEBUG[4074]: app_queue.c:713 handle_statechange: Device 'Local/*844@default-application' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2011-02-07 13:53:30] DEBUG[4022]: devicestate.c:287 do_state_change: Changing state for Zap/23 - state 0 (Unknown) [2011-02-07 13:53:30] DEBUG[4074]: 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.