[Apr 19 16:09:09] Asterisk SVN-branch-1.4-r61686, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Apr 19 16:09:09] Created by Mark Spencer [Apr 19 16:09:09] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Apr 19 16:09:09] This is free software, with components licensed under the GNU General Public [Apr 19 16:09:09] License version 2 and other licenses; you are welcome to redistribute it under [Apr 19 16:09:09] certain conditions. Type 'core show license' for details. [Apr 19 16:09:09] ========================================================================= [Apr 19 16:09:10] Asterisk Ready. [Apr 19 16:09:12] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:12] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:09:12] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:09:13] -- Saved useragent "MxSipApp/5.0.17.104 MxSF/v3.2.2.4" for peer 5678 [Apr 19 16:09:13] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Apr 19 16:09:13] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:09:13] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:09:13] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:09:13] DEBUG[31082]: app_queue.c:546 changethread: 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 19 16:09:13] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:13] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:13] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:09:13] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:09:13] DEBUG[31064]: chan_sip.c:8418 register_verify: SIP REGISTER attempt failed for (null) : Peer not found [Apr 19 16:09:13] NOTICE[31064]: chan_sip.c:14602 handle_request_register: Registration from 'sip:3330001@10.4.119.245' failed for '10.4.121.237' - No matching peer found [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 Their Tag 8d686d0dc54cec4 Our tag: as2f63b219 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:8418 register_verify: SIP REGISTER attempt failed for (null) : Peer not found [Apr 19 16:09:14] NOTICE[31064]: chan_sip.c:14602 handle_request_register: Registration from 'sip:3330003@10.4.119.245' failed for '10.4.121.237' - No matching peer found [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 Their Tag 0ba9152c0097b33 Our tag: as7b06cd8e [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 Their Tag 8d686d0dc54cec4 Our tag: as2f63b219 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:8418 register_verify: SIP REGISTER attempt failed for (null) : Peer not found [Apr 19 16:09:14] NOTICE[31064]: chan_sip.c:14602 handle_request_register: Registration from 'sip:3330004@10.4.119.245' failed for '10.4.121.237' - No matching peer found [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245 Their Tag 8fb122cfafdce6a Our tag: as5c76bf6c [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 Their Tag 0ba9152c0097b33 Our tag: as7b06cd8e [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 Their Tag 8d686d0dc54cec4 Our tag: as2f63b219 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 613babc92668b0e660b5184f1b2fd48e@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:09:14] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:09:14] -- Saved useragent "MxSipApp/5.0.17.104 MxSF/v3.2.2.4" for peer 4321 [Apr 19 16:09:14] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321 [Apr 19 16:09:14] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:14] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:14] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:14] DEBUG[31083]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 23b27bcf5786b56110e0102305314e9a@10.4.119.245 Their Tag Our tag: as412be8c7 [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 1b8f98b6653233e06785209a1d15d333@10.4.119.245 Their Tag Our tag: as7ebb2237 [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '1b8f98b6653233e06785209a1d15d333@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:09:21] Really destroying SIP dialog '1b8f98b6653233e06785209a1d15d333@10.4.119.245' Method: NOTIFY [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 23b27bcf5786b56110e0102305314e9a@10.4.119.245 Their Tag Our tag: as412be8c7 [Apr 19 16:09:21] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '23b27bcf5786b56110e0102305314e9a@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:09:21] Really destroying SIP dialog '23b27bcf5786b56110e0102305314e9a@10.4.119.245' Method: NOTIFY [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 613babc92668b0e660b5184f1b2fd48e@10.4.119.245 Their Tag ea8124efa2ccbcd Our tag: as0e726e76 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245 Their Tag 8fb122cfafdce6a Our tag: as5c76bf6c [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 Their Tag 0ba9152c0097b33 Our tag: as7b06cd8e [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 Their Tag 8d686d0dc54cec4 Our tag: as2f63b219 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 50658f93845b2202f9d324879cc6c8f8@10.4.122.235 - INVITE (With RTP) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:13414 handle_request_invite: Checking SIP call limits for device 1234 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:7992 build_route: build_route: Contact hop: Test 2 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:13488 handle_request_invite: SIP/1234-0860bba8: New call is still down.... Trying... [Apr 19 16:09:27] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-0860bba8 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:09:27] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:09:27] DEBUG[31084]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 19 16:09:27] -- Executing [4321@default:1] Dial("SIP/1234-0860bba8", "SIP/4321|20|") in new stack [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:09:27] DEBUG[31084]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-4321-1. [Apr 19 16:09:27] DEBUG[31084]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 19 16:09:27] DEBUG[31084]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 19 16:09:27] DEBUG[31084]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 19 16:09:27] DEBUG[31084]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:2831 sip_call: Outgoing Call for 4321 [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:09:27] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:09:27] -- Called 4321 [Apr 19 16:09:27] DEBUG[31085]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag Our tag: as63d8c110 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6d0aae770b16489518c335b778af6d3a@10.4.119.245' Request 102: Found [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 100 to standard invite [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6d0aae770b16489518c335b778af6d3a@10.4.119.245' Request 102: Found [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 180 to standard invite [Apr 19 16:09:27] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08610d58 [Apr 19 16:09:27] -- SIP/4321-08610d58 is ringing [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:27] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:27] DEBUG[31086]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6d0aae770b16489518c335b778af6d3a@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 200 to standard invite [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/4321-08610d58 [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:09:27] DEBUG[31064]: chan_sip.c:7992 build_route: build_route: Contact hop: Test [Apr 19 16:09:27] -- Call on SIP/4321-08610d58 left from hold [Apr 19 16:09:27] DEBUG[31084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08610d58 [Apr 19 16:09:27] -- SIP/4321-08610d58 answered SIP/1234-0860bba8 [Apr 19 16:09:27] DEBUG[31084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-0860bba8 [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/1234-0860bba8 [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6430 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:09:27] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:27] DEBUG[31084]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:09:27] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:27] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:09:27] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:09:27] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:09:27] DEBUG[31087]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:27] DEBUG[31088]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:28] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:28] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 50658f93845b2202f9d324879cc6c8f8@10.4.122.235 Their Tag 358f28df897e4e3 Our tag: as3c9cb6dc [Apr 19 16:09:28] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:28] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '50658f93845b2202f9d324879cc6c8f8@10.4.122.235' of Response 804281503: Match Not Found [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/4321-08610d58 [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:13561 handle_request_invite: SIP/4321-08610d58: This call is UP.... [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:6430 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:09:30] DEBUG[31064]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:09:30] -- Started music on hold, class 'default', on SIP/1234-0860bba8 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2020 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 19 16:09:30] SEQNO cycled: 65536 11597 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] DEBUG[31084]: channel.c:2363 __ast_read: Generator got voice, switching to phase locked mode [Apr 19 16:09:30] DEBUG[31084]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:09:30] DEBUG[31084]: channel.c:2876 set_format: Set channel SIP/1234-0860bba8 to write format slin [Apr 19 16:09:30] DEBUG[31084]: res_musiconhold.c:254 ast_moh_files_next: SIP/1234-0860bba8 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix' [Apr 19 16:09:30] DEBUG[31084]: rtp.c:2703 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 19 16:09:30] DEBUG[31084]: rtp.c:2720 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 19 16:09:30] SEQNO cycled: 131072 11598 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 196608 11599 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] DEBUG[31084]: rtp.c:875 ast_rtcp_read: Got RTCP report of 84 bytes [Apr 19 16:09:30] SEQNO cycled: 262144 11600 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:30] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6d0aae770b16489518c335b778af6d3a@10.4.119.245' of Response 842748356: Match Not Found [Apr 19 16:09:30] SEQNO cycled: 327680 11601 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 393216 11602 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 458752 11603 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 524288 11604 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 589824 11605 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 655360 11606 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 720896 11607 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 786432 11608 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 851968 11609 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 917504 11610 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 983040 11611 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1048576 11612 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1114112 11613 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] DEBUG[31084]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:09:30] SEQNO cycled: 1179648 11614 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1245184 11615 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1310720 11616 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1376256 11617 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1441792 11618 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1507328 11619 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1572864 11620 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1638400 11621 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1703936 11622 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1769472 11623 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1835008 11624 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1900544 11625 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 1966080 11626 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 2031616 11627 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:30] SEQNO cycled: 2097152 11628 [Apr 19 16:09:30] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2162688 11629 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2228224 11630 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2293760 11631 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2359296 11632 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2424832 11633 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2490368 11634 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2555904 11635 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2621440 11636 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2686976 11637 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2752512 11638 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2818048 11639 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2883584 11640 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 2949120 11641 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3014656 11642 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3080192 11643 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3145728 11644 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3211264 11645 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3276800 11646 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3342336 11647 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3407872 11648 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3473408 11649 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3538944 11650 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3604480 11651 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3670016 11652 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3735552 11653 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3801088 11654 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3866624 11655 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3932160 11656 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 3997696 11657 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4063232 11658 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4128768 11659 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4194304 11660 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4259840 11661 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4325376 11662 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4390912 11663 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4456448 11664 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4521984 11665 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4587520 11666 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4653056 11667 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4718592 11668 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4784128 11669 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4849664 11670 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4915200 11671 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 4980736 11672 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5046272 11673 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5111808 11674 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5177344 11675 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5242880 11676 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5308416 11677 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:31] SEQNO cycled: 5373952 11678 [Apr 19 16:09:31] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5439488 11679 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5505024 11680 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5570560 11681 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5636096 11682 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5701632 11683 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5767168 11684 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5832704 11685 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5898240 11686 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 5963776 11687 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6029312 11688 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6094848 11689 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6160384 11690 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6225920 11691 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6291456 11692 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6356992 11693 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6422528 11694 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6488064 11695 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6553600 11696 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6619136 11697 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6684672 11698 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6750208 11699 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6815744 11700 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6881280 11701 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 6946816 11702 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7012352 11703 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7077888 11704 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7143424 11705 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7208960 11706 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7274496 11707 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7340032 11708 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7405568 11709 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7471104 11710 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7536640 11711 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7602176 11712 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7667712 11713 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7733248 11714 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7798784 11715 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7864320 11716 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7929856 11717 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 7995392 11718 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8060928 11719 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8126464 11720 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8192000 11721 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8257536 11722 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8323072 11723 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8388608 11724 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8454144 11725 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8519680 11726 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8585216 11727 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:32] SEQNO cycled: 8650752 11728 [Apr 19 16:09:32] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 8716288 11729 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 8781824 11730 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 8847360 11731 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 8912896 11732 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 8978432 11733 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9043968 11734 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9109504 11735 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9175040 11736 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9240576 11737 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9306112 11738 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9371648 11739 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9437184 11740 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9502720 11741 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9568256 11742 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9633792 11743 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9699328 11744 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9764864 11745 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9830400 11746 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9895936 11747 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 9961472 11748 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10027008 11749 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10092544 11750 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10158080 11751 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10223616 11752 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10289152 11753 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10354688 11754 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10420224 11755 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10485760 11756 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10551296 11757 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10616832 11758 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10682368 11759 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10747904 11760 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10813440 11761 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10878976 11762 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 10944512 11763 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11010048 11764 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11075584 11765 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11141120 11766 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11206656 11767 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11272192 11768 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11337728 11769 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11403264 11770 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11468800 11771 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11534336 11772 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11599872 11773 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11665408 11774 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11730944 11775 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11796480 11776 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11862016 11777 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:33] SEQNO cycled: 11927552 11778 [Apr 19 16:09:33] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 11993088 11779 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12058624 11780 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12124160 11781 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12189696 11782 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12255232 11783 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12320768 11784 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12386304 11785 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12451840 11786 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12517376 11787 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12582912 11788 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12648448 11789 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12713984 11790 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12779520 11791 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12845056 11792 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12910592 11793 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 12976128 11794 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13041664 11795 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13107200 11796 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13172736 11797 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13238272 11798 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13303808 11799 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13369344 11800 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13434880 11801 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13500416 11802 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13565952 11803 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13631488 11804 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13697024 11805 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13762560 11806 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13828096 11807 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13893632 11808 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 13959168 11809 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14024704 11810 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14090240 11811 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14155776 11812 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14221312 11813 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14286848 11814 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14352384 11815 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14417920 11816 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14483456 11817 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14548992 11818 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14614528 11819 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14680064 11820 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14745600 11821 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14811136 11822 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14876672 11823 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 14942208 11824 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 15007744 11825 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 15073280 11826 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 15138816 11827 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:34] SEQNO cycled: 15204352 11828 [Apr 19 16:09:34] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15269888 11829 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15335424 11830 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15400960 11831 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15466496 11832 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15532032 11833 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15597568 11834 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15663104 11835 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15728640 11836 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15794176 11837 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15859712 11838 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15925248 11839 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 15990784 11840 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16056320 11841 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16121856 11842 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16187392 11843 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16252928 11844 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16318464 11845 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16384000 11846 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16449536 11847 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16515072 11848 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16580608 11849 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] DEBUG[31084]: rtp.c:875 ast_rtcp_read: Got RTCP report of 84 bytes [Apr 19 16:09:35] SEQNO cycled: 16646144 11850 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16711680 11851 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16777216 11852 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16842752 11853 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16908288 11854 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 16973824 11855 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17039360 11856 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17104896 11857 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17170432 11858 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17235968 11859 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17301504 11860 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17367040 11861 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17432576 11862 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17498112 11863 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17563648 11864 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17629184 11865 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17694720 11866 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17760256 11867 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17825792 11868 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17891328 11869 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 17956864 11870 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18022400 11871 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18087936 11872 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18153472 11873 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18219008 11874 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18284544 11875 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18350080 11876 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18415616 11877 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:35] SEQNO cycled: 18481152 11878 [Apr 19 16:09:35] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18546688 11879 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18612224 11880 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18677760 11881 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18743296 11882 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18808832 11883 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18874368 11884 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 18939904 11885 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19005440 11886 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19070976 11887 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19136512 11888 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19202048 11889 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19267584 11890 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19333120 11891 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19398656 11892 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 50658f93845b2202f9d324879cc6c8f8@10.4.122.235 Their Tag 358f28df897e4e3 Our tag: as3c9cb6dc [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 613babc92668b0e660b5184f1b2fd48e@10.4.119.245 Their Tag ea8124efa2ccbcd Our tag: as0e726e76 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245 Their Tag 8fb122cfafdce6a Our tag: as5c76bf6c [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 Their Tag 0ba9152c0097b33 Our tag: as7b06cd8e [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 Their Tag 8d686d0dc54cec4 Our tag: as2f63b219 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 Their Tag f25462650876ed4 Our tag: as1d1867b2 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 Their Tag 747b475cd2a8318 Our tag: as5c9366e4 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 - INVITE (With RTP) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:13414 handle_request_invite: Checking SIP call limits for device 4321 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:7992 build_route: build_route: Contact hop: Test [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:13488 handle_request_invite: SIP/4321-0861c958: New call is still down.... Trying... [Apr 19 16:09:36] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-0861c958 [Apr 19 16:09:36] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:36] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:36] SEQNO cycled: 19464192 11893 [Apr 19 16:09:36] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] DEBUG[31090]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:36] DEBUG[31089]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 19 16:09:36] -- Executing [5678@default:1] Dial("SIP/4321-0861c958", "SIP/5678|20|") in new stack [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:09:36] DEBUG[31089]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-5678-1. [Apr 19 16:09:36] DEBUG[31089]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 19 16:09:36] DEBUG[31089]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 19 16:09:36] DEBUG[31089]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 19 16:09:36] DEBUG[31089]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:2831 sip_call: Outgoing Call for 5678 [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:09:36] DEBUG[31089]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=35) [Apr 19 16:09:36] DEBUG[31089]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:09:36] -- Called 5678 [Apr 19 16:09:36] SEQNO cycled: 19529728 11894 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19595264 11895 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19660800 11896 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag Our tag: as130b9726 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245' Request 102: Found [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 100 to standard invite [Apr 19 16:09:36] SEQNO cycled: 19726336 11897 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19791872 11898 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19857408 11899 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 19922944 11900 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245' Request 102: Found [Apr 19 16:09:36] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 180 to standard invite [Apr 19 16:09:36] DEBUG[31064]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-08621438 [Apr 19 16:09:36] -- SIP/5678-08621438 is ringing [Apr 19 16:09:36] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:09:36] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:09:36] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:09:36] DEBUG[31091]: app_queue.c:546 changethread: 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 19 16:09:36] SEQNO cycled: 19988480 11901 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20054016 11902 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20119552 11903 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20185088 11904 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20250624 11905 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20316160 11906 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20381696 11907 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20447232 11908 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20512768 11909 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20578304 11910 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20643840 11911 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20709376 11912 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20774912 11913 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20840448 11914 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20905984 11915 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 20971520 11916 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21037056 11917 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21102592 11918 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21168128 11919 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21233664 11920 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21299200 11921 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21364736 11922 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21430272 11923 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21495808 11924 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21561344 11925 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21626880 11926 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21692416 11927 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:36] SEQNO cycled: 21757952 11928 [Apr 19 16:09:36] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 21823488 11929 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 21889024 11930 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 21954560 11931 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22020096 11932 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] DEBUG[31084]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:09:37] SEQNO cycled: 22085632 11933 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22151168 11934 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22216704 11935 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22282240 11936 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22347776 11937 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22413312 11938 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22478848 11939 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22544384 11940 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22609920 11941 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22675456 11942 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22740992 11943 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22806528 11944 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22872064 11945 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 22937600 11946 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23003136 11947 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23068672 11948 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23134208 11949 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23199744 11950 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23265280 11951 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23330816 11952 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23396352 11953 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23461888 11954 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23527424 11955 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23592960 11956 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23658496 11957 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23724032 11958 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23789568 11959 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23855104 11960 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23920640 11961 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 23986176 11962 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24051712 11963 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24117248 11964 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24182784 11965 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24248320 11966 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24313856 11967 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24379392 11968 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24444928 11969 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24510464 11970 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24576000 11971 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24641536 11972 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24707072 11973 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24772608 11974 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24838144 11975 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24903680 11976 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 24969216 11977 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:37] SEQNO cycled: 25034752 11978 [Apr 19 16:09:37] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25100288 11979 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25165824 11980 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25231360 11981 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25296896 11982 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25362432 11983 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25427968 11984 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25493504 11985 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25559040 11986 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25624576 11987 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25690112 11988 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25755648 11989 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25821184 11990 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25886720 11991 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 25952256 11992 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26017792 11993 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26083328 11994 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26148864 11995 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26214400 11996 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26279936 11997 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26345472 11998 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26411008 11999 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26476544 12000 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26542080 12001 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26607616 12002 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26673152 12003 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26738688 12004 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26804224 12005 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26869760 12006 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 26935296 12007 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27000832 12008 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27066368 12009 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27131904 12010 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27197440 12011 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27262976 12012 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27328512 12013 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27394048 12014 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27459584 12015 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27525120 12016 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27590656 12017 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27656192 12018 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27721728 12019 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27787264 12020 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27852800 12021 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27918336 12022 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 27983872 12023 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 28049408 12024 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 28114944 12025 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 28180480 12026 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 28246016 12027 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:38] SEQNO cycled: 28311552 12028 [Apr 19 16:09:38] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28377088 12029 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28442624 12030 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28508160 12031 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28573696 12032 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28639232 12033 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28704768 12034 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28770304 12035 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28835840 12036 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28901376 12037 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 28966912 12038 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29032448 12039 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29097984 12040 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29163520 12041 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29229056 12042 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29294592 12043 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29360128 12044 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29425664 12045 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29491200 12046 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29556736 12047 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29622272 12048 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29687808 12049 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29753344 12050 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29818880 12051 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29884416 12052 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 29949952 12053 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30015488 12054 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30081024 12055 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30146560 12056 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30212096 12057 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30277632 12058 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30343168 12059 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] SEQNO cycled: 30408704 12060 [Apr 19 16:09:39] DEBUG[31084]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received REFER (9) - Command in SIP REFER [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:8724 get_refer_info: Attended transfer: Will use Replace-Call-ID : 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 (No check of from/to tags) [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:8578 get_sip_pvt_byid_locked: Looking for callid 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 (fromtag 23d8249556297b5 totag as7d0cc97c) [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:8602 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 23d8249556297b5 Our tag is as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:13730 local_attended_transfer: SIP attended transfer: Attempting transfer in ringing state [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12748 attempt_transfer: Sip transfer:-------------------- [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12750 attempt_transfer: -- Transferer to PBX channel: SIP/4321-08610d58 State Up [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12754 attempt_transfer: -- Transferer to PBX second channel (target): SIP/4321-0861c958 State Ring [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12758 attempt_transfer: -- Bridged call to transferee: SIP/1234-0860bba8 State Up [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12764 attempt_transfer: -- No target second channel --- [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12765 attempt_transfer: -- END Sip transfer:-------------------- [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12773 attempt_transfer: SIP transfer: Four channels to handle [Apr 19 16:09:39] -- Stopped music on hold on SIP/1234-0860bba8 [Apr 19 16:09:39] DEBUG[31064]: channel.c:2876 set_format: Set channel SIP/1234-0860bba8 to write format ulaw [Apr 19 16:09:39] DEBUG[31064]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12804 attempt_transfer: SIP transfer: trying to masquerade SIP/1234-0860bba8 into SIP/4321-0861c958 [Apr 19 16:09:39] DEBUG[31064]: channel.c:3274 ast_channel_masquerade: Planning to masquerade channel SIP/1234-0860bba8 into the structure of SIP/4321-0861c958 [Apr 19 16:09:39] DEBUG[31064]: channel.c:3288 ast_channel_masquerade: Done planning to masquerade channel SIP/1234-0860bba8 into the structure of SIP/4321-0861c958 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:12809 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:13765 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/4321-0861c958 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31089]: channel.c:3406 ast_do_masquerade: Actually Masquerading SIP/1234-0860bba8(6) into the structure of SIP/4321-0861c958(4) [Apr 19 16:09:39] DEBUG[31089]: channel.c:3418 ast_do_masquerade: Got clone lock for masquerade on 'SIP/1234-0860bba8' at 0x86100a0 [Apr 19 16:09:39] DEBUG[31089]: chan_sip.c:3589 sip_fixup: SIP Fixup: New owner for dialogue 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245: SIP/1234-0860bba8 (Old parent: SIP/1234-0860bba8) [Apr 19 16:09:39] DEBUG[31089]: chan_sip.c:3313 sip_hangup: Hangup call SIP/1234-0860bba8, SIP callid 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245) [Apr 19 16:09:39] DEBUG[31089]: chan_sip.c:3336 sip_hangup: Hanging up channel in state Ring (not UP) [Apr 19 16:09:39] DEBUG[31089]: chan_sip.c:3267 hangup_cause2sip: AST hangup cause 16 (no match found in SIP) [Apr 19 16:09:39] DEBUG[31089]: channel.c:3618 ast_do_masquerade: Putting channel SIP/1234-0860bba8 in 4/4 formats [Apr 19 16:09:39] DEBUG[31089]: chan_sip.c:3589 sip_fixup: SIP Fixup: New owner for dialogue 50658f93845b2202f9d324879cc6c8f8@10.4.122.235: SIP/1234-0860bba8 (Old parent: SIP/4321-0861c958) [Apr 19 16:09:39] DEBUG[31089]: channel.c:3654 ast_do_masquerade: Released clone lock on 'SIP/4321-0861c958' [Apr 19 16:09:39] DEBUG[31089]: channel.c:3664 ast_do_masquerade: Done Masquerading SIP/1234-0860bba8 (6) [Apr 19 16:09:39] DEBUG[31089]: rtp.c:1068 bridge_p2p_rtp_write: RTP Transmission error of packet to 0.0.0.0:0: Invalid argument [Apr 19 16:09:39] DEBUG[31084]: rtp.c:3071 bridge_p2p_loop: Oooh, something is weird, backing out [Apr 19 16:09:39] DEBUG[31084]: channel.c:4065 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/4321-0861c958, c1=SIP/4321-08610d58, flags: Yes,Yes,No,No [Apr 19 16:09:39] DEBUG[31084]: channel.c:4164 ast_channel_bridge: Bridge stops bridging channels SIP/4321-0861c958 and SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/4321-08610d58' [Apr 19 16:09:39] DEBUG[31084]: chan_sip.c:3298 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 6d0aae770b16489518c335b778af6d3a@10.4.119.245. [Apr 19 16:09:39] DEBUG[31084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08610d58 [Apr 19 16:09:39] DEBUG[31084]: rtp.c:1478 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 19 16:09:39] DEBUG[31084]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 19 16:09:39] DEBUG[31084]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,4321,1) exited non-zero on 'SIP/4321-0861c958' [Apr 19 16:09:39] == Spawn extension (default, 4321, 1) exited non-zero on 'SIP/4321-0861c958' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test" <4321>' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321-0861c958' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-08621438' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20|' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:36' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:39' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '3' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013367.0' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test" <4321>' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321-08610d58' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:27' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:27' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:39' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013367.1' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test" <4321>' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/1234-0860bba8' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321-08610d58' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 19 16:09:39] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:39] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:39] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321|20|' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:27' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:27' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:39' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013367.0' [Apr 19 16:09:39] DEBUG[31084]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:39] DEBUG[31084]: channel.c:1721 ast_hangup: Hanging up zombie 'SIP/4321-0861c958' [Apr 19 16:09:39] DEBUG[31084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-0861c958 [Apr 19 16:09:39] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:09:39] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:09:39] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:09:39] DEBUG[31092]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:39] DEBUG[31093]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:39] SEQNO cycled: 30474240 12062 [Apr 19 16:09:39] SEQNO cycled: 30539776 12063 [Apr 19 16:09:39] SEQNO cycled: 30605312 12064 [Apr 19 16:09:39] SEQNO cycled: 30670848 12065 [Apr 19 16:09:39] SEQNO cycled: 30736384 12066 [Apr 19 16:09:39] SEQNO cycled: 30801920 12067 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '6d0aae770b16489518c335b778af6d3a@10.4.119.245' of Request 103: Match Not Found [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6d0aae770b16489518c335b778af6d3a@10.4.119.245 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14263 handle_request_bye: Received bye, no owner, selfdestruct soon. [Apr 19 16:09:39] SEQNO cycled: 30867456 12068 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '5afc9996d2c8951128ff97df9dc8411e@10.4.119.245' of Response 1643854524: Match Not Found [Apr 19 16:09:39] SEQNO cycled: 30932992 12069 [Apr 19 16:09:39] SEQNO cycled: 30998528 12070 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:39] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:39] SEQNO cycled: 31064064 12071 [Apr 19 16:09:39] SEQNO cycled: 31129600 12072 [Apr 19 16:09:39] SEQNO cycled: 31195136 12073 [Apr 19 16:09:39] SEQNO cycled: 31260672 12074 [Apr 19 16:09:39] SEQNO cycled: 31326208 12075 [Apr 19 16:09:39] SEQNO cycled: 31391744 12076 [Apr 19 16:09:39] SEQNO cycled: 31457280 12077 [Apr 19 16:09:39] SEQNO cycled: 31522816 12078 [Apr 19 16:09:40] SEQNO cycled: 31588352 12079 [Apr 19 16:09:40] SEQNO cycled: 31653888 12080 [Apr 19 16:09:40] SEQNO cycled: 31719424 12081 [Apr 19 16:09:40] SEQNO cycled: 31784960 12082 [Apr 19 16:09:40] SEQNO cycled: 31850496 12083 [Apr 19 16:09:40] SEQNO cycled: 31916032 12084 [Apr 19 16:09:40] SEQNO cycled: 31981568 12085 [Apr 19 16:09:40] SEQNO cycled: 32047104 12086 [Apr 19 16:09:40] SEQNO cycled: 32112640 12087 [Apr 19 16:09:40] SEQNO cycled: 32178176 12088 [Apr 19 16:09:40] SEQNO cycled: 32243712 12089 [Apr 19 16:09:40] SEQNO cycled: 32309248 12090 [Apr 19 16:09:40] SEQNO cycled: 32374784 12091 [Apr 19 16:09:40] SEQNO cycled: 32440320 12092 [Apr 19 16:09:40] SEQNO cycled: 32505856 12093 [Apr 19 16:09:40] SEQNO cycled: 32571392 12094 [Apr 19 16:09:40] SEQNO cycled: 32636928 12095 [Apr 19 16:09:40] SEQNO cycled: 32702464 12096 [Apr 19 16:09:40] SEQNO cycled: 32768000 12097 [Apr 19 16:09:40] SEQNO cycled: 32833536 12098 [Apr 19 16:09:40] SEQNO cycled: 32899072 12099 [Apr 19 16:09:40] DEBUG[31089]: rtp.c:875 ast_rtcp_read: Got RTCP report of 84 bytes [Apr 19 16:09:40] SEQNO cycled: 32964608 12100 [Apr 19 16:09:40] SEQNO cycled: 33030144 12101 [Apr 19 16:09:40] SEQNO cycled: 33095680 12102 [Apr 19 16:09:40] SEQNO cycled: 33161216 12103 [Apr 19 16:09:40] SEQNO cycled: 33226752 12104 [Apr 19 16:09:40] SEQNO cycled: 33292288 12105 [Apr 19 16:09:40] SEQNO cycled: 33357824 12106 [Apr 19 16:09:40] SEQNO cycled: 33423360 12107 [Apr 19 16:09:40] SEQNO cycled: 33488896 12108 [Apr 19 16:09:40] SEQNO cycled: 33554432 12109 [Apr 19 16:09:40] SEQNO cycled: 33619968 12110 [Apr 19 16:09:40] SEQNO cycled: 33685504 12111 [Apr 19 16:09:40] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:40] SEQNO cycled: 33751040 12112 [Apr 19 16:09:40] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:40] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:40] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:40] SEQNO cycled: 33816576 12113 [Apr 19 16:09:40] SEQNO cycled: 33882112 12114 [Apr 19 16:09:40] SEQNO cycled: 33947648 12115 [Apr 19 16:09:40] SEQNO cycled: 34013184 12116 [Apr 19 16:09:40] SEQNO cycled: 34078720 12117 [Apr 19 16:09:40] SEQNO cycled: 34144256 12118 [Apr 19 16:09:40] SEQNO cycled: 34209792 12119 [Apr 19 16:09:40] SEQNO cycled: 34275328 12120 [Apr 19 16:09:40] SEQNO cycled: 34340864 12121 [Apr 19 16:09:40] SEQNO cycled: 34406400 12122 [Apr 19 16:09:40] SEQNO cycled: 34471936 12123 [Apr 19 16:09:40] SEQNO cycled: 34537472 12124 [Apr 19 16:09:40] SEQNO cycled: 34603008 12125 [Apr 19 16:09:40] SEQNO cycled: 34668544 12126 [Apr 19 16:09:40] SEQNO cycled: 34734080 12127 [Apr 19 16:09:40] SEQNO cycled: 34799616 12128 [Apr 19 16:09:41] SEQNO cycled: 34865152 12129 [Apr 19 16:09:41] SEQNO cycled: 34930688 12130 [Apr 19 16:09:41] SEQNO cycled: 34996224 12131 [Apr 19 16:09:41] SEQNO cycled: 35061760 12132 [Apr 19 16:09:41] SEQNO cycled: 35127296 12133 [Apr 19 16:09:41] SEQNO cycled: 35192832 12134 [Apr 19 16:09:41] SEQNO cycled: 35258368 12135 [Apr 19 16:09:41] SEQNO cycled: 35323904 12136 [Apr 19 16:09:41] SEQNO cycled: 35389440 12137 [Apr 19 16:09:41] SEQNO cycled: 35454976 12138 [Apr 19 16:09:41] SEQNO cycled: 35520512 12139 [Apr 19 16:09:41] SEQNO cycled: 35586048 12140 [Apr 19 16:09:41] SEQNO cycled: 35651584 12141 [Apr 19 16:09:41] SEQNO cycled: 35717120 12142 [Apr 19 16:09:41] SEQNO cycled: 35782656 12143 [Apr 19 16:09:41] SEQNO cycled: 35848192 12144 [Apr 19 16:09:41] SEQNO cycled: 35913728 12145 [Apr 19 16:09:41] SEQNO cycled: 35979264 12146 [Apr 19 16:09:41] SEQNO cycled: 36044800 12147 [Apr 19 16:09:41] SEQNO cycled: 36110336 12148 [Apr 19 16:09:41] SEQNO cycled: 36175872 12149 [Apr 19 16:09:41] SEQNO cycled: 36241408 12150 [Apr 19 16:09:41] SEQNO cycled: 36306944 12151 [Apr 19 16:09:41] SEQNO cycled: 36372480 12152 [Apr 19 16:09:41] SEQNO cycled: 36438016 12153 [Apr 19 16:09:41] SEQNO cycled: 36503552 12154 [Apr 19 16:09:41] SEQNO cycled: 36569088 12155 [Apr 19 16:09:41] SEQNO cycled: 36634624 12156 [Apr 19 16:09:41] SEQNO cycled: 36700160 12157 [Apr 19 16:09:41] SEQNO cycled: 36765696 12158 [Apr 19 16:09:41] SEQNO cycled: 36831232 12159 [Apr 19 16:09:41] SEQNO cycled: 36896768 12160 [Apr 19 16:09:41] SEQNO cycled: 36962304 12161 [Apr 19 16:09:41] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:41] SEQNO cycled: 37027840 12162 [Apr 19 16:09:41] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:41] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:41] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:41] SEQNO cycled: 37093376 12163 [Apr 19 16:09:41] SEQNO cycled: 37158912 12164 [Apr 19 16:09:41] SEQNO cycled: 37224448 12165 [Apr 19 16:09:41] SEQNO cycled: 37289984 12166 [Apr 19 16:09:41] SEQNO cycled: 37355520 12167 [Apr 19 16:09:41] SEQNO cycled: 37421056 12168 [Apr 19 16:09:41] SEQNO cycled: 37486592 12169 [Apr 19 16:09:41] SEQNO cycled: 37552128 12170 [Apr 19 16:09:41] SEQNO cycled: 37617664 12171 [Apr 19 16:09:41] SEQNO cycled: 37683200 12172 [Apr 19 16:09:41] SEQNO cycled: 37748736 12173 [Apr 19 16:09:41] SEQNO cycled: 37814272 12174 [Apr 19 16:09:41] SEQNO cycled: 37879808 12175 [Apr 19 16:09:41] SEQNO cycled: 37945344 12176 [Apr 19 16:09:41] SEQNO cycled: 38010880 12177 [Apr 19 16:09:41] SEQNO cycled: 38076416 12178 [Apr 19 16:09:42] SEQNO cycled: 38141952 12179 [Apr 19 16:09:42] SEQNO cycled: 38207488 12180 [Apr 19 16:09:42] SEQNO cycled: 38273024 12181 [Apr 19 16:09:42] SEQNO cycled: 38338560 12182 [Apr 19 16:09:42] SEQNO cycled: 38404096 12183 [Apr 19 16:09:42] SEQNO cycled: 38469632 12184 [Apr 19 16:09:42] SEQNO cycled: 38535168 12185 [Apr 19 16:09:42] SEQNO cycled: 38600704 12186 [Apr 19 16:09:42] SEQNO cycled: 38666240 12187 [Apr 19 16:09:42] SEQNO cycled: 38731776 12188 [Apr 19 16:09:42] SEQNO cycled: 38797312 12189 [Apr 19 16:09:42] SEQNO cycled: 38862848 12190 [Apr 19 16:09:42] SEQNO cycled: 38928384 12191 [Apr 19 16:09:42] SEQNO cycled: 38993920 12192 [Apr 19 16:09:42] SEQNO cycled: 39059456 12193 [Apr 19 16:09:42] SEQNO cycled: 39124992 12194 [Apr 19 16:09:42] SEQNO cycled: 39190528 12195 [Apr 19 16:09:42] SEQNO cycled: 39256064 12196 [Apr 19 16:09:42] SEQNO cycled: 39321600 12197 [Apr 19 16:09:42] SEQNO cycled: 39387136 12198 [Apr 19 16:09:42] SEQNO cycled: 39452672 12199 [Apr 19 16:09:42] SEQNO cycled: 39518208 12200 [Apr 19 16:09:42] SEQNO cycled: 39583744 12201 [Apr 19 16:09:42] SEQNO cycled: 39649280 12202 [Apr 19 16:09:42] SEQNO cycled: 39714816 12203 [Apr 19 16:09:42] SEQNO cycled: 39780352 12204 [Apr 19 16:09:42] SEQNO cycled: 39845888 12205 [Apr 19 16:09:42] SEQNO cycled: 39911424 12206 [Apr 19 16:09:42] SEQNO cycled: 39976960 12207 [Apr 19 16:09:42] SEQNO cycled: 40042496 12208 [Apr 19 16:09:42] SEQNO cycled: 40108032 12209 [Apr 19 16:09:42] SEQNO cycled: 40173568 12210 [Apr 19 16:09:42] SEQNO cycled: 40239104 12211 [Apr 19 16:09:42] SEQNO cycled: 40304640 12212 [Apr 19 16:09:42] SEQNO cycled: 40370176 12213 [Apr 19 16:09:42] SEQNO cycled: 40435712 12214 [Apr 19 16:09:42] SEQNO cycled: 40501248 12215 [Apr 19 16:09:42] SEQNO cycled: 40566784 12216 [Apr 19 16:09:42] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '66c6d98114c63c36f8c16ff7614947c3@10.4.122.235' [Apr 19 16:09:42] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 66c6d98114c63c36f8c16ff7614947c3@10.4.122.235 [Apr 19 16:09:42] Really destroying SIP dialog '66c6d98114c63c36f8c16ff7614947c3@10.4.122.235' Method: REGISTER [Apr 19 16:09:42] SEQNO cycled: 40632320 12217 [Apr 19 16:09:42] SEQNO cycled: 40697856 12218 [Apr 19 16:09:42] SEQNO cycled: 40763392 12219 [Apr 19 16:09:42] SEQNO cycled: 40828928 12220 [Apr 19 16:09:42] SEQNO cycled: 40894464 12221 [Apr 19 16:09:42] SEQNO cycled: 40960000 12222 [Apr 19 16:09:42] SEQNO cycled: 41025536 12223 [Apr 19 16:09:42] SEQNO cycled: 41091072 12224 [Apr 19 16:09:42] SEQNO cycled: 41156608 12225 [Apr 19 16:09:42] SEQNO cycled: 41222144 12226 [Apr 19 16:09:42] SEQNO cycled: 41287680 12227 [Apr 19 16:09:42] SEQNO cycled: 41353216 12228 [Apr 19 16:09:43] SEQNO cycled: 41418752 12229 [Apr 19 16:09:43] SEQNO cycled: 41484288 12230 [Apr 19 16:09:43] SEQNO cycled: 41549824 12231 [Apr 19 16:09:43] SEQNO cycled: 41615360 12232 [Apr 19 16:09:43] SEQNO cycled: 41680896 12233 [Apr 19 16:09:43] SEQNO cycled: 41746432 12234 [Apr 19 16:09:43] SEQNO cycled: 41811968 12235 [Apr 19 16:09:43] SEQNO cycled: 41877504 12236 [Apr 19 16:09:43] SEQNO cycled: 41943040 12237 [Apr 19 16:09:43] SEQNO cycled: 42008576 12238 [Apr 19 16:09:43] SEQNO cycled: 42074112 12239 [Apr 19 16:09:43] SEQNO cycled: 42139648 12240 [Apr 19 16:09:43] SEQNO cycled: 42205184 12241 [Apr 19 16:09:43] SEQNO cycled: 42270720 12242 [Apr 19 16:09:43] SEQNO cycled: 42336256 12243 [Apr 19 16:09:43] SEQNO cycled: 42401792 12244 [Apr 19 16:09:43] SEQNO cycled: 42467328 12245 [Apr 19 16:09:43] SEQNO cycled: 42532864 12246 [Apr 19 16:09:43] SEQNO cycled: 42598400 12247 [Apr 19 16:09:43] SEQNO cycled: 42663936 12248 [Apr 19 16:09:43] SEQNO cycled: 42729472 12249 [Apr 19 16:09:43] SEQNO cycled: 42795008 12250 [Apr 19 16:09:43] SEQNO cycled: 42860544 12251 [Apr 19 16:09:43] SEQNO cycled: 42926080 12252 [Apr 19 16:09:43] SEQNO cycled: 42991616 12253 [Apr 19 16:09:43] SEQNO cycled: 43057152 12254 [Apr 19 16:09:43] SEQNO cycled: 43122688 12255 [Apr 19 16:09:43] SEQNO cycled: 43188224 12256 [Apr 19 16:09:43] SEQNO cycled: 43253760 12257 [Apr 19 16:09:43] SEQNO cycled: 43319296 12258 [Apr 19 16:09:43] SEQNO cycled: 43384832 12259 [Apr 19 16:09:43] SEQNO cycled: 43450368 12260 [Apr 19 16:09:43] SEQNO cycled: 43515904 12261 [Apr 19 16:09:43] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:43] SEQNO cycled: 43581440 12262 [Apr 19 16:09:43] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:43] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:43] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:43] SEQNO cycled: 43646976 12263 [Apr 19 16:09:43] SEQNO cycled: 43712512 12264 [Apr 19 16:09:43] SEQNO cycled: 43778048 12265 [Apr 19 16:09:43] SEQNO cycled: 43843584 12266 [Apr 19 16:09:43] SEQNO cycled: 43909120 12267 [Apr 19 16:09:43] SEQNO cycled: 43974656 12268 [Apr 19 16:09:43] SEQNO cycled: 44040192 12269 [Apr 19 16:09:43] SEQNO cycled: 44105728 12270 [Apr 19 16:09:43] SEQNO cycled: 44171264 12271 [Apr 19 16:09:43] SEQNO cycled: 44236800 12272 [Apr 19 16:09:43] SEQNO cycled: 44302336 12273 [Apr 19 16:09:43] SEQNO cycled: 44367872 12274 [Apr 19 16:09:43] SEQNO cycled: 44433408 12275 [Apr 19 16:09:43] SEQNO cycled: 44498944 12276 [Apr 19 16:09:43] SEQNO cycled: 44564480 12277 [Apr 19 16:09:43] SEQNO cycled: 44630016 12278 [Apr 19 16:09:44] SEQNO cycled: 44695552 12279 [Apr 19 16:09:44] SEQNO cycled: 44761088 12280 [Apr 19 16:09:44] SEQNO cycled: 44826624 12281 [Apr 19 16:09:44] SEQNO cycled: 44892160 12282 [Apr 19 16:09:44] SEQNO cycled: 44957696 12283 [Apr 19 16:09:44] SEQNO cycled: 45023232 12284 [Apr 19 16:09:44] SEQNO cycled: 45088768 12285 [Apr 19 16:09:44] SEQNO cycled: 45154304 12286 [Apr 19 16:09:44] SEQNO cycled: 45219840 12287 [Apr 19 16:09:44] SEQNO cycled: 45285376 12288 [Apr 19 16:09:44] SEQNO cycled: 45350912 12289 [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:11654 handle_response_invite: SIP response 200 to standard invite [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/5678-08621438 [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:09:44] DEBUG[31064]: chan_sip.c:7992 build_route: build_route: Contact hop: Test 3 [Apr 19 16:09:44] -- Call on SIP/5678-08621438 left from hold [Apr 19 16:09:44] DEBUG[31089]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-08621438 [Apr 19 16:09:44] -- SIP/5678-08621438 answered SIP/1234-0860bba8 [Apr 19 16:09:44] -- Packet2Packet bridging SIP/1234-0860bba8 and SIP/5678-08621438 [Apr 19 16:09:44] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:09:44] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:09:44] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:09:44] DEBUG[31094]: app_queue.c:546 changethread: 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 19 16:09:45] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245' [Apr 19 16:09:45] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245 [Apr 19 16:09:45] Really destroying SIP dialog '0617b0d3eb603e9c4d3bb7dbc1abca83@10.4.119.245' Method: REGISTER [Apr 19 16:09:45] DEBUG[31089]: rtp.c:875 ast_rtcp_read: Got RTCP report of 84 bytes [Apr 19 16:09:45] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '408611b50f2869c76cf5b12a75cf8498@10.4.119.245' [Apr 19 16:09:45] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 408611b50f2869c76cf5b12a75cf8498@10.4.119.245 [Apr 19 16:09:45] Really destroying SIP dialog '408611b50f2869c76cf5b12a75cf8498@10.4.119.245' Method: REGISTER [Apr 19 16:09:46] DEBUG[31089]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog 'ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245' [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245 [Apr 19 16:09:46] Really destroying SIP dialog 'ae7c0f20821bbdd4c0ecaee77ede898f@10.4.119.245' Method: REGISTER [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245' [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245 [Apr 19 16:09:46] Really destroying SIP dialog '8bf7a2ad0c36085f6381a3c291b5913d@10.4.119.245' Method: REGISTER [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog '613babc92668b0e660b5184f1b2fd48e@10.4.119.245' [Apr 19 16:09:46] DEBUG[31064]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog 613babc92668b0e660b5184f1b2fd48e@10.4.119.245 [Apr 19 16:09:46] Really destroying SIP dialog '613babc92668b0e660b5184f1b2fd48e@10.4.119.245' Method: REGISTER [Apr 19 16:09:47] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:47] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:47] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:47] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:14259 handle_request_bye: Received bye, issuing owner hangup [Apr 19 16:09:49] DEBUG[31089]: rtp.c:3102 bridge_p2p_loop: Oooh, got a hangup [Apr 19 16:09:49] DEBUG[31089]: channel.c:4094 ast_channel_bridge: Returning from native bridge, channels: SIP/1234-0860bba8, SIP/5678-08621438 [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 's' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-08621438' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/1234-0860bba8' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:36' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:44' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:09:49' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '13' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '5' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013376.3' [Apr 19 16:09:49] DEBUG[31089]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:09:49] DEBUG[31089]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/5678-08621438' [Apr 19 16:09:49] DEBUG[31089]: chan_sip.c:3313 sip_hangup: Hangup call SIP/5678-08621438, SIP callid 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245) [Apr 19 16:09:49] DEBUG[31089]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-08621438 [Apr 19 16:09:49] DEBUG[31089]: rtp.c:1478 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 19 16:09:49] DEBUG[31089]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 19 16:09:49] DEBUG[31089]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,5678,1) exited non-zero on 'SIP/1234-0860bba8' [Apr 19 16:09:49] == Spawn extension (default, 5678, 1) exited non-zero on 'SIP/1234-0860bba8' [Apr 19 16:09:49] DEBUG[31089]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/1234-0860bba8' [Apr 19 16:09:49] DEBUG[31089]: chan_sip.c:3313 sip_hangup: Hangup call SIP/1234-0860bba8, SIP callid 50658f93845b2202f9d324879cc6c8f8@10.4.122.235) [Apr 19 16:09:49] DEBUG[31089]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-0860bba8 [Apr 19 16:09:49] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:09:49] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:09:49] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:09:49] DEBUG[31054]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:09:49] DEBUG[31054]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:09:49] DEBUG[31054]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:09:49] DEBUG[31095]: app_queue.c:546 changethread: 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 19 16:09:49] DEBUG[31096]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245 Their Tag e8cd5f1bf72e5e6 Our tag: as130b9726 [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:4365 find_call: = No match Their Call ID: 6d0aae770b16489518c335b778af6d3a@10.4.119.245 Their Tag fb77ce65f40d21f Our tag: as63d8c110 [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 50658f93845b2202f9d324879cc6c8f8@10.4.122.235 Their Tag 358f28df897e4e3 Our tag: as3c9cb6dc [Apr 19 16:09:49] DEBUG[31064]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '50658f93845b2202f9d324879cc6c8f8@10.4.122.235' of Request 102: Match Not Found [Apr 19 16:09:49] Really destroying SIP dialog '5a304bad5a54d59d1b80be643fe7cff1@10.4.119.245' Method: BYE [Apr 19 16:09:49] Really destroying SIP dialog '50658f93845b2202f9d324879cc6c8f8@10.4.122.235' Method: ACK [Apr 19 16:09:51] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:51] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:51] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:09:55] DEBUG[31064]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #50)) [Apr 19 16:09:55] DEBUG[31064]: chan_sip.c:4365 find_call: = Found Their Call ID: 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 Their Tag 23d8249556297b5 Our tag: as7d0cc97c [Apr 19 16:09:55] DEBUG[31064]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK sopt[Apr 19 16:09:59] WARNING[31064]: chan_sip.c:1900 retrans_pkt: Maximum retries exceeded on transmission 5afc9996d2c8951128ff97df9dc8411e@10.4.119.245 for seqno 1643854524 (Critical Response) [Apr 19 16:09:59] Really destroying SIP dialog '5afc9996d2c8951128ff97df9dc8411e@10.4.119.245' Method: ACK now No such command 'sopt now' (type 'help' for help) *CLI> stop now [Apr 19 16:10:04] Beginning asterisk shutdown.... [Apr 19 16:10:04] Executing last minute cleanups [Apr 19 16:10:04] == Destroying musiconhold processes [Apr 19 16:10:04] Asterisk cleanly ending (0). [Apr 19 16:10:04] DEBUG[31048]: asterisk.c:1274 quit_handler: Asterisk ending (0).