[Apr 19 16:13:29] Asterisk SVN-branch-1.4-r61686, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Apr 19 16:13:29] Created by Mark Spencer [Apr 19 16:13:29] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Apr 19 16:13:29] This is free software, with components licensed under the GNU General Public [Apr 19 16:13:29] License version 2 and other licenses; you are welcome to redistribute it under [Apr 19 16:13:29] certain conditions. Type 'core show license' for details. [Apr 19 16:13:29] ========================================================================= [Apr 19 16:13:30] Asterisk Ready. [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for ca538dcd56cba534040c3ac853313042@10.4.119.245 - INVITE (With RTP) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:13414 handle_request_invite: Checking SIP call limits for device 4321 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:7992 build_route: build_route: Contact hop: Test [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:13488 handle_request_invite: SIP/4321-09e13b78: New call is still down.... Trying... [Apr 19 16:13:37] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-09e13b78 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:13:37] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:13:37] DEBUG[31280]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 19 16:13:37] -- Executing [1234@default:1] Dial("SIP/4321-09e13b78", "SIP/1234|20|") in new stack [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:13:37] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-1234-1. [Apr 19 16:13:37] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 19 16:13:37] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 19 16:13:37] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 19 16:13:37] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:2831 sip_call: Outgoing Call for 1234 [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:13:37] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:13:37] -- Called 1234 [Apr 19 16:13:37] DEBUG[31281]: 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:13:37] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag Our tag: as3c4f9343 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '75e041226d82fb75624cc7400562abd2@10.4.119.245' Request 102: Found [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 100 to standard invite [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '75e041226d82fb75624cc7400562abd2@10.4.119.245' Request 102: Found [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 180 to standard invite [Apr 19 16:13:37] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-09e18db8 [Apr 19 16:13:37] -- SIP/1234-09e18db8 is ringing [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:13:37] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:13:37] DEBUG[31282]: 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:13:37] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '75e041226d82fb75624cc7400562abd2@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 200 to standard invite [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/1234-09e18db8 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:7992 build_route: build_route: Contact hop: [Apr 19 16:13:37] -- Call on SIP/1234-09e18db8 left from hold [Apr 19 16:13:37] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-09e18db8 [Apr 19 16:13:37] -- SIP/1234-09e18db8 answered SIP/4321-09e13b78 [Apr 19 16:13:37] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-09e13b78 [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/4321-09e13b78 [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6430 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:13:37] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:37] DEBUG[31280]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:13:37] -- Packet2Packet bridging SIP/4321-09e13b78 and SIP/1234-09e18db8 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:13:37] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:13:37] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:13:37] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:13:37] DEBUG[31283]: 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:13:37] DEBUG[31284]: 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:13:37] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: ca538dcd56cba534040c3ac853313042@10.4.119.245 Their Tag bd8350b9765cb33 Our tag: as48f1cf20 [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:13:37] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'ca538dcd56cba534040c3ac853313042@10.4.119.245' of Response 237943943: Match Not Found [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/1234-09e18db8 [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:13561 handle_request_invite: SIP/1234-09e18db8: This call is UP.... [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:6430 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:13:39] DEBUG[31263]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:13:39] -- Started music on hold, class 'default', on SIP/4321-09e13b78 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 19 16:13:39] SEQNO cycled: 65536 38336 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] DEBUG[31280]: channel.c:2363 __ast_read: Generator got voice, switching to phase locked mode [Apr 19 16:13:39] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:13:39] DEBUG[31280]: channel.c:2876 set_format: Set channel SIP/4321-09e13b78 to write format slin [Apr 19 16:13:39] DEBUG[31280]: res_musiconhold.c:254 ast_moh_files_next: SIP/4321-09e13b78 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix' [Apr 19 16:13:39] DEBUG[31280]: rtp.c:2703 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 19 16:13:39] DEBUG[31280]: rtp.c:2720 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 19 16:13:39] SEQNO cycled: 131072 38337 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 196608 38338 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 262144 38339 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 327680 38340 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 393216 38341 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 458752 38342 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 524288 38343 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 589824 38344 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 655360 38345 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 720896 38346 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:13:39] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '75e041226d82fb75624cc7400562abd2@10.4.119.245' of Response 786349952: Match Not Found [Apr 19 16:13:39] SEQNO cycled: 786432 38347 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:39] SEQNO cycled: 851968 38348 [Apr 19 16:13:39] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 917504 38349 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 983040 38350 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1048576 38351 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1114112 38352 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1179648 38353 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1245184 38354 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1310720 38355 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1376256 38356 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1441792 38357 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1507328 38358 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1572864 38359 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1638400 38360 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1703936 38361 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1769472 38362 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1835008 38363 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1900544 38364 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 1966080 38365 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2031616 38366 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2097152 38367 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2162688 38368 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2228224 38369 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2293760 38370 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2359296 38371 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2424832 38372 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2490368 38373 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2555904 38374 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2621440 38375 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2686976 38376 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2752512 38377 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2818048 38378 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2883584 38379 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 2949120 38380 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3014656 38381 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3080192 38382 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3145728 38383 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3211264 38384 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3276800 38385 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3342336 38386 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3407872 38387 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3473408 38388 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3538944 38389 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3604480 38390 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3670016 38391 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3735552 38392 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3801088 38393 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3866624 38394 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3932160 38395 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 3997696 38396 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 4063232 38397 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:40] SEQNO cycled: 4128768 38398 [Apr 19 16:13:40] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4194304 38399 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4259840 38400 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4325376 38401 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4390912 38402 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4456448 38403 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4521984 38404 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4587520 38405 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4653056 38406 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4718592 38407 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4784128 38408 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4849664 38409 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4915200 38410 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 4980736 38411 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5046272 38412 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5111808 38413 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5177344 38414 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5242880 38415 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5308416 38416 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5373952 38417 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5439488 38418 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5505024 38419 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5570560 38420 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5636096 38421 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5701632 38422 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5767168 38423 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5832704 38424 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5898240 38425 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 5963776 38426 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6029312 38427 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6094848 38428 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6160384 38429 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6225920 38430 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6291456 38431 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6356992 38432 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6422528 38433 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6488064 38434 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6553600 38435 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6619136 38436 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6684672 38437 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6750208 38438 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6815744 38439 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6881280 38440 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 6946816 38441 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7012352 38442 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7077888 38443 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7143424 38444 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7208960 38445 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7274496 38446 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7340032 38447 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:41] SEQNO cycled: 7405568 38448 [Apr 19 16:13:41] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7471104 38449 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7536640 38450 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7602176 38451 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7667712 38452 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7733248 38453 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7798784 38454 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7864320 38455 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7929856 38456 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 7995392 38457 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8060928 38458 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8126464 38459 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8192000 38460 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8257536 38461 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8323072 38462 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] DEBUG[31280]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:13:42] SEQNO cycled: 8388608 38463 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8454144 38464 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8519680 38465 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8585216 38466 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8650752 38467 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: ca538dcd56cba534040c3ac853313042@10.4.119.245 Their Tag bd8350b9765cb33 Our tag: as48f1cf20 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235 - INVITE (With RTP) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:13414 handle_request_invite: Checking SIP call limits for device 1234 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:7992 build_route: build_route: Contact hop: Test 2 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:13488 handle_request_invite: SIP/1234-09e249b0: New call is still down.... Trying... [Apr 19 16:13:42] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-09e249b0 [Apr 19 16:13:42] SEQNO cycled: 8716288 38468 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:13:42] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:13:42] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:13:42] DEBUG[31285]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 19 16:13:42] -- Executing [5678@default:1] Dial("SIP/1234-09e249b0", "SIP/5678|20|") in new stack [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:13:42] DEBUG[31285]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-5678-1. [Apr 19 16:13:42] DEBUG[31285]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 19 16:13:42] DEBUG[31285]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 19 16:13:42] DEBUG[31285]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 19 16:13:42] DEBUG[31285]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:2831 sip_call: Outgoing Call for 5678 [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:13:42] DEBUG[31285]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=35) [Apr 19 16:13:42] DEBUG[31285]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:13:42] -- Called 5678 [Apr 19 16:13:42] DEBUG[31286]: 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:13:42] SEQNO cycled: 8781824 38469 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8847360 38470 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 8912896 38471 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag Our tag: as5cc423e4 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '41b288a63e974460171876cc741e6d44@10.4.119.245' Request 102: Found [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 100 to standard invite [Apr 19 16:13:42] SEQNO cycled: 8978432 38472 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9043968 38473 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9109504 38474 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9175040 38475 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '41b288a63e974460171876cc741e6d44@10.4.119.245' Request 102: Found [Apr 19 16:13:42] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 180 to standard invite [Apr 19 16:13:42] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-09e295f0 [Apr 19 16:13:42] -- SIP/5678-09e295f0 is ringing [Apr 19 16:13:42] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:42] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:42] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:42] DEBUG[31287]: 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:13:42] SEQNO cycled: 9240576 38477 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9306112 38478 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9371648 38479 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9437184 38480 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9502720 38481 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9568256 38482 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9633792 38483 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9699328 38484 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9764864 38485 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9830400 38486 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9895936 38487 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 9961472 38488 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10027008 38489 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10092544 38490 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10158080 38491 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10223616 38492 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10289152 38493 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10354688 38494 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10420224 38495 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10485760 38496 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10551296 38497 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:42] SEQNO cycled: 10616832 38498 [Apr 19 16:13:42] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 10682368 38499 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 10747904 38500 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 10813440 38501 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 10878976 38502 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 10944512 38503 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11010048 38504 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11075584 38505 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11141120 38506 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11206656 38507 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11272192 38508 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11337728 38509 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11403264 38510 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11468800 38511 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11534336 38512 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11599872 38513 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11665408 38514 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11730944 38515 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11796480 38516 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11862016 38517 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11927552 38518 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 11993088 38519 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12058624 38520 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12124160 38521 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12189696 38522 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12255232 38523 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12320768 38524 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12386304 38525 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12451840 38526 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12517376 38527 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12582912 38528 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12648448 38529 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12713984 38530 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12779520 38531 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12845056 38532 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12910592 38533 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 12976128 38534 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13041664 38535 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13107200 38536 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13172736 38537 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13238272 38538 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13303808 38539 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13369344 38540 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13434880 38541 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13500416 38542 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13565952 38543 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13631488 38544 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13697024 38545 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13762560 38546 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13828096 38547 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:43] SEQNO cycled: 13893632 38548 [Apr 19 16:13:43] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 13959168 38549 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14024704 38550 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14090240 38551 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14155776 38552 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14221312 38553 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14286848 38554 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14352384 38555 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14417920 38556 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14483456 38557 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 14548992 38558 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235 Their Tag 4a7df86230920d9 Our tag: as4c45d0ac [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235 [Apr 19 16:13:44] DEBUG[31285]: rtp.c:1478 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 's' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-09e295f0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:42' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:44' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013622.3' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/5678-09e295f0' [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:3313 sip_hangup: Hangup call SIP/5678-09e295f0, SIP callid 41b288a63e974460171876cc741e6d44@10.4.119.245) [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:3336 sip_hangup: Hanging up channel in state Ringing (not UP) [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '41b288a63e974460171876cc741e6d44@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:44] DEBUG[31285]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-09e295f0 [Apr 19 16:13:44] DEBUG[31285]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Apr 19 16:13:44] DEBUG[31285]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,5678,1) exited non-zero on 'SIP/1234-09e249b0' [Apr 19 16:13:44] == Spawn extension (default, 5678, 1) exited non-zero on 'SIP/1234-09e249b0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test 2" <1234>' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1234' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '5678' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/1234-09e249b0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-09e295f0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20|' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:42' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:44' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013622.2' [Apr 19 16:13:44] DEBUG[31285]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:44] DEBUG[31285]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/1234-09e249b0' [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:3313 sip_hangup: Hangup call SIP/1234-09e249b0, SIP callid 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235) [Apr 19 16:13:44] DEBUG[31285]: chan_sip.c:3336 sip_hangup: Hanging up channel in state Ring (not UP) [Apr 19 16:13:44] DEBUG[31285]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-09e249b0 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:44] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:13:44] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:13:44] DEBUG[31288]: 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:13:44] DEBUG[31289]: 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:13:44] SEQNO cycled: 14614528 38559 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235 Their Tag 4a7df86230920d9 Our tag: as4c45d0ac [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received REFER (9) - Command in SIP REFER [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14020 handle_request_refer: chan1->name: SIP/1234-09e18db8 [Apr 19 16:13:44] DEBUG[31263]: channel.c:1503 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/4321-09e13b78' [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14083 handle_request_refer: Blind transfer succeeded. Telling transferer. [Apr 19 16:13:44] -- Stopped music on hold on SIP/4321-09e13b78 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2876 set_format: Set channel SIP/4321-09e13b78 to write format ulaw [Apr 19 16:13:44] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:13:44] DEBUG[31280]: rtp.c:3102 bridge_p2p_loop: Oooh, got a hangup [Apr 19 16:13:44] DEBUG[31280]: channel.c:4094 ast_channel_bridge: Returning from native bridge, channels: SIP/4321-09e13b78, SIP/1234-09e18db8 [Apr 19 16:13:44] DEBUG[31280]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/1234-09e18db8' [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3298 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 75e041226d82fb75624cc7400562abd2@10.4.119.245. [Apr 19 16:13:44] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-09e18db8 [Apr 19 16:13:44] DEBUG[31280]: rtp.c:1478 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 19 16:13:44] DEBUG[31280]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 19 16:13:44] DEBUG[31280]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,5678,0) exited non-zero on 'SIP/4321-09e13b78' [Apr 19 16:13:44] == Spawn extension (default, 5678, 0) exited non-zero on 'SIP/4321-09e13b78' [Apr 19 16:13:44] DEBUG[31280]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 19 16:13:44] -- Executing [5678@default:1] Dial("SIP/4321-09e13b78", "SIP/5678|20|") in new stack [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:15383 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-5678-1. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3328 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER_REFERER. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3328 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable BLINDTRANSFER. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable BRIDGEPEER. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable STACK-default-1234-1. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 19 16:13:44] DEBUG[31280]: channel.c:3341 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:2831 sip_call: Outgoing Call for 5678 [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:6198 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) [Apr 19 16:13:44] DEBUG[31280]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 19 16:13:44] -- Called 5678 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Apr 19 16:13:44] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 1234 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Apr 19 16:13:44] DEBUG[31290]: 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:13:44] SEQNO cycled: 14680064 38560 [Apr 19 16:13:44] SEQNO cycled: 14745600 38561 [Apr 19 16:13:44] SEQNO cycled: 14811136 38562 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '41b288a63e974460171876cc741e6d44@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '41b288a63e974460171876cc741e6d44@10.4.119.245' of Request 102: Match Found [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 487 to standard invite [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:44] SEQNO cycled: 14876672 38563 [Apr 19 16:13:44] SEQNO cycled: 14942208 38564 [Apr 19 16:13:44] SEQNO cycled: 15007744 38565 [Apr 19 16:13:44] SEQNO cycled: 15073280 38566 [Apr 19 16:13:44] SEQNO cycled: 15138816 38567 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245' Request 102: Found [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 100 to standard invite [Apr 19 16:13:44] SEQNO cycled: 15204352 38568 [Apr 19 16:13:44] SEQNO cycled: 15269888 38569 [Apr 19 16:13:44] SEQNO cycled: 15335424 38571 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245' Request 102: Found [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 180 to standard invite [Apr 19 16:13:44] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-09e1e818 [Apr 19 16:13:44] -- SIP/5678-09e1e818 is ringing [Apr 19 16:13:44] DEBUG[31280]: channel.c:2466 ast_indicate_data: Driver for channel 'SIP/4321-09e13b78' does not support indication 3, emulating it [Apr 19 16:13:44] DEBUG[31280]: channel.c:2876 set_format: Set channel SIP/4321-09e13b78 to write format slin [Apr 19 16:13:44] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:44] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:44] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:44] DEBUG[31291]: 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:13:44] SEQNO cycled: 15400960 38572 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] DEBUG[31280]: channel.c:2363 __ast_read: Generator got voice, switching to phase locked mode [Apr 19 16:13:44] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:13:44] DEBUG[31280]: rtp.c:2573 ast_rtp_raw_write: Difference is 1920, ms is 260 [Apr 19 16:13:44] SEQNO cycled: 15466496 38573 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15532032 38574 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 602571d6e3dc300d9ff3f05ed80df563@10.4.122.235 Their Tag 4a7df86230920d9 Our tag: as4c45d0ac [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '602571d6e3dc300d9ff3f05ed80df563@10.4.122.235' of Response 1893782250: Match Not Found [Apr 19 16:13:44] Really destroying SIP dialog '602571d6e3dc300d9ff3f05ed80df563@10.4.122.235' Method: ACK [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '75e041226d82fb75624cc7400562abd2@10.4.119.245' of Request 104: Match Not Found [Apr 19 16:13:44] SEQNO cycled: 15597568 38575 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 75e041226d82fb75624cc7400562abd2@10.4.119.245 [Apr 19 16:13:44] DEBUG[31263]: chan_sip.c:14263 handle_request_bye: Received bye, no owner, selfdestruct soon. [Apr 19 16:13:44] SEQNO cycled: 15663104 38576 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15728640 38577 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15794176 38578 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15859712 38579 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15925248 38580 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 15990784 38581 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16056320 38582 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16121856 38583 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16187392 38584 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16252928 38585 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16318464 38586 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16384000 38587 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16449536 38588 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16515072 38589 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16580608 38590 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16646144 38591 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16711680 38592 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16777216 38593 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16842752 38594 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16908288 38595 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 16973824 38596 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 17039360 38597 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:44] SEQNO cycled: 17104896 38598 [Apr 19 16:13:44] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17170432 38599 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17235968 38600 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17301504 38601 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17367040 38602 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17432576 38603 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17498112 38604 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17563648 38605 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17629184 38606 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17694720 38607 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17760256 38608 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 17825792 38609 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:13:45] SEQNO cycled: 17891328 38610 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:45] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:45] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:45] SEQNO cycled: 17956864 38611 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18022400 38612 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18087936 38613 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18153472 38614 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18219008 38615 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18284544 38616 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18350080 38617 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18415616 38618 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18481152 38619 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18546688 38620 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18612224 38621 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18677760 38622 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18743296 38623 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18808832 38624 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18874368 38625 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 18939904 38626 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19005440 38627 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19070976 38628 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19136512 38629 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19202048 38630 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19267584 38631 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19333120 38632 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19398656 38633 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19464192 38634 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19529728 38635 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19595264 38636 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19660800 38637 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19726336 38638 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19791872 38639 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] DEBUG[31280]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:13:45] SEQNO cycled: 19857408 38640 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19922944 38641 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 19988480 38642 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20054016 38643 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20119552 38644 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20185088 38645 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20250624 38646 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20316160 38647 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:45] SEQNO cycled: 20381696 38648 [Apr 19 16:13:45] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20447232 38649 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20512768 38650 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20578304 38651 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20643840 38652 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20709376 38653 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20774912 38654 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20840448 38655 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20905984 38656 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 20971520 38657 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21037056 38658 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21102592 38659 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:13:46] SEQNO cycled: 21168128 38660 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:46] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:46] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:46] SEQNO cycled: 21233664 38661 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21299200 38662 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21364736 38663 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21430272 38664 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21495808 38665 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21561344 38666 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21626880 38667 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21692416 38668 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21757952 38669 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21823488 38670 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21889024 38671 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 21954560 38672 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22020096 38673 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22085632 38674 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22151168 38675 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22216704 38676 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22282240 38677 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22347776 38678 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22413312 38679 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22478848 38680 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22544384 38681 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22609920 38682 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22675456 38683 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22740992 38684 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22806528 38685 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22872064 38686 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 22937600 38687 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23003136 38688 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23068672 38689 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23134208 38690 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23199744 38691 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23265280 38692 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23330816 38693 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23396352 38694 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23461888 38695 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23527424 38696 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23592960 38697 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:46] SEQNO cycled: 23658496 38698 [Apr 19 16:13:46] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 23724032 38699 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 23789568 38700 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 23855104 38701 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 23920640 38702 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 23986176 38703 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24051712 38704 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24117248 38705 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24182784 38706 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24248320 38707 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24313856 38708 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24379392 38709 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24444928 38710 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24510464 38711 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24576000 38712 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24641536 38713 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24707072 38714 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24772608 38715 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24838144 38716 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24903680 38717 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 24969216 38718 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25034752 38719 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25100288 38720 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25165824 38721 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25231360 38722 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25296896 38723 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25362432 38724 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25427968 38725 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] SEQNO cycled: 25493504 38726 [Apr 19 16:13:47] DEBUG[31280]: channel.c:2412 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:11654 handle_response_invite: SIP response 200 to standard invite [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/5678-09e1e818 [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:7992 build_route: build_route: Contact hop: Test 3 [Apr 19 16:13:47] -- Call on SIP/5678-09e1e818 left from hold [Apr 19 16:13:47] DEBUG[31280]: channel.c:2876 set_format: Set channel SIP/4321-09e13b78 to write format ulaw [Apr 19 16:13:47] DEBUG[31280]: channel.c:2020 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 19 16:13:47] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-09e1e818 [Apr 19 16:13:47] -- SIP/5678-09e1e818 answered SIP/4321-09e13b78 [Apr 19 16:13:47] -- Packet2Packet bridging SIP/4321-09e13b78 and SIP/5678-09e1e818 [Apr 19 16:13:47] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:47] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:47] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:47] DEBUG[31292]: 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:13:47] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: ca538dcd56cba534040c3ac853313042@10.4.119.245 Their Tag bd8350b9765cb33 Our tag: as48f1cf20 [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 - REGISTER (No RTP) [Apr 19 16:13:47] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 19 16:13:47] -- Saved useragent "MxSipApp/5.0.17.104 MxSF/v3.2.2.4" for peer 5678 [Apr 19 16:13:47] DEBUG[31263]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Apr 19 16:13:47] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:47] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:47] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:47] DEBUG[31293]: 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:13:48] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:13:48] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:13:48] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:48] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:48] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:48] DEBUG[31280]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:14705 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:14259 handle_request_bye: Received bye, issuing owner hangup [Apr 19 16:13:51] DEBUG[31280]: rtp.c:3102 bridge_p2p_loop: Oooh, got a hangup [Apr 19 16:13:51] DEBUG[31280]: channel.c:4094 ast_channel_bridge: Returning from native bridge, channels: SIP/4321-09e13b78, SIP/5678-09e1e818 [Apr 19 16:13:51] DEBUG[31280]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/5678-09e1e818' [Apr 19 16:13:51] DEBUG[31280]: chan_sip.c:3313 sip_hangup: Hangup call SIP/5678-09e1e818, SIP callid 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245) [Apr 19 16:13:51] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678-09e1e818 [Apr 19 16:13:51] DEBUG[31280]: rtp.c:1478 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 19 16:13:51] DEBUG[31280]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 19 16:13:51] DEBUG[31280]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,5678,1) exited non-zero on 'SIP/4321-09e13b78' [Apr 19 16:13:51] == Spawn extension (default, 5678, 1) exited non-zero on 'SIP/4321-09e13b78' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test" <4321>' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '5678' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321-09e13b78' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-09e1e818' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20|' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:37' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:37' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-19 16:13:51' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '14' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '14' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1177013617.0' [Apr 19 16:13:51] DEBUG[31280]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 19 16:13:51] DEBUG[31280]: channel.c:1716 ast_hangup: Hanging up channel 'SIP/4321-09e13b78' [Apr 19 16:13:51] DEBUG[31280]: chan_sip.c:3313 sip_hangup: Hangup call SIP/4321-09e13b78, SIP callid ca538dcd56cba534040c3ac853313042@10.4.119.245) [Apr 19 16:13:51] DEBUG[31280]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-09e13b78 [Apr 19 16:13:51] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Apr 19 16:13:51] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 5678 [Apr 19 16:13:51] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Apr 19 16:13:51] DEBUG[31253]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Apr 19 16:13:51] DEBUG[31253]: chan_sip.c:15317 sip_devicestate: Checking device state for peer 4321 [Apr 19 16:13:51] DEBUG[31253]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Apr 19 16:13:51] DEBUG[31294]: 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:13:51] DEBUG[31295]: 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:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245 Their Tag 76564fb10afd9b2 Our tag: as38fc288c [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: ca538dcd56cba534040c3ac853313042@10.4.119.245 Their Tag bd8350b9765cb33 Our tag: as48f1cf20 [Apr 19 16:13:51] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'ca538dcd56cba534040c3ac853313042@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:51] Really destroying SIP dialog '5d28ce11652ef2d055fc2bb87a6c7e70@10.4.119.245' Method: BYE [Apr 19 16:13:51] Really destroying SIP dialog 'ca538dcd56cba534040c3ac853313042@10.4.119.245' Method: ACK [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 1af2c9570666b7377b3453f11547f103@10.4.119.245 Their Tag Our tag: as4e75f7fd [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '1af2c9570666b7377b3453f11547f103@10.4.119.245' of Request 102: Match Not Found [Apr 19 16:13:52] Really destroying SIP dialog '1af2c9570666b7377b3453f11547f103@10.4.119.245' Method: NOTIFY [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:52] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 stop no[Apr 19 16:13:56] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:13:56] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:13:56] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:13:56] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 w[Apr 19 16:14:00] DEBUG[31263]: chan_sip.c:1881 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #39)) [Apr 19 16:14:00] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 2779aa60d2cedc9e5cdbd3d610b219c9@10.4.119.245 Their Tag 0d267a5bd3c9683 Our tag: as0855a7ee [Apr 19 16:14:00] DEBUG[31263]: chan_sip.c:4365 find_call: = No match Their Call ID: 41b288a63e974460171876cc741e6d44@10.4.119.245 Their Tag 022f961270b13be Our tag: as5cc423e4 [Apr 19 16:14:00] DEBUG[31263]: chan_sip.c:4365 find_call: = Found Their Call ID: 75e041226d82fb75624cc7400562abd2@10.4.119.245 Their Tag 92ebfa44e8dec71 Our tag: as3c4f9343 [Apr 19 16:14:11] Beginning asterisk shutdown.... [Apr 19 16:14:11] Executing last minute cleanups [Apr 19 16:14:11] == Destroying musiconhold processes [Apr 19 16:14:11] Asterisk cleanly ending (0). [Apr 19 16:14:11] DEBUG[31247]: asterisk.c:1274 quit_handler: Asterisk ending (0).