[2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 7f17f45c10c1bf872b5443422a7fe674@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 785e7fb639a577400648f4b74a27eaae@173.8.103.157:5060 [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '785e7fb639a577400648f4b74a27eaae@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 650ea92428e52e6960ce3867439a1b0d@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 2938014c757daee57ff0d60b0db6fef4@173.8.103.157:5060 [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '2938014c757daee57ff0d60b0db6fef4@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 620dd7ef3debd4f51e627c8569240630@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 16ba79e637c5550f3bcee5290d615c1e@173.8.103.157:5060 [2012-08-06 16:25:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '16ba79e637c5550f3bcee5290d615c1e@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:25:48] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:25:48] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 771935198_50483733@192.168.27.84 - INVITE (No RTP) [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb666347c' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 17970 for RTP instance '0xb666347c' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0xb666347c' is setup and ready to go [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb666347c' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:5390 do_setnat: Setting NAT on RTP to Off [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:477 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:477 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:477 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:598 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:598 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:598 ast_rtp_codecs_payload_formats: Incorporating payload 96 on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: rtp_engine.c:598 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb667a240 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb666347c' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: res_rtp_asterisk.c:3220 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xb666347c' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:24360 handle_request_invite: Checking SIP call limits for device [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: dsp.c:468 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: dsp.c:468 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [+16516811421@from-pstn-e164-us:1] Set("SIP/bandwidth-0000001a", "CALLERID(number)=6512454836") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Goto' -- Executing [+16516811421@from-pstn-e164-us:2] Goto("SIP/bandwidth-0000001a", "from-pstn,6516811421,1") in new stack -- Goto (from-pstn,6516811421,1) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [6516811421@from-pstn:1] Set("SIP/bandwidth-0000001a", "__FROM_DID=6516811421") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Gosub' -- Executing [6516811421@from-pstn:2] Gosub("SIP/bandwidth-0000001a", "app-blacklist-check,s,1()") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_stack.c:578 gosub_exec: Channel SIP/bandwidth-0000001a has no datastore, so we're allocating one. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '6512454836' in family 'blacklist' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key 'TAYLOR TELEPHON ' in family 'blacklist' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@app-blacklist-check:1] GotoIf("SIP/bandwidth-0000001a", "0?blacklisted") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:11104 pbx_builtin_gotoif: Not taking any branch [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@app-blacklist-check:2] Set("SIP/bandwidth-0000001a", "CALLED_BLACKLIST=1") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Return' -- Executing [s@app-blacklist-check:3] Return("SIP/bandwidth-0000001a", "") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [6516811421@from-pstn:3] Set("SIP/bandwidth-0000001a", "CDR(did)=6516811421") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [6516811421@from-pstn:4] ExecIf("SIP/bandwidth-0000001a", "0 ?Set(CALLERID(name)=6512454836)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [6516811421@from-pstn:5] Set("SIP/bandwidth-0000001a", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [6516811421@from-pstn:6] Set("SIP/bandwidth-0000001a", "CALLERPRES()=allowed_not_screened") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Goto' -- Executing [6516811421@from-pstn:7] Goto("SIP/bandwidth-0000001a", "ext-group,600,1") in new stack -- Goto (ext-group,600,1) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Macro' -- Executing [600@ext-group:1] Macro("SIP/bandwidth-0000001a", "user-callerid,") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("SIP/bandwidth-0000001a", "AMPUSER=6512454836") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:2] GotoIf("SIP/bandwidth-0000001a", "0?report") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:11104 pbx_builtin_gotoif: Not taking any branch [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-user-callerid:3] ExecIf("SIP/bandwidth-0000001a", "1?Set(REALCALLERIDNUM=6512454836)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '6512454836/user' in family 'DEVICE' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: DEVICE/6512454836/user not found in database. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:4] Set("SIP/bandwidth-0000001a", "AMPUSER=") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER//cidname not found in database. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("SIP/bandwidth-0000001a", "AMPUSERCIDNAME=") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:6] GotoIf("SIP/bandwidth-0000001a", "1?report") in new stack -- Goto (macro-user-callerid,s,11) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:11] GotoIf("SIP/bandwidth-0000001a", "0?continue") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:11104 pbx_builtin_gotoif: Not taking any branch [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '-1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:12] Set("SIP/bandwidth-0000001a", "__TTL=64") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:13] GotoIf("SIP/bandwidth-0000001a", "1?continue") in new stack -- Goto (macro-user-callerid,s,24) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:24] Set("SIP/bandwidth-0000001a", "CALLERID(number)=6512454836") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:25] Set("SIP/bandwidth-0000001a", "CALLERID(name)=TAYLOR TELEPHON ") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:26] Set("SIP/bandwidth-0000001a", "CHANNEL(language)=en") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Macro' -- Executing [600@ext-group:2] Macro("SIP/bandwidth-0000001a", "blkvm-setifempty,") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/bandwidth-0000001a", "1?init") in new stack -- Goto (macro-blkvm-setifempty,s,4) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/bandwidth-0000001a", "__BLKVM_CHANNEL=SIP/bandwidth-0000001a") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/bandwidth-0000001a", "SHARED(BLKVM,SIP/bandwidth-0000001a)=TRUE") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/bandwidth-0000001a", "GOSUB_RETVAL=TRUE") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'MacroExit' -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/bandwidth-0000001a", "") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [600@ext-group:3] GotoIf("SIP/bandwidth-0000001a", "1?skipov") in new stack -- Goto (ext-group,600,6) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [600@ext-group:6] Set("SIP/bandwidth-0000001a", "RRNODEST=") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [600@ext-group:7] Set("SIP/bandwidth-0000001a", "__NODEST=600") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GosubIf' -- Executing [600@ext-group:8] GosubIf("SIP/bandwidth-0000001a", "0?sub-rgsetcid,s,1()") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [600@ext-group:9] Set("SIP/bandwidth-0000001a", "__PICKUPMARK=600") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Gosub' -- Executing [600@ext-group:10] Gosub("SIP/bandwidth-0000001a", "sub-record-check,s,1(rg,600,dontcare)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_stack.c:620 gosub_exec: Setting 'ARG1' to 'rg' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_stack.c:620 gosub_exec: Setting 'ARG2' to '600' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_stack.c:620 gosub_exec: Setting 'ARG3' to 'dontcare' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:1] GotoIf("SIP/bandwidth-0000001a", "1?check") in new stack -- Goto (sub-record-check,s,6) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:6] Set("SIP/bandwidth-0000001a", "__MON_FMT=wav") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:7] GotoIf("SIP/bandwidth-0000001a", "1?next") in new stack -- Goto (sub-record-check,s,10) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:10] ExecIf("SIP/bandwidth-0000001a", "0?Return()") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-record-check:11] GotoIf("SIP/bandwidth-0000001a", "0?rg,1") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:11104 pbx_builtin_gotoif: Not taking any branch [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:12] Set("SIP/bandwidth-0000001a", "__REC_STATUS=INITIALIZED") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@sub-record-check:13] ExecIf("SIP/bandwidth-0000001a", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:14] Set("SIP/bandwidth-0000001a", "NOW=1344288348") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:15] Set("SIP/bandwidth-0000001a", "__DAY=06") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:16] Set("SIP/bandwidth-0000001a", "__MONTH=08") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:17] Set("SIP/bandwidth-0000001a", "__YEAR=2012") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:18] Set("SIP/bandwidth-0000001a", "__TIMESTR=20120806-162548") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '10' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:19] Set("SIP/bandwidth-0000001a", "__FROMEXTEN=6512454836") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-record-check:20] Set("SIP/bandwidth-0000001a", "__CALLFILENAME=rg-600-6512454836-20120806-162548-1344288348.30") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Goto' -- Executing [s@sub-record-check:21] Goto("SIP/bandwidth-0000001a", "rg,1") in new stack -- Goto (sub-record-check,rg,1) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GosubIf' -- Executing [rg@sub-record-check:1] GosubIf("SIP/bandwidth-0000001a", "0?record,1(rg,dontcare,6512454836)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Return' -- Executing [rg@sub-record-check:2] Return("SIP/bandwidth-0000001a", "") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [600@ext-group:11] Set("SIP/bandwidth-0000001a", "RingGroupMethod=ringall") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Macro' -- Executing [600@ext-group:12] Macro("SIP/bandwidth-0000001a", "dial,30,tr,101-103-106-107-108-109-110") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:1] GotoIf("SIP/bandwidth-0000001a", "1?dial") in new stack -- Goto (macro-dial,s,3) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-dial:3] AGI("SIP/bandwidth-0000001a", "dialparties.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi dialparties.agi: Starting New Dialparties.agi dialparties.agi: Caller ID name is 'TAYLOR TELEPHON' number is '6512454836' > dialparties.agi: USE_CONFIRMATION: 'FALSE' > dialparties.agi: RINGGROUP_INDEX: '' dialparties.agi: Methodology of ring is 'ringall' -- dialparties.agi: Added extension 101 to extension map -- dialparties.agi: Added extension 103 to extension map -- dialparties.agi: Added extension 106 to extension map -- dialparties.agi: Added extension 107 to extension map -- dialparties.agi: Added extension 108 to extension map -- dialparties.agi: Added extension 109 to extension map -- dialparties.agi: Added extension 110 to extension map [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '101' in family 'CF' -- dialparties.agi: Extension 101 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '103' in family 'CF' -- dialparties.agi: Extension 103 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '106' in family 'CF' -- dialparties.agi: Extension 106 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '107' in family 'CF' -- dialparties.agi: Extension 107 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108' in family 'CF' -- dialparties.agi: Extension 108 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '109' in family 'CF' -- dialparties.agi: Extension 109 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '110' in family 'CF' -- dialparties.agi: Extension 110 cf is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '101' in family 'DND' -- dialparties.agi: Extension 101 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '103' in family 'DND' -- dialparties.agi: Extension 103 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '106' in family 'DND' -- dialparties.agi: Extension 106 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '107' in family 'DND' -- dialparties.agi: Extension 107 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108' in family 'DND' -- dialparties.agi: Extension 108 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '109' in family 'DND' -- dialparties.agi: Extension 109 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '110' in family 'DND' -- dialparties.agi: Extension 110 do not disturb is disabled [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '101' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '101' in family 'CFU' > dialparties.agi: extnum 101 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/101 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '103' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '103' in family 'CFU' > dialparties.agi: extnum 103 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/103 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '106' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '106' in family 'CFU' > dialparties.agi: extnum 106 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/106 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '107' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '107' in family 'CFU' > dialparties.agi: extnum 107 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/107 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108' in family 'CFU' > dialparties.agi: extnum 108 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/108 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '109' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '109' in family 'CFU' > dialparties.agi: extnum 109 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/109 to 6512454836 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '110' in family 'CFB' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '110' in family 'CFU' > dialparties.agi: extnum 110 has: cw: 1; hascfb: 0 [] hascfu: 0 [] -- dialparties.agi: dbset CALLTRACE/110 to 6512454836 -- dialparties.agi: Filtered ARG3: 101-103-106-107-108-109-110 > dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: trM(auto-blkvm) > dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: trM(auto-blkvm) -- AGI Script dialparties.agi completed, returning 0 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: AGI [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:7] Dial("SIP/bandwidth-0000001a", "SIP/101&SIP/103&SIP/106&USTM/107@107&USTM/108@108&USTM/109@109&SIP/110,30,trM(auto-blkvm)") in new stack [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:28594 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6d0dd2e91122aef50847b28d1b1b68e0@192.168.183.1:5060 - INVITE (No RTP) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8e8e524' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 12340 for RTP instance '0x8e8e524' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0x8e8e524' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8e3fe84' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 13702 for RTP instance '0x8e3fe84' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0x8e3fe84' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8e3fe84' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8e8e524' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5390 do_setnat: Setting NAT on RTP to Off [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5394 do_setnat: Setting NAT on VRTP to Off [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AGISTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ds. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG3. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG2. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG1. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLFILENAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROMEXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TIMESTR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable YEAR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MONTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable DAY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable NOW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_POLICY_MODE. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_STATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MON_FMT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DB_RESULT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable NODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RRNODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable BLKVM_CHANNEL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGPRES_SV. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable CALLED_BLACKLIST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROM_DID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPCALLID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPURI. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:28594 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 5ead4b5c519713aa36ab85984c379aac@192.168.183.1:5060 - INVITE (No RTP) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb667a274' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 13004 for RTP instance '0xb667a274' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0xb667a274' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb6699a54' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 12322 for RTP instance '0xb6699a54' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0xb6699a54' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb6699a54' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb667a274' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5390 do_setnat: Setting NAT on RTP to Off [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5394 do_setnat: Setting NAT on VRTP to Off [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AGISTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ds. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG3. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG2. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG1. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLFILENAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROMEXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TIMESTR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable YEAR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MONTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable DAY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable NOW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_POLICY_MODE. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_STATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MON_FMT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DB_RESULT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable NODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RRNODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable BLKVM_CHANNEL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGPRES_SV. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable CALLED_BLACKLIST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROM_DID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPCALLID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPURI. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:28594 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 0c5fe9472f5623da0236cdde22a0ca31@192.168.183.1:5060 - INVITE (No RTP) [2012-08-06 16:25:48] WARNING[5348][C-0000000d]: app_dial.c:2433 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Unknown) [2012-08-06 16:25:48] WARNING[5348][C-0000000d]: app_dial.c:2433 dial_exec_full: Unable to create channel of type 'USTM' (cause 34 - Circuit/channel congestion) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8e70c04' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 14480 for RTP instance '0x8e70c04' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0x8e70c04' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8e70c04' == Using UNISTIM RTP CoS mark 5 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8e70c04' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AGISTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ds. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG3. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG2. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG1. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLFILENAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROMEXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TIMESTR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable YEAR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MONTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable DAY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable NOW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_POLICY_MODE. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_STATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MON_FMT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DB_RESULT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable NODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RRNODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable BLKVM_CHANNEL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGPRES_SV. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable CALLED_BLACKLIST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROM_DID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPCALLID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPURI. [2012-08-06 16:25:48] WARNING[5348][C-0000000d]: app_dial.c:2433 dial_exec_full: Unable to create channel of type 'USTM' (cause 34 - Circuit/channel congestion) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:28594 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 662c4e5c4ca5dcc4306ccab50c6b82ee@192.168.183.1:5060 - INVITE (No RTP) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:276 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb66aafd4' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1156 ast_rtp_new: Allocated port 11326 for RTP instance '0xb66aafd4' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: rtp_engine.c:285 ast_rtp_instance_new: RTP instance '0xb66aafd4' is setup and ready to go [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3254 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb66aafd4' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5390 do_setnat: Setting NAT on RTP to Off [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AGISTATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ds. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG3. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG2. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable ARG1. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable GOSUB_RETVAL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLFILENAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROMEXTEN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TIMESTR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable YEAR. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MONTH. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable DAY. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable NOW. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_POLICY_MODE. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable REC_STATUS. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable MON_FMT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable DB_RESULT. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable NODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable RRNODEST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable BLKVM_CHANNEL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable AMPUSER. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGPRES_SV. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable CALLED_BLACKLIST. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6351 ast_channel_inherit_variables: Copying hard-transferable variable FROM_DID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPCALLID. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: channel.c:6355 ast_channel_inherit_variables: Not copying variable SIPURI. [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5956 sip_call: Outgoing Call for 101 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12450 add_sdp: ** Our capability: (gsm|ulaw|g729|h264|mpeg4) Video flag: False Text flag: False [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12451 add_sdp: ** Our prefcodec: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method INVITE - callid 4a1526320c1b52517d88362c631a748a@192.168.183.1:5060 -- Called SIP/101 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5956 sip_call: Outgoing Call for 103 [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND101' in family 'CustomDevstate' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12450 add_sdp: ** Our capability: (gsm|ulaw|g729|h264|mpeg4) Video flag: False Text flag: False [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12451 add_sdp: ** Our prefcodec: (ulaw) [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method INVITE - callid 5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060 [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND103' in family 'CustomDevstate' -- Called SIP/103 -- Called USTM/108@108 [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:5956 sip_call: Outgoing Call for 110 [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND108' in family 'CustomDevstate' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12450 add_sdp: ** Our capability: (ulaw) Video flag: False Text flag: False [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:12451 add_sdp: ** Our prefcodec: (ulaw) [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:25:48] DEBUG[5348][C-0000000d]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method INVITE - callid 5f57a25a52547db879c397f224122103@192.168.183.1:5060 -- Called SIP/110 -- SIP/110-0000001d connected line has changed. Saving it until answer for SIP/bandwidth-0000001a -- USTM/108@108-0x8def060 is ringing -- SIP/103-0000001c connected line has changed. Saving it until answer for SIP/bandwidth-0000001a -- SIP/101-0000001b connected line has changed. Saving it until answer for SIP/bandwidth-0000001a [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060' Request 102: Found [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f57a25a52547db879c397f224122103@192.168.183.1:5060' Request 102: Found [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060' Request 102: Found -- SIP/103-0000001c is ringing [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND103' in family 'CustomDevstate' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f57a25a52547db879c397f224122103@192.168.183.1:5060' Request 102: Found -- SIP/110-0000001d is ringing [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:25:48] DEBUG[8269][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4a1526320c1b52517d88362c631a748a@192.168.183.1:5060' Request 102: Found -- SIP/101-0000001b is ringing [2012-08-06 16:25:48] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND101' in family 'CustomDevstate' -- USTM/108@108-0x8def060 answered SIP/bandwidth-0000001a [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/101-0000001b' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6609 sip_hangup: This call was answered elsewhere [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6635 sip_hangup: Hangup call SIP/101-0000001b, SIP callid 4a1526320c1b52517d88362c631a748a@192.168.183.1:5060 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8e8e524' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8e3fe84' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4a1526320c1b52517d88362c631a748a@192.168.183.1:5060' Request 102: Found [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/103-0000001c' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6609 sip_hangup: This call was answered elsewhere [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6635 sip_hangup: Hangup call SIP/103-0000001c, SIP callid 5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb667a274' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND108' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND101' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb6699a54' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060' Request 102: Found [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND101' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/110-0000001d' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND103' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND103' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6609 sip_hangup: This call was answered elsewhere [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6635 sip_hangup: Hangup call SIP/110-0000001d, SIP callid 5f57a25a52547db879c397f224122103@192.168.183.1:5060 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb66aafd4' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:4307 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f57a25a52547db879c397f224122103@192.168.183.1:5060' Request 102: Found [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-auto-blkvm:1] Set("USTM/108@108-0x8def060", "__MACRO_RESULT=") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-auto-blkvm:2] Macro("USTM/108@108-0x8def060", "blkvm-clr,") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-clr:1] Set("USTM/108@108-0x8def060", "SHARED(BLKVM,SIP/bandwidth-0000001a)=") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-blkvm-clr:2] Set("USTM/108@108-0x8def060", "GOSUB_RETVAL=") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Set [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'MacroExit' -- Executing [s@macro-blkvm-clr:3] MacroExit("USTM/108@108-0x8def060", "") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: Macro [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_strings.c:970 regex: FUNCTION REGEX ([^0-9])(108@108) [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER//cidname not found in database. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-auto-blkvm:3] ExecIf("USTM/108@108-0x8def060", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=108@108)") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_strings.c:970 regex: FUNCTION REGEX ([^0-9])(108@108) [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER//cidname not found in database. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_strings.c:970 regex: FUNCTION REGEX ([^0-9])(108@108) [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER//cidname not found in database. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108@108/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER/108@108/cidname not found in database. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-auto-blkvm:4] ExecIf("USTM/108@108-0x8def060", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_strings.c:970 regex: FUNCTION REGEX ([^0-9])(108@108) [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER//cidname not found in database. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: db.c:329 ast_db_get: Unable to find key '108@108/cidname' in family 'AMPUSER' [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: func_db.c:145 function_db_read: DB: AMPUSER/108@108/cidname not found in database. [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4228 __sip_ack: Acked pending invite 102 [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5f57a25a52547db879c397f224122103@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4228 __sip_ack: Acked pending invite 102 [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4a1526320c1b52517d88362c631a748a@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4a1526320c1b52517d88362c631a748a@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:6842 sip_answer: SIP answering channel: SIP/bandwidth-0000001a [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:12888 transmit_response_with_sdp: Setting framing from config on incoming call [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:12450 add_sdp: ** Our capability: (ulaw) Video flag: True Text flag: True [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: chan_sip.c:12451 add_sdp: ** Our prefcodec: (nothing) [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: features.c:4198 clear_dialed_interfaces: Removing dialed interfaces datastore on USTM/108@108-0x8def060 since we're bridging [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4228 __sip_ack: Acked pending invite 102 [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5f57a25a52547db879c397f224122103@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND101' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND103' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:25:51] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5de697f97396584a0d4f10984ac689eb@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0xb66749c8 -- start learning mode pass with addr = 67.231.0.115:11630 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0xb66749c8 -- probation = 4, seq = 2701 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0xb66749c8 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0xb66749c8 -- start learning mode pass with addr = 67.231.0.115:11630 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0xb66749c8 -- probation = 3, seq = 2702 [2012-08-06 16:25:51] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0xb66749c8 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0xb66749c8 -- start learning mode pass with addr = 67.231.0.115:11630 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0xb66749c8 -- probation = 2, seq = 2703 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0xb66749c8 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:25:52] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '771935198_50483733@192.168.27.84' of Response 27148: Match Found [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0xb66749c8 -- start learning mode pass with addr = 67.231.0.115:11630 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0xb66749c8 -- probation = 1, seq = 2704 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2918 ast_rtp_read: 0xb66749c8 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 67.231.0.115:11630 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2037 ast_rtp_write: Ooh, format changed from unknown to ulaw [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2072 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [2012-08-06 16:25:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1932 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x8e70c04' [2012-08-06 16:25:54] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 51459080687f64cd103ce0d14826353d@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:25:54] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 28c3b582741926606590b0073eb91640@192.168.183.1:5060 [2012-08-06 16:25:54] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '28c3b582741926606590b0073eb91640@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:54] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 372 [2012-08-06 16:25:58] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0x8e8e524' [2012-08-06 16:25:58] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0x8e3fe84' [2012-08-06 16:25:58] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0xb667a274' [2012-08-06 16:25:58] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0xb6699a54' [2012-08-06 16:25:58] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0xb66aafd4' [2012-08-06 16:25:58] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 2508b54e69760b6b572fb216241657ef@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:25:58] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 5b8fc7a123cd6e3e07f34d7016e75613@192.168.183.1:5060 [2012-08-06 16:25:58] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5b8fc7a123cd6e3e07f34d7016e75613@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:25:59] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 371 [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6db0fb852cdaff0f423830a7291c2763@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 285e59217b2ebfe26daec02a492774a7@192.168.183.1:5060 [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '285e59217b2ebfe26daec02a492774a7@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 413cc9cd571caab049acfc0e0ee698d0@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 5c54d9565d33f259122d2c6e7fa36239@192.168.183.1:5060 [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5c54d9565d33f259122d2c6e7fa36239@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1aeeeb443b3626e84d11bbd8170dd425@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 16a4776415a9c0395b5a9aee751c5f72@192.168.183.1:5060 [2012-08-06 16:26:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '16a4776415a9c0395b5a9aee751c5f72@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 101bdf30-8fb7a8c0-13c4-3d7b3be2-5e9045aa-3d7b3be2 - REGISTER (No RTP) [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4950057472b6f36728a3a4c52f7f7a29@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 63a185ad0ee3779a596f39a823d191e2@192.168.183.1:5060 [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 03d7874a35d7a22e4a717b550d4231b9@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 1572a3e12c04665353454f8a7399c095@192.168.183.1:5060 [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '1572a3e12c04665353454f8a7399c095@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:14] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '63a185ad0ee3779a596f39a823d191e2@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:15] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:26:28] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 471858e90893333d430067b82ac65d7a@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:28] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 7a00ddc87d2e49472e8f34877843255a@192.168.183.1:5060 [2012-08-06 16:26:28] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '7a00ddc87d2e49472e8f34877843255a@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:29] DEBUG[8277]: chan_iax2.c:2501 peercnt_remove: ip callno count decremented to 0 for 70.89.198.99 [2012-08-06 16:26:29] DEBUG[8282]: chan_iax2.c:2469 peercnt_add: ip callno count incremented to 1 for 70.89.198.99 [2012-08-06 16:26:29] DEBUG[8283]: chan_iax2.c:2825 sched_delay_remove: schedule decrement of callno used for 70.89.198.99 in 60 seconds [2012-08-06 16:26:29] DEBUG[8283]: chan_iax2.c:11092 socket_process_helper: Peer office: got pong, lastms 23, historicms 23, maxms 2000 [2012-08-06 16:26:33] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 7ed7b4902e3fec11023c5e6a3e52a6f2@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:33] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:26:33] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 768edf4d385d03b606e0225140d958ac@173.8.103.157:5060 [2012-08-06 16:26:33] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '768edf4d385d03b606e0225140d958ac@173.8.103.157:5060' of Request 102: Match Found -- Started music on hold, class 'default', on SIP/bandwidth-0000001a [2012-08-06 16:26:34] DEBUG[5348][C-0000000d]: channel.c:3460 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-08-06 16:26:34] DEBUG[5348][C-0000000d]: channel.c:5216 set_format: Set channel SIP/bandwidth-0000001a to write format slin [2012-08-06 16:26:34] DEBUG[5348][C-0000000d]: res_musiconhold.c:355 ast_moh_files_next: SIP/bandwidth-0000001a Opened file 0 '/var/lib/asterisk/mohmp3//wav_music-2' [2012-08-06 16:26:34] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2037 ast_rtp_write: Ooh, format changed from unknown to ulaw [2012-08-06 16:26:34] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2072 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [2012-08-06 16:26:34] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 2e190dd951ee5f190fa1be392764f7ad@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:34] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 2401138d1098235d0468cdfe5f72d8f2@192.168.183.1:5060 [2012-08-06 16:26:34] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '2401138d1098235d0468cdfe5f72d8f2@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1423247c28c44e1d4fa98faf519cc9ef@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 5f4766326d1900e3093057a03bead978@192.168.183.1:5060 [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 09ca049f624a4c79226883034facc2d0@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 0c6c5e8d58887e554dceb70f337ab4d0@192.168.183.1:5060 [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5f4766326d1900e3093057a03bead978@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:40] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '0c6c5e8d58887e554dceb70f337ab4d0@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:41] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND102' in family 'CustomDevstate' [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6c76592a2fdb18c34343b31779c08ca5@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 3a57169e40fecbba7143cc0936a76bc8@173.8.103.157:5060 [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '3a57169e40fecbba7143cc0936a76bc8@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4c08b7cd0b3c833a1c02ec8016e859e5@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 6e483fcb768474815b52fdb25d26bc75@173.8.103.157:5060 [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '6e483fcb768474815b52fdb25d26bc75@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 51ba292626d7b3861f3af0eb1163dd2d@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 6021e7f55759015519ec2072042a5a33@173.8.103.157:5060 [2012-08-06 16:26:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '6021e7f55759015519ec2072042a5a33@173.8.103.157:5060' of Request 102: Match Found -- Stopped music on hold on SIP/bandwidth-0000001a [2012-08-06 16:26:45] DEBUG[5348][C-0000000d]: channel.c:5216 set_format: Set channel SIP/bandwidth-0000001a to write format ulaw [2012-08-06 16:26:45] DEBUG[5348][C-0000000d]: channel.c:3460 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0x8dfb518 -- start learning mode pass with addr = 192.168.183.186:10000 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0x8dfb518 -- probation = 4, seq = 16262 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0x8dfb518 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0x8dfb518 -- start learning mode pass with addr = 192.168.183.186:10000 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0x8dfb518 -- probation = 3, seq = 16263 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0x8dfb518 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0x8dfb518 -- start learning mode pass with addr = 192.168.183.186:10000 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0x8dfb518 -- probation = 2, seq = 16264 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2914 ast_rtp_read: 0x8dfb518 -- Condition for learning hasn't exited, so reject the frame. [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2908 ast_rtp_read: 0x8dfb518 -- start learning mode pass with addr = 192.168.183.186:10000 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:1029 rtp_learning_rtp_seq_update: 0x8dfb518 -- probation = 1, seq = 16265 [2012-08-06 16:26:46] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2918 ast_rtp_read: 0x8dfb518 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 192.168.183.186:10000 [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:2514 ast_rtcp_read: Got RTCP report of 64 bytes [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:7369 ast_generic_bridge: Didn't get a frame from channel: USTM/108@108-0x8def060 [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:7845 ast_channel_bridge: Bridge stops bridging channels SIP/bandwidth-0000001a and USTM/108@108-0x8def060 [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:2554 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/bandwidth-0000001a' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Macro' -- Executing [h@macro-dial:1] Macro("SIP/bandwidth-0000001a", "hangupcall") in new stack [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '1' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-hangupcall:1] GotoIf("SIP/bandwidth-0000001a", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: GotoIf [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4303 pbx_substitute_variables_helper_full: Expression result is '0' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-hangupcall:3] ExecIf("SIP/bandwidth-0000001a", "0?Set(CDR(recordingfile)=)") in new stack [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: app_macro.c:434 _macro_exec: Executed application: ExecIf [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:4407 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-hangupcall:4] Hangup("SIP/bandwidth-0000001a", "") in new stack [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:2554 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/bandwidth-0000001a' == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/bandwidth-0000001a' in macro 'hangupcall' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:5417 ast_pbx_h_exten_run: Spawn extension (macro-dial,h,1) exited non-zero on 'SIP/bandwidth-0000001a' == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/bandwidth-0000001a' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: cdr_mysql.c:336 mysql_log: Inserting a CDR record. [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: cdr_mysql.c:339 mysql_log: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`did`) VALUES ('2012-08-06 16:25:48','\"TAYLOR TELEPHON\" <+16512454836>','+16512454836','600','ext-group','SIP/bandwidth-0000001a','USTM/108@108-0x8def060','Dial','SIP/101&SIP/103&SIP/106&USTM/107@107&USTM/108@108&USTM/109@109&SIP/110,30,trM(a','64','61','ANSWERED','3','1344288348.30','6516811421') [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: cdr_radius.c:208 radius_log: Unable to create RADIUS record. CDR not recorded! [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:2733 ast_hangup: Hanging up channel 'USTM/108@108-0x8def060' [2012-08-06 16:26:52] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND108' in family 'CustomDevstate' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: app_dial.c:3098 dial_exec_full: Exiting with DIALSTATUS=ANSWER. == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/bandwidth-0000001a' in macro 'dial' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: pbx.c:5898 __ast_pbx_run: Spawn extension (ext-group,600,12) exited non-zero on 'SIP/bandwidth-0000001a' == Spawn extension (ext-group, 600, 12) exited non-zero on 'SIP/bandwidth-0000001a' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:2554 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/bandwidth-0000001a' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: channel.c:2733 ast_hangup: Hanging up channel 'SIP/bandwidth-0000001a' [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: chan_sip.c:6635 sip_hangup: Hangup call SIP/bandwidth-0000001a, SIP callid 771935198_50483733@192.168.27.84 [2012-08-06 16:26:52] DEBUG[5348][C-0000000d]: res_rtp_asterisk.c:3299 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb666347c' [2012-08-06 16:26:52] DEBUG[8269][C-0000000d]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '771935198_50483733@192.168.27.84' of Request 102: Match Found [2012-08-06 16:26:52] DEBUG[8269]: rtp_engine.c:224 instance_destructor: Destroyed RTP instance '0xb666347c' [2012-08-06 16:26:54] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 3361772105a050830600288549b168aa@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:54] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 2ac46160038d909728775edc01e2900d@192.168.183.1:5060 [2012-08-06 16:26:54] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '2ac46160038d909728775edc01e2900d@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:54] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 372 [2012-08-06 16:26:58] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 13af0ec1052a4a09076cc0bf1b14f1f3@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:26:58] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 23dbbbc616d2370726d1e31058805bc0@192.168.183.1:5060 [2012-08-06 16:26:58] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '23dbbbc616d2370726d1e31058805bc0@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:26:59] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 371 [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4a62eddb363db93535f378024195383a@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 5e772a08647adad10df85c1452f3063d@192.168.183.1:5060 [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5e772a08647adad10df85c1452f3063d@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 13d1784b6e880bde3cf354083d8c7c1c@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 70a8c476081a073f19381db15424d50c@192.168.183.1:5060 [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '70a8c476081a073f19381db15424d50c@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 0eb3b11e746002b06f80375c42ad0738@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 6f44d7a362efb4d51397c28b43bc7921@192.168.183.1:5060 [2012-08-06 16:27:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '6f44d7a362efb4d51397c28b43bc7921@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 101bdf30-8fb7a8c0-13c4-3d7b3be2-5e9045aa-3d7b3be2 - REGISTER (No RTP) [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1b177d031800696352c7fb243bf46f4b@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 4f0ad36c7a5cc8a67346916868dd225d@192.168.183.1:5060 [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1a3c30617223fcb1369bb5246b7f8302@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 36e07ffc1c8d7b02296dd5fd3e76bc7e@192.168.183.1:5060 [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4f0ad36c7a5cc8a67346916868dd225d@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:12] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '36e07ffc1c8d7b02296dd5fd3e76bc7e@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:13] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:27:28] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 7d36833712d41893554787aa2fdee4cb@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:28] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 3c5b2ade072042f74df55b8136ad1278@192.168.183.1:5060 [2012-08-06 16:27:28] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '3c5b2ade072042f74df55b8136ad1278@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:29] DEBUG[8277]: chan_iax2.c:2501 peercnt_remove: ip callno count decremented to 0 for 70.89.198.99 [2012-08-06 16:27:29] DEBUG[8287]: chan_iax2.c:2469 peercnt_add: ip callno count incremented to 1 for 70.89.198.99 [2012-08-06 16:27:29] DEBUG[8278]: chan_iax2.c:2825 sched_delay_remove: schedule decrement of callno used for 70.89.198.99 in 60 seconds [2012-08-06 16:27:29] DEBUG[8278]: chan_iax2.c:11092 socket_process_helper: Peer office: got pong, lastms 18, historicms 18, maxms 2000 [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'Command' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'Command' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'Command' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Reusing connection to 192.168.173.240/user="jonnt" [2012-08-06 16:27:32] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Mailbox is empty [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxStatus' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:32] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:32] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Reusing connection to 192.168.173.240/user="jonnt" [2012-08-06 16:27:33] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Mailbox is empty [2012-08-06 16:27:33] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Reusing connection to 192.168.173.240/user="jonnt" [2012-08-06 16:27:33] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Mailbox is empty [2012-08-06 16:27:33] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Reusing connection to 192.168.173.240/user="jonnt" [2012-08-06 16:27:33] DEBUG[8358]: app_voicemail.c:3085 mm_log: IMAP Info: Mailbox is empty [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8358]: manager.c:5066 process_message: Running action 'MailboxCount' [2012-08-06 16:27:33] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6c1488b83a5ef0004e138e1f716eaeea@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:33] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:27:33] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 20b62ac24821a4b265db241803c5bbf3@173.8.103.157:5060 [2012-08-06 16:27:34] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '20b62ac24821a4b265db241803c5bbf3@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:27:34] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 662bdb674bb2dc1a02c7d7f803a27c2c@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:34] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 45a6032609acfaa306db8d9854632bb2@192.168.183.1:5060 [2012-08-06 16:27:34] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '45a6032609acfaa306db8d9854632bb2@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 2cb83abf0ce45946236ae6547d3858e3@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 2f8ce93f05265bec3364448e2c396976@192.168.183.1:5060 [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 127732765e01ee0c6934426d7b55575e@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 4ee117726289c778207395db2dafdbae@192.168.183.1:5060 [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '2f8ce93f05265bec3364448e2c396976@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:38] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4ee117726289c778207395db2dafdbae@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:39] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND102' in family 'CustomDevstate' [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 50e1721e3ce81d7e6b7f836226bc8ccd@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 59cb836c36aba79f7f496c963ab6a566@173.8.103.157:5060 [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '59cb836c36aba79f7f496c963ab6a566@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 5420b2d06b87b45033a6f959589cdca0@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 297da698697585d8014eb8c96bbf1814@173.8.103.157:5060 [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '297da698697585d8014eb8c96bbf1814@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 7071ee254785e21e70c8ac19653812f2@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 48e9e41226f0503f7543f6a2622e0ee7@173.8.103.157:5060 [2012-08-06 16:27:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '48e9e41226f0503f7543f6a2622e0ee7@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:27:54] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 05ea39ad313a9d62723972457616c5c7@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:54] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 04e0b5450ad59576604be1b24b3d2dba@192.168.183.1:5060 [2012-08-06 16:27:54] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '04e0b5450ad59576604be1b24b3d2dba@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:54] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 372 [2012-08-06 16:27:58] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 162add753a5c91c439f73b995e5aed3b@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:27:58] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 670e875252cbed09510e370870bb9da3@192.168.183.1:5060 [2012-08-06 16:27:58] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '670e875252cbed09510e370870bb9da3@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:27:59] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 371 [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 2f66d8e750d26ce944f8d1ee5530c7d7@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 4eae145d622f0e1b4976ac20060fbb41@192.168.183.1:5060 [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4eae145d622f0e1b4976ac20060fbb41@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1819d8c9118b6ab0461460043b2e8cd5@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 35bb0a9f7180cb506b548542375a9acb@192.168.183.1:5060 [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '35bb0a9f7180cb506b548542375a9acb@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4acded77268ee65019cb82857b4a6e91@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 2478fdd84b381c4b0a93924a552d0e91@192.168.183.1:5060 [2012-08-06 16:28:03] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '2478fdd84b381c4b0a93924a552d0e91@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 101bdf30-8fb7a8c0-13c4-3d7b3be2-5e9045aa-3d7b3be2 - REGISTER (No RTP) [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 51235ffb4436769b1513ca7230f57747@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 71646a8a576c66b5300d569437b52474@192.168.183.1:5060 [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6af0a7643bd323c4150e043c0c74fdf8@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 696510c25d5cfd2549232f1e6a446498@192.168.183.1:5060 [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '71646a8a576c66b5300d569437b52474@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:10] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '696510c25d5cfd2549232f1e6a446498@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:11] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND110' in family 'CustomDevstate' [2012-08-06 16:28:28] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 1a2431821770feaf554157a43ff12480@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:28] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 41331a46082314d7586c04b3441e07dd@192.168.183.1:5060 [2012-08-06 16:28:28] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '41331a46082314d7586c04b3441e07dd@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:29] DEBUG[8277]: chan_iax2.c:2501 peercnt_remove: ip callno count decremented to 0 for 70.89.198.99 [2012-08-06 16:28:29] DEBUG[8282]: chan_iax2.c:2469 peercnt_add: ip callno count incremented to 1 for 70.89.198.99 [2012-08-06 16:28:29] DEBUG[8283]: chan_iax2.c:2825 sched_delay_remove: schedule decrement of callno used for 70.89.198.99 in 60 seconds [2012-08-06 16:28:29] DEBUG[8283]: chan_iax2.c:11092 socket_process_helper: Peer office: got pong, lastms 21, historicms 21, maxms 2000 [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 32a3fb9d5359bfbc063a1e324e357558@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 5597f33731f10daf442c2dbc2c566a54@173.8.103.157:5060 [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '5597f33731f10daf442c2dbc2c566a54@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4c5dded61bbd477e4b8c06bd082eb104@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 4a0ea1a31831f1c3256b44ee11b16444@192.168.183.1:5060 [2012-08-06 16:28:34] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4a0ea1a31831f1c3256b44ee11b16444@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:15268 parse_register_contact: Store REGISTER's Contact header for call routing. [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 5f283da341d4a41e04ed4df729fa1eea@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 4766eb453f6f22b653a3a81c37fdf022@192.168.183.1:5060 [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 66fe775076b2db51733af99f0d3c018b@192.168.183.1:5060 - NOTIFY (No RTP) [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method NOTIFY - callid 60ad586d487ad8e514304d9c5fb889fc@192.168.183.1:5060 [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '4766eb453f6f22b653a3a81c37fdf022@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:36] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '60ad586d487ad8e514304d9c5fb889fc@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:37] DEBUG[8264]: db.c:329 ast_db_get: Unable to find key 'DND102' in family 'CustomDevstate' [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 3c7508123bb945f024ac034110f2945b@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 25835e527b32d9153516ef436aa9a195@173.8.103.157:5060 [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '25835e527b32d9153516ef436aa9a195@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 5e3a4c9f36cb7dd074d7c96302d172ba@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.225.202:5060 is not local, substituting externaddr [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 7a17399f31c645e47f90479055857b0c@173.8.103.157:5060 [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '7a17399f31c645e47f90479055857b0c@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 6e53798562dd63bd5712516b72d2daf3@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3698 ast_sip_ouraddrfor: Target address 216.82.224.202:5060 is not local, substituting externaddr [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 57c133a9431efa7e4ad6ac274bf97dab@173.8.103.157:5060 [2012-08-06 16:28:44] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '57c133a9431efa7e4ad6ac274bf97dab@173.8.103.157:5060' of Request 102: Match Found [2012-08-06 16:28:54] DEBUG[8269]: chan_sip.c:8299 sip_alloc: Allocating new SIP dialog for 4b1e40ec53bd698a0d2d6d856e41c797@192.168.183.1:5060 - OPTIONS (No RTP) [2012-08-06 16:28:54] DEBUG[8269]: chan_sip.c:3217 initialize_initreq: Initializing initreq for method OPTIONS - callid 7afa4cb8021b68df0c75ecd2740f6859@192.168.183.1:5060 [2012-08-06 16:28:54] DEBUG[8269]: chan_sip.c:4266 __sip_ack: Stopping retransmission on '7afa4cb8021b68df0c75ecd2740f6859@192.168.183.1:5060' of Request 102: Match Found [2012-08-06 16:28:54] DEBUG[8269]: chan_sip.c:27324 handle_request_do: Invalid SIP message - rejected , no callid, len 372