*CLI> Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for e47bfa7c-90481526-eb06dba7@10.130.1.100 - INVITE (With RTP) Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:1044 parse_sip_options: * SIP extension value: 2 for call e47bfa7c-90481526-eb06dba7@10.130.1.100 Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:7215 check_user_full: Setting NAT on RTP to 0 Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on 'e47bfa7c-90481526-eb06dba7@10.130.1.100' of Response 1: Match Found Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:7215 check_user_full: Setting NAT on RTP to 0 Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:10571 handle_request_invite: Checking SIP call limits for device polycom Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:6194 build_route: build_route: Contact hop: Nov 6 09:35:57 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Answer' -- Executing Answer("SIP/polycom-0817c798", "") in new stack Nov 6 09:35:57 DEBUG[17336]: chan_sip.c:2557 sip_answer: sip_answer(SIP/polycom-0817c798) Nov 6 09:35:57 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("SIP/polycom-0817c798", "1") in new stack Nov 6 09:35:57 DEBUG[17337]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 6 09:35:57 DEBUG[17338]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '44f433022148c1d35836e55c50570927@10.130.1.65' of Request 102: Match Found Nov 6 09:35:57 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on 'e47bfa7c-90481526-eb06dba7@10.130.1.100' of Response 2: Match Found Nov 6 09:35:57 DEBUG[17336]: rtp.c:411 ast_rtcp_read: Got RTCP report of 88 bytes Nov 6 09:35:58 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/polycom-0817c798", "IAX2/vodacomm@FreeWorldTel-Out2/[called_party_id]||M(page)") in new stack Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-3. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-2. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable STACK-internal-123-1. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPCALLID. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Nov 6 09:35:58 DEBUG[17336]: channel.c:2902 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called vodacomm@FreeWorldTel-Out2/[called_party_id] Nov 6 09:35:58 DEBUG[17336]: channel.c:2409 set_format: Set channel IAX2/FreeWorldTel-Out2-5 to read format ulaw Nov 6 09:35:58 DEBUG[17336]: channel.c:2409 set_format: Set channel IAX2/FreeWorldTel-Out2-5 to write format ulaw Nov 6 09:35:58 DEBUG[17339]: app_queue.c:500 changethread: Device 'IAX2/FreeWorldTel-Out2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- Call accepted by [IAX_provider_ip] (format ulaw) -- Format for call is ulaw -- IAX2/FreeWorldTel-Out2-5 is making progress passing it to SIP/polycom-0817c798 Nov 6 09:35:58 DEBUG[17333]: chan_iax2.c:6781 socket_read: Ooh, voice format changed to 4 Nov 6 09:35:58 DEBUG[17336]: rtp.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw -- IAX2/FreeWorldTel-Out2-5 answered SIP/polycom-0817c798 Nov 6 09:36:07 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:07 DEBUG[17341]: app_queue.c:500 changethread: Device 'IAX2/FreeWorldTel-Out2' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 6 09:36:07 DEBUG[17340]: rtp.c:411 ast_rtcp_read: Got RTCP report of 88 bytes Nov 6 09:36:08 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF' -- Executing SendDTMF("IAX2/FreeWorldTel-Out2-5", "234|100") in new stack Nov 6 09:36:08 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 2 Nov 6 09:36:08 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 3 Nov 6 09:36:08 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 4 Nov 6 09:36:09 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:10 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF' -- Executing SendDTMF("IAX2/FreeWorldTel-Out2-5", "6|250") in new stack Nov 6 09:36:10 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 6 Nov 6 09:36:10 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:11 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF' -- Executing SendDTMF("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:11 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 1 Nov 6 09:36:11 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:12 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF' -- Executing SendDTMF("IAX2/FreeWorldTel-Out2-5", "3") in new stack Nov 6 09:36:12 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 3 Nov 6 09:36:12 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "1") in new stack Nov 6 09:36:13 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'SendDTMF' -- Executing SendDTMF("IAX2/FreeWorldTel-Out2-5", "6") in new stack Nov 6 09:36:13 DTMF[17336]: channel.c:2345 ast_write: IAX2/FreeWorldTel-Out2-5 : 6 Nov 6 09:36:14 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Wait' -- Executing Wait("IAX2/FreeWorldTel-Out2-5", "10") in new stack Nov 6 09:36:17 DEBUG[17340]: rtp.c:411 ast_rtcp_read: Got RTCP report of 88 bytes Nov 6 09:36:24 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("IAX2/FreeWorldTel-Out2-5", "MACRO_RESULT=CONTINUE") in new stack Nov 6 09:36:24 DEBUG[17336]: app_dial.c:1489 dial_exec_full: Macro exited with status 0 Nov 6 09:36:24 DEBUG[17336]: channel.c:1373 ast_hangup: Hanging up channel 'IAX2/FreeWorldTel-Out2-5' Nov 6 09:36:24 DEBUG[17336]: chan_iax2.c:3104 iax2_hangup: We're hanging up IAX2/FreeWorldTel-Out2-5 now... -- Hungup 'IAX2/FreeWorldTel-Out2-5' Nov 6 09:36:24 DEBUG[17336]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Nov 6 09:36:24 DEBUG[17336]: pbx.c:1677 pbx_extension_helper: Launching 'Hangup' -- Executing Hangup("SIP/polycom-0817c798", "") in new stack Nov 6 09:36:24 DEBUG[17336]: pbx.c:2316 __ast_pbx_run: Spawn extension (internal,123,4) exited non-zero on 'SIP/polycom-0817c798' == Spawn extension (internal, 123, 4) exited non-zero on 'SIP/polycom-0817c798' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"polycom" ' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'polycom' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '123' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'internal' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/polycom-0817c798' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'IAX2/FreeWorldTel-Out2-5' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Hangup' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:35:57' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:35:57' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-06 09:36:24' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '27' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '27' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1162830957.0' Nov 6 09:36:24 DEBUG[17336]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 09:36:24 DEBUG[17336]: channel.c:1373 ast_hangup: Hanging up channel 'SIP/polycom-0817c798' Nov 6 09:36:24 DEBUG[17336]: chan_sip.c:2427 sip_hangup: Hangup call SIP/polycom-0817c798, SIP callid e47bfa7c-90481526-eb06dba7@10.130.1.100) Nov 6 09:36:24 DEBUG[17336]: chan_sip.c:2435 sip_hangup: update_call_counter(polycom) - decrement call limit counter Nov 6 09:36:24 DEBUG[17342]: app_queue.c:500 changethread: Device 'IAX2/FreeWorldTel-Out2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Nov 6 09:36:24 DEBUG[17343]: app_queue.c:500 changethread: Device 'SIP/polycom' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Nov 6 09:36:24 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on 'e47bfa7c-90481526-eb06dba7@10.130.1.100' of Request 102: Match Found Nov 6 09:36:36 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:36:36 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 6 Nov 6 09:36:36 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:36:36 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 7 Nov 6 09:36:46 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Nov 6 09:36:46 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Nov 6 09:36:46 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '6fc80dc810653d1f00fc2da9601158a3@10.130.1.65' of Request 102: Match Found Nov 6 09:36:46 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '535e114657711b5e1dfb07ae7c5cfa59@10.130.1.65' of Request 102: Match Found Nov 6 09:36:46 DEBUG[17333]: chan_iax2.c:7257 socket_read: Peer lastms 70, historicms 70, maxms 2000 Nov 6 09:36:46 DEBUG[17333]: chan_iax2.c:7257 socket_read: Peer lastms 71, historicms 71, maxms 2000 Nov 6 09:37:26 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:37:26 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 1 Nov 6 09:37:26 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:37:26 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 2 Nov 6 09:37:46 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Nov 6 09:37:46 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '44039126426762b70ac22f1738343f1f@10.130.1.65' of Request 102: Match Found Nov 6 09:37:46 DEBUG[17334]: chan_sip.c:3168 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Nov 6 09:37:46 DEBUG[17334]: chan_sip.c:1412 __sip_ack: Stopping retransmission on '4b0537ed3ccf644e21fa544c6f1e265e@10.130.1.65' of Request 102: Match Found Nov 6 09:37:46 DEBUG[17333]: chan_iax2.c:7257 socket_read: Peer lastms 72, historicms 72, maxms 2000 Nov 6 09:37:46 DEBUG[17333]: chan_iax2.c:7257 socket_read: Peer lastms 73, historicms 73, maxms 2000 Nov 6 09:38:16 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:38:16 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 5 Nov 6 09:38:16 DEBUG[17333]: chan_iax2.c:7751 iax2_do_register: Allocate call number Nov 6 09:38:16 DEBUG[17333]: chan_iax2.c:7757 iax2_do_register: Registration created on call 6