[Apr 27 10:48:20] Asterisk SVN-branch-1.4-r189664, Copyright (C) 1999 - 2008 Digium, Inc. and others. [Apr 27 10:48:20] Created by Mark Spencer [Apr 27 10:48:20] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Apr 27 10:48:20] This is free software, with components licensed under the GNU General Public [Apr 27 10:48:20] License version 2 and other licenses; you are welcome to redistribute it under [Apr 27 10:48:20] certain conditions. Type 'core show license' for details. [Apr 27 10:48:20] ========================================================================= [Apr 27 10:48:23] Asterisk Ready. [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 304d01953da7adba5dd4aeba278c8dac@10.4.119.245 Their Tag Our tag: as2a443d7c [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '304d01953da7adba5dd4aeba278c8dac@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:26] NOTICE[11598]: chan_sip.c:12983 handle_response_peerpoke: Peer '4567' is now Reachable. (1ms / 2000ms) [Apr 27 10:48:26] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Apr 27 10:48:26] Really destroying SIP dialog '304d01953da7adba5dd4aeba278c8dac@10.4.119.245' Method: OPTIONS [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Apr 27 10:48:26] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 4567 [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Apr 27 10:48:26] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for 5fcbba46fbce0780 - REGISTER (No RTP) [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 27 10:48:26] -- Saved useragent "Mediatrix 3301-001 v2.0.1.8" for peer 3456 [Apr 27 10:48:26] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 1bf3863a7e76e6c80c47062511695640@10.4.119.245 Their Tag Our tag: as6a8515c8 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '1bf3863a7e76e6c80c47062511695640@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:26] NOTICE[11598]: chan_sip.c:12983 handle_response_peerpoke: Peer '3456' is now Reachable. (1ms / 2000ms) [Apr 27 10:48:26] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Apr 27 10:48:26] Really destroying SIP dialog '1bf3863a7e76e6c80c47062511695640@10.4.119.245' Method: OPTIONS [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Apr 27 10:48:26] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 3456 [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Apr 27 10:48:26] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 3456 [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Apr 27 10:48:26] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:26] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 5fcbba46fbce0780 Their Tag 449df9e4c4 Our tag: as7a610ac3 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for b81f7eebf62addae - REGISTER (No RTP) [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 27 10:48:26] -- Saved useragent "Mediatrix 3301-001 v2.0.1.8" for peer 4567 [Apr 27 10:48:26] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Apr 27 10:48:26] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 4567 [Apr 27 10:48:26] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Apr 27 10:48:26] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 4e27c0b750e765b724fa6427514c7e0d@10.4.119.245 Their Tag Our tag: as186b76c5 [Apr 27 10:48:26] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '4e27c0b750e765b724fa6427514c7e0d@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:26] Really destroying SIP dialog '4e27c0b750e765b724fa6427514c7e0d@10.4.119.245' Method: OPTIONS [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: b81f7eebf62addae Their Tag a29599a731 Our tag: as0a7630c1 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 5fcbba46fbce0780 Their Tag 449df9e4c4 Our tag: as7a610ac3 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245 - REGISTER (No RTP) [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 27 10:48:28] -- Saved useragent "MxSipApp/5.0.24.172 " for peer 5678 [Apr 27 10:48:28] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245 Their Tag 51463cae4e5ab01 Our tag: as3f1135ca [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: b81f7eebf62addae Their Tag a29599a731 Our tag: as0a7630c1 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 5fcbba46fbce0780 Their Tag 449df9e4c4 Our tag: as7a610ac3 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245 - REGISTER (No RTP) [Apr 27 10:48:28] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 27 10:48:28] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 27 10:48:28] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 5678 [Apr 27 10:48:28] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 27 10:48:28] -- Saved useragent "MxSipApp/5.0.24.172 " for peer 6789 [Apr 27 10:48:28] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:28] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6789 [Apr 27 10:48:28] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6789 [Apr 27 10:48:28] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 6789 [Apr 27 10:48:28] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/6789 - state 1 (Not in use) [Apr 27 10:48:28] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/6789' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245 Their Tag eb3aac4bf851ad9 Our tag: as127fc228 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245 Their Tag 51463cae4e5ab01 Our tag: as3f1135ca [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: b81f7eebf62addae Their Tag a29599a731 Our tag: as0a7630c1 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 5fcbba46fbce0780 Their Tag 449df9e4c4 Our tag: as7a610ac3 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to Off [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to Off [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for 59be7cef736dd8afd2861e6704266e07@10.4.119.245 - INVITE (With RTP) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to On [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to On [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:5602 process_sdp: T38 state changed to 0 on channel [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:5682 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:14673 handle_request_invite: Checking SIP call limits for device 6789 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:3288 update_call_counter: Updating call counter for incoming call [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4131 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4132 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4133 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4134 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4157 sip_new: This channel will not be able to handle video. [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:8568 build_route: build_route: Contact hop: sip:6789@10.4.119.185 [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:14756 handle_request_invite: SIP/6789-09d01710: New call is still down.... Trying... [Apr 27 10:48:31] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6789 [Apr 27 10:48:31] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6789 [Apr 27 10:48:31] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 6789 [Apr 27 10:48:31] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/6789 - state 1 (Not in use) [Apr 27 10:48:31] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' [Apr 27 10:48:31] -- Executing [1234@TestGateway:1] Goto("SIP/6789-09d01710", "aa_3|s|1") in new stack [Apr 27 10:48:31] -- Goto (aa_3,s,1) [Apr 27 10:48:31] DEBUG[11616]: pbx.c:1760 pbx_substitute_variables_helper_full: Expression result is '1' [Apr 27 10:48:31] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' [Apr 27 10:48:31] -- Executing [s@aa_3:1] GotoIf("SIP/6789-09d01710", "1?3") in new stack [Apr 27 10:48:31] -- Goto (aa_3,s,3) [Apr 27 10:48:31] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Answer' [Apr 27 10:48:31] -- Executing [s@aa_3:3] Answer("SIP/6789-09d01710", "") in new stack [Apr 27 10:48:31] DEBUG[11616]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6789 [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:3761 sip_answer: SIP answering channel: SIP/6789-09d01710 [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:6909 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:6632 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:6633 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:6750 add_sdp: -- Done with adding codecs to SDP [Apr 27 10:48:31] DEBUG[11616]: channel.c:2459 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Apr 27 10:48:31] DEBUG[11616]: chan_sip.c:6851 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 27 10:48:31] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Wait' [Apr 27 10:48:31] -- Executing [s@aa_3:4] Wait("SIP/6789-09d01710", "1") in new stack [Apr 27 10:48:31] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/6789' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:31] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6789 [Apr 27 10:48:31] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 6789 [Apr 27 10:48:31] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/6789 - state 1 (Not in use) [Apr 27 10:48:31] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/6789' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 27 10:48:31] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '59be7cef736dd8afd2861e6704266e07@10.4.119.245' of Response 2049184837: Match Found [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Apr 27 10:48:32] -- Executing [s@aa_3:5] Set("SIP/6789-09d01710", "LOOPED=1") in new stack [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1760 pbx_substitute_variables_helper_full: Expression result is '0' [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' [Apr 27 10:48:32] -- Executing [s@aa_3:6] GotoIf("SIP/6789-09d01710", "0?hang|1") in new stack [Apr 27 10:48:32] DEBUG[11616]: pbx.c:6053 pbx_builtin_gotoif: Not taking any branch [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Apr 27 10:48:32] -- Executing [s@aa_3:7] Set("SIP/6789-09d01710", "TIMEOUT(digit)=3") in new stack [Apr 27 10:48:32] -- Digit timeout set to 3 [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Apr 27 10:48:32] -- Executing [s@aa_3:8] Set("SIP/6789-09d01710", "TIMEOUT(response)=7") in new stack [Apr 27 10:48:32] -- Response timeout set to 7 [Apr 27 10:48:32] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'BackGround' [Apr 27 10:48:32] -- Executing [s@aa_3:9] BackGround("SIP/6789-09d01710", "custom/aa_3") in new stack [Apr 27 10:48:32] DEBUG[11616]: channel.c:2991 set_format: Set channel SIP/6789-09d01710 to write format slin [Apr 27 10:48:32] DEBUG[11616]: rtp.c:2822 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 27 10:48:32] DEBUG[11616]: rtp.c:2839 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 27 10:48:32] -- Playing 'custom/aa_3' (language 'en') [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 27 10:48:34] DEBUG[11616]: channel.c:2991 set_format: Set channel SIP/6789-09d01710 to write format ulaw [Apr 27 10:48:34] DEBUG[11616]: pbx.c:2414 __ast_pbx_run: Oooh, got something to jump out with ('1')! [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag Our tag: as45572c62 [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag Our tag: as5b3f511f [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2becf8490e9891cb361dd403307edec6@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:34] WARNING[11598]: chan_sip.c:13227 handle_response: Remote host can't match request NOTIFY to call '2becf8490e9891cb361dd403307edec6@10.4.119.245'. Giving up. [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag Our tag: as45572c62 [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2a6826dd28df0da5352613ca468f6a0a@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:34] WARNING[11598]: chan_sip.c:13227 handle_response: Remote host can't match request NOTIFY to call '2a6826dd28df0da5352613ca468f6a0a@10.4.119.245'. Giving up. [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 16aa5bc9748ea8a91ed2e6250fe9290f@10.4.119.245 Their Tag Our tag: as2c053e7c [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '16aa5bc9748ea8a91ed2e6250fe9290f@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:34] Really destroying SIP dialog '16aa5bc9748ea8a91ed2e6250fe9290f@10.4.119.245' Method: NOTIFY [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:34] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:35] == CDR updated on SIP/6789-09d01710 [Apr 27 10:48:35] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Dial' [Apr 27 10:48:35] -- Executing [1234@aa_3:1] Dial("SIP/6789-09d01710", "SIP/5678@TestGateway1|20") in new stack [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:16843 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:2850 create_addr_from_peer: Our T38 capability (3872) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to Off [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to Off [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4131 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4132 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4133 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4134 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4136 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:4157 sip_new: This channel will not be able to handle video. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable LOOPED. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 27 10:48:35] DEBUG[11616]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:3082 sip_call: Outgoing Call for 5678 [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:3288 update_call_counter: Updating call counter for outgoing call [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:3097 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:6632 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:6633 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:6750 add_sdp: -- Done with adding codecs to SDP [Apr 27 10:48:35] DEBUG[11616]: channel.c:2459 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Apr 27 10:48:35] DEBUG[11616]: chan_sip.c:6851 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 27 10:48:35] -- Called 5678@TestGateway1 [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag Our tag: as30a9d2c6 [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:2269 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' Request 102: Found [Apr 27 10:48:35] DEBUG[11598]: chan_sip.c:12455 handle_response_invite: SIP response 100 to standard invite [Apr 27 10:48:37] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245 Their Tag eb3aac4bf851ad9 Our tag: as127fc228 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245 Their Tag 51463cae4e5ab01 Our tag: as3f1135ca [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: b81f7eebf62addae Their Tag a29599a731 Our tag: as0a7630c1 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 5fcbba46fbce0780 Their Tag 449df9e4c4 Our tag: as7a610ac3 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2123df764073374b4881fa526db78a3b@10.4.119.245 Their Tag 3966603599 Our tag: as7e8ab5a0 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 Their Tag 153978010 Our tag: as63e4be66 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to Off [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to Off [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 - INVITE (With RTP) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to Off [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to Off [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5602 process_sdp: T38 state changed to 0 on channel [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5682 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:14673 handle_request_invite: Checking SIP call limits for device [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:3288 update_call_counter: Updating call counter for incoming call [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4131 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4132 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4133 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4134 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4157 sip_new: This channel will not be able to handle video. [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:8568 build_route: build_route: Contact hop: sip:anonymous@10.4.126.129 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:14756 handle_request_invite: SIP/TestGateway1-09d9de58: New call is still down.... Trying... [Apr 27 10:48:38] DEBUG[11598]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/TestGateway1 [Apr 27 10:48:38] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - TestGateway1 [Apr 27 10:48:38] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer TestGateway1 [Apr 27 10:48:38] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/TestGateway1 - state 1 (Not in use) [Apr 27 10:48:38] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/TestGateway1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:38] DEBUG[11617]: pbx.c:1843 pbx_extension_helper: Launching 'Dial' [Apr 27 10:48:38] -- Executing [5678@TestGateway:1] Dial("SIP/TestGateway1-09d9de58", "SIP/5678|20") in new stack [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:16843 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:2850 create_addr_from_peer: Our T38 capability (3872) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:2804 do_setnat: Setting NAT on RTP to On [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:2814 do_setnat: Setting NAT on UDPTL to On [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4131 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4132 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4133 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4134 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4136 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:4157 sip_new: This channel will not be able to handle video. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag Our tag: as3a61db10 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2269 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' Request 102: Found [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:12455 handle_response_invite: SIP response 183 to standard invite [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5602 process_sdp: T38 state changed to 0 on channel SIP/TestGateway1-09d0be30 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5682 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5689 process_sdp: We have an owner, now see if we need to change this call [Apr 27 10:48:38] DEBUG[11616]: rtp.c:2822 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 27 10:48:38] DEBUG[11616]: rtp.c:2839 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 27 10:48:38] -- SIP/TestGateway1-09d0be30 is making progress passing it to SIP/6789-09d01710 [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 27 10:48:38] DEBUG[11617]: channel.c:3499 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:3082 sip_call: Outgoing Call for 5678 [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:3288 update_call_counter: Updating call counter for outgoing call [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:3097 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6632 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6633 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6750 add_sdp: -- Done with adding codecs to SDP [Apr 27 10:48:38] DEBUG[11617]: channel.c:2459 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6851 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 27 10:48:38] -- Called 5678 [Apr 27 10:48:38] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 72 bytes [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag Our tag: as3a61db10 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2269 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6b5e5477417ca40705527dd21bfcd99b@10.4.119.245' Request 102: Found [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:12455 handle_response_invite: SIP response 100 to standard invite [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:2269 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6b5e5477417ca40705527dd21bfcd99b@10.4.119.245' Request 102: Found [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:12455 handle_response_invite: SIP response 183 to standard invite [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5602 process_sdp: T38 state changed to 0 on channel SIP/5678-09da2870 [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5682 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11598]: chan_sip.c:5689 process_sdp: We have an owner, now see if we need to change this call [Apr 27 10:48:38] -- SIP/5678-09da2870 is making progress passing it to SIP/TestGateway1-09d9de58 [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6909 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6632 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6633 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6750 add_sdp: -- Done with adding codecs to SDP [Apr 27 10:48:38] DEBUG[11617]: channel.c:2459 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Apr 27 10:48:38] DEBUG[11617]: chan_sip.c:6851 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 27 10:48:38] DEBUG[11617]: rtp.c:2822 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 27 10:48:38] DEBUG[11617]: rtp.c:2839 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 Their Tag 3400570672 Our tag: as45572c62 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2becf8490e9891cb361dd403307edec6@10.4.119.245 Their Tag 893730783 Our tag: as5b3f511f [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received INFO (13) - Command in SIP INFO [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:39] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' of Request 103: Match Found [Apr 27 10:48:40] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:40] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:40] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:40] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' of Request 104: Match Found [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog '2becf8490e9891cb361dd403307edec6@10.4.119.245' [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog 2becf8490e9891cb361dd403307edec6@10.4.119.245 [Apr 27 10:48:41] Really destroying SIP dialog '2becf8490e9891cb361dd403307edec6@10.4.119.245' Method: NOTIFY [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog '2a6826dd28df0da5352613ca468f6a0a@10.4.119.245' [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog 2a6826dd28df0da5352613ca468f6a0a@10.4.119.245 [Apr 27 10:48:41] Really destroying SIP dialog '2a6826dd28df0da5352613ca468f6a0a@10.4.119.245' Method: NOTIFY [Apr 27 10:48:41] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:41] DEBUG[11617]: rtp.c:2822 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 27 10:48:41] DEBUG[11617]: rtp.c:2839 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:2196 __sip_ack: Acked pending invite 102 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '6b5e5477417ca40705527dd21bfcd99b@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:12455 handle_response_invite: SIP response 200 to standard invite [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:5602 process_sdp: T38 state changed to 0 on channel SIP/5678-09da2870 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:5682 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:5689 process_sdp: We have an owner, now see if we need to change this call [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:3288 update_call_counter: Updating call counter for outgoing call [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:8568 build_route: build_route: Contact hop: Test [Apr 27 10:48:41] DEBUG[11617]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Apr 27 10:48:41] -- SIP/5678-09da2870 answered SIP/TestGateway1-09d9de58 [Apr 27 10:48:41] DEBUG[11617]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/TestGateway1 [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:3761 sip_answer: SIP answering channel: SIP/TestGateway1-09d9de58 [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:6909 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:6632 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:6633 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:6750 add_sdp: -- Done with adding codecs to SDP [Apr 27 10:48:41] DEBUG[11617]: channel.c:2459 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Apr 27 10:48:41] DEBUG[11617]: chan_sip.c:6851 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 27 10:48:41] -- Packet2Packet bridging SIP/TestGateway1-09d9de58 and SIP/5678-09da2870 [Apr 27 10:48:41] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 27 10:48:41] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 5678 [Apr 27 10:48:41] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 27 10:48:41] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - TestGateway1 [Apr 27 10:48:41] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer TestGateway1 [Apr 27 10:48:41] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/TestGateway1 - state 1 (Not in use) [Apr 27 10:48:41] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:41] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/TestGateway1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245' of Response 153061950: Match Found [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:41] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:42] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:42] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:42] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:43] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:43] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:43] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:43] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:43] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 72 bytes [Apr 27 10:48:45] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:45] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:45] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:45] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:45] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 27 10:48:46] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:48] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 27 10:48:49] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:49] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:49] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:50] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 72 bytes [Apr 27 10:48:51] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 27 10:48:51] DEBUG[11616]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:51] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:53] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:53] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:53] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:55] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog '7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245' [Apr 27 10:48:55] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog 7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245 [Apr 27 10:48:55] Really destroying SIP dialog '7c0f8bdb133e5d286086acaf4f5a668e@10.4.119.245' Method: NOTIFY [Apr 27 10:48:55] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog '2123df764073374b4881fa526db78a3b@10.4.119.245' [Apr 27 10:48:55] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog 2123df764073374b4881fa526db78a3b@10.4.119.245 [Apr 27 10:48:55] Really destroying SIP dialog '2123df764073374b4881fa526db78a3b@10.4.119.245' Method: NOTIFY [Apr 27 10:48:55] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 27 10:48:56] -- Nobody picked up in 20000 ms [Apr 27 10:48:56] DEBUG[11616]: rtp.c:1520 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 27 10:48:56] DEBUG[11616]: channel.c:1520 ast_hangup: Hanging up channel 'SIP/TestGateway1-09d0be30' [Apr 27 10:48:56] DEBUG[11616]: chan_sip.c:3605 sip_hangup: Hangup call SIP/TestGateway1-09d0be30, SIP callid 2a88e3194f83474020cfc54d212749bd@10.4.119.245) [Apr 27 10:48:56] DEBUG[11616]: chan_sip.c:3628 sip_hangup: Hanging up channel in state Down (not UP) [Apr 27 10:48:56] DEBUG[11616]: chan_sip.c:2196 __sip_ack: Acked pending invite 102 [Apr 27 10:48:56] DEBUG[11616]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:56] DEBUG[11616]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/TestGateway1 [Apr 27 10:48:56] DEBUG[11616]: app_dial.c:1822 dial_exec_full: Exiting with DIALSTATUS=NOANSWER. [Apr 27 10:48:56] == Auto fallthrough, channel 'SIP/6789-09d01710' status is 'NOANSWER' [Apr 27 10:48:56] DEBUG[11616]: channel.c:1427 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/6789-09d01710' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1843 pbx_extension_helper: Launching 'Hangup' [Apr 27 10:48:56] -- Executing [h@aa_3:1] Hangup("SIP/6789-09d01710", "") in new stack [Apr 27 10:48:56] DEBUG[11616]: pbx.c:2563 __ast_pbx_run: Spawn extension (aa_3,h,1) exited non-zero on 'SIP/6789-09d01710' [Apr 27 10:48:56] == Spawn extension (aa_3, h, 1) exited non-zero on 'SIP/6789-09d01710' [Apr 27 10:48:56] DEBUG[11616]: channel.c:1520 ast_hangup: Hanging up channel 'SIP/6789-09d01710' [Apr 27 10:48:56] DEBUG[11616]: chan_sip.c:3605 sip_hangup: Hangup call SIP/6789-09d01710, SIP callid 59be7cef736dd8afd2861e6704266e07@10.4.119.245) [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '6789' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '6789' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '1234' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'aa_3' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/6789-09d01710' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/TestGateway1-09d0be30' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/5678@TestGateway1|20' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:48:31' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:48:31' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:48:56' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '25' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '25' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '1240843711.0' [Apr 27 10:48:56] DEBUG[11616]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Apr 27 10:48:56] DEBUG[11616]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6789 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:56] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - TestGateway1 [Apr 27 10:48:56] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer TestGateway1 [Apr 27 10:48:56] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/TestGateway1 - state 1 (Not in use) [Apr 27 10:48:56] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6789 [Apr 27 10:48:56] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 6789 [Apr 27 10:48:56] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/6789 - state 1 (Not in use) [Apr 27 10:48:56] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/TestGateway1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:56] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/6789' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 59be7cef736dd8afd2861e6704266e07@10.4.119.245 Their Tag 0e7fe467352e402 Our tag: as142f921c [Apr 27 10:48:56] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '59be7cef736dd8afd2861e6704266e07@10.4.119.245' of Request 102: Match Found [Apr 27 10:48:56] Really destroying SIP dialog '59be7cef736dd8afd2861e6704266e07@10.4.119.245' Method: INFO [Apr 27 10:48:56] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:1958 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #92)) [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:57] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:1958 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #92)) [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog '5fcbba46fbce0780' [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog 5fcbba46fbce0780 [Apr 27 10:48:58] Really destroying SIP dialog '5fcbba46fbce0780' Method: REGISTER [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog 'b81f7eebf62addae' [Apr 27 10:48:58] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog b81f7eebf62addae [Apr 27 10:48:58] Really destroying SIP dialog 'b81f7eebf62addae' Method: REGISTER [Apr 27 10:48:59] DEBUG[11617]: rtp.c:877 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:1958 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #92)) [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog 'a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245' [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245 [Apr 27 10:49:00] Really destroying SIP dialog 'a319f3e7505c2aef26a77b0fa41a42b9@10.4.119.245' Method: REGISTER [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:2133 __sip_autodestruct: Auto destroying SIP dialog 'ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245' [Apr 27 10:49:00] DEBUG[11598]: chan_sip.c:3397 sip_destroy: Destroying SIP dialog ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245 [Apr 27 10:49:00] Really destroying SIP dialog 'ff9f0ba0706f99fe7162f4ecaf4cf824@10.4.119.245' Method: REGISTER [Apr 27 10:49:01] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:49:01] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:49:01] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:1680 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:15529 handle_request_bye: Received bye, issuing owner hangup [Apr 27 10:49:02] DEBUG[11617]: rtp.c:3262 bridge_p2p_loop: Oooh, got a hangup [Apr 27 10:49:02] DEBUG[11617]: channel.c:4284 ast_channel_bridge: Returning from native bridge, channels: SIP/TestGateway1-09d9de58, SIP/5678-09da2870 [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'anonymous' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'anonymous' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '5678' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'TestGateway' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/TestGateway1-09d9de58' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-09da2870' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:48:38' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:48:41' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-04-27 10:49:02' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '24' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '21' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '1240843718.2' [Apr 27 10:49:02] DEBUG[11617]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Apr 27 10:49:02] DEBUG[11617]: channel.c:1520 ast_hangup: Hanging up channel 'SIP/5678-09da2870' [Apr 27 10:49:02] DEBUG[11617]: chan_sip.c:3605 sip_hangup: Hangup call SIP/5678-09da2870, SIP callid 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245) [Apr 27 10:49:02] DEBUG[11617]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Apr 27 10:49:02] DEBUG[11617]: rtp.c:1520 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 27 10:49:02] DEBUG[11617]: app_dial.c:1822 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 27 10:49:02] DEBUG[11617]: pbx.c:2429 __ast_pbx_run: Spawn extension (TestGateway,5678,1) exited non-zero on 'SIP/TestGateway1-09d9de58' [Apr 27 10:49:02] == Spawn extension (TestGateway, 5678, 1) exited non-zero on 'SIP/TestGateway1-09d9de58' [Apr 27 10:49:02] DEBUG[11617]: channel.c:1427 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/TestGateway1-09d9de58' [Apr 27 10:49:02] DEBUG[11617]: channel.c:1520 ast_hangup: Hanging up channel 'SIP/TestGateway1-09d9de58' [Apr 27 10:49:02] DEBUG[11617]: chan_sip.c:3605 sip_hangup: Hangup call SIP/TestGateway1-09d9de58, SIP callid 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245) [Apr 27 10:49:02] DEBUG[11617]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/TestGateway1 [Apr 27 10:49:02] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 27 10:49:02] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer 5678 [Apr 27 10:49:02] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 27 10:49:02] DEBUG[11585]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - TestGateway1 [Apr 27 10:49:02] DEBUG[11585]: chan_sip.c:16767 sip_devicestate: Checking device state for peer TestGateway1 [Apr 27 10:49:02] DEBUG[11585]: devicestate.c:287 do_state_change: Changing state for SIP/TestGateway1 - state 1 (Not in use) [Apr 27 10:49:02] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:49:02] DEBUG[11597]: app_queue.c:675 handle_statechange: Device 'SIP/TestGateway1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:4709 find_call: = No match Their Call ID: 6b5e5477417ca40705527dd21bfcd99b@10.4.119.245 Their Tag 4552f390976c75f Our tag: as3a61db10 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245 Their Tag e43d4b79d0ecf40 Our tag: as113e30a4 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245' of Request 102: Match Found [Apr 27 10:49:02] Really destroying SIP dialog '6b5e5477417ca40705527dd21bfcd99b@10.4.119.245' Method: BYE [Apr 27 10:49:02] Really destroying SIP dialog '7108d6f4f8331c4f81ea72a1e1ccc61d@10.4.119.245' Method: ACK [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:4709 find_call: = Found Their Call ID: 2a88e3194f83474020cfc54d212749bd@10.4.119.245 Their Tag 35b088f5addb603 Our tag: as30a9d2c6 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:15993 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:2228 __sip_ack: Stopping retransmission on '2a88e3194f83474020cfc54d212749bd@10.4.119.245' of Request 102: Match Found [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:1680 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2a88e3194f83474020cfc54d212749bd@10.4.119.245 [Apr 27 10:49:02] DEBUG[11598]: chan_sip.c:15533 handle_request_bye: Received bye, no owner, selfdestruct soon. [Apr 27 10:49:17] Beginning asterisk shutdown.... [Apr 27 10:49:17] Executing last minute cleanups [Apr 27 10:49:17] == Destroying musiconhold processes [Apr 27 10:49:17] DEBUG[11581]: res_musiconhold.c:1070 moh_class_destructor: Destroying MOH class 'default' [Apr 27 10:49:17] Asterisk cleanly ending (0). [Apr 27 10:49:17] DEBUG[11581]: asterisk.c:1320 quit_handler: Asterisk ending (0).