[Jun 4 10:36:19] Asterisk SVN-branch-1.4-r199022M, Copyright (C) 1999 - 2008 Digium, Inc. and others. [Jun 4 10:36:19] Created by Mark Spencer [Jun 4 10:36:19] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Jun 4 10:36:19] This is free software, with components licensed under the GNU General Public [Jun 4 10:36:19] License version 2 and other licenses; you are welcome to redistribute it under [Jun 4 10:36:19] certain conditions. Type 'core show license' for details. [Jun 4 10:36:19] ========================================================================= [Jun 4 10:36:20] Asterisk Ready. [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2805 do_setnat: Setting NAT on RTP to Off [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2815 do_setnat: Setting NAT on UDPTL to Off [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4656 sip_alloc: Allocating new SIP dialog for 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 - INVITE (With RTP) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2805 do_setnat: Setting NAT on RTP to On [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2815 do_setnat: Setting NAT on UDPTL to On [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:5662 process_sdp: T38 state changed to 0 on channel [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:5742 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:14753 handle_request_invite: Checking SIP call limits for device 4567 [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:3289 update_call_counter: Updating call counter for incoming call [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4132 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4133 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4134 sip_new: *** Our capabilities are 0x804 (ulaw|g726) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4135 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4158 sip_new: This channel will not be able to handle video. [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:8628 build_route: build_route: Contact hop: sip:4567@10.4.119.185 [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:14836 handle_request_invite: SIP/4567-08519ae8: New call is still down.... Trying... [Jun 4 10:36:43] DEBUG[29883]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Jun 4 10:36:43] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Jun 4 10:36:43] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 4567 [Jun 4 10:36:43] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Jun 4 10:36:43] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:43] DEBUG[29900]: pbx.c:1844 pbx_extension_helper: Launching 'Dial' [Jun 4 10:36:43] -- Executing [5678@default:1] Dial("SIP/4567-08519ae8", "SIP/5678|20") in new stack [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:16937 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4656 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:2851 create_addr_from_peer: Our T38 capability (3872) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:2805 do_setnat: Setting NAT on RTP to On [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:2815 do_setnat: Setting NAT on UDPTL to On [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4132 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4133 sip_new: *** Joint capabilities are 0x0 (nothing) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4134 sip_new: *** Our capabilities are 0x804 (ulaw|g726) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4135 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4137 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:4158 sip_new: This channel will not be able to handle video. [Jun 4 10:36:43] DEBUG[29900]: rtp.c:1682 ast_rtp_make_compatible: Seeded SDP of 'SIP/5678-0851fc00' with that of 'SIP/4567-08519ae8' [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jun 4 10:36:43] DEBUG[29900]: channel.c:3593 ast_channel_inherit_variables: Not copying variable SIPURI. [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:3083 sip_call: Outgoing Call for 5678 [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:3289 update_call_counter: Updating call counter for outgoing call [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:3098 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:6692 add_sdp: ** Our capability: 0x804 (ulaw|g726) Video flag: False [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:6693 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:6810 add_sdp: -- Done with adding codecs to SDP [Jun 4 10:36:43] DEBUG[29900]: channel.c:2458 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 4 10:36:43] DEBUG[29900]: chan_sip.c:6911 add_sdp: Done building SDP. Settling with this capability: 0x804 (ulaw|g726) [Jun 4 10:36:43] -- Called 5678 [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag Our tag: as5a3b25af [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2270 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' Request 102: Found [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:12520 handle_response_invite: SIP response 100 to standard invite [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:2270 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' Request 102: Found [Jun 4 10:36:43] DEBUG[29883]: chan_sip.c:12520 handle_response_invite: SIP response 180 to standard invite [Jun 4 10:36:43] DEBUG[29883]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Jun 4 10:36:43] -- SIP/5678-0851fc00 is ringing [Jun 4 10:36:43] DEBUG[29900]: rtp.c:1611 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/4567-08519ae8' with that of 'SIP/5678-0851fc00' [Jun 4 10:36:43] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Jun 4 10:36:43] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 5678 [Jun 4 10:36:43] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Jun 4 10:36:43] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2197 __sip_ack: Acked pending invite 102 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' of Request 102: Match Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12520 handle_response_invite: SIP response 200 to standard invite [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5662 process_sdp: T38 state changed to 0 on channel SIP/5678-0851fc00 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5742 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5749 process_sdp: We have an owner, now see if we need to change this call [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:3289 update_call_counter: Updating call counter for outgoing call [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:8628 build_route: build_route: Contact hop: sip:5678@10.4.127.199 [Jun 4 10:36:44] DEBUG[29900]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Jun 4 10:36:44] -- SIP/5678-0851fc00 answered SIP/4567-08519ae8 [Jun 4 10:36:44] DEBUG[29900]: rtp.c:1611 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/4567-08519ae8' with that of 'SIP/5678-0851fc00' [Jun 4 10:36:44] DEBUG[29900]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:3762 sip_answer: SIP answering channel: SIP/4567-08519ae8 [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6969 transmit_response_with_sdp: Setting framing from config on incoming call [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6692 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6693 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6810 add_sdp: -- Done with adding codecs to SDP [Jun 4 10:36:44] DEBUG[29900]: channel.c:2458 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6911 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 4 10:36:44] -- Native bridging SIP/4567-08519ae8 and SIP/5678-0851fc00 [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:18666 sip_set_rtp_peer: Deferring reinvite on SIP '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' - It's audio will be redirected to IP 10.4.127.199 [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:18661 sip_set_rtp_peer: Sending reinvite on SIP '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' - It's audio soon redirected to IP 10.4.119.185 [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6692 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6693 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6810 add_sdp: -- Done with adding codecs to SDP [Jun 4 10:36:44] DEBUG[29900]: channel.c:2458 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:6911 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29900]: chan_sip.c:1669 initialize_initreq: Initializing already initialized SIP dialog 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 (presumably reinvite) [Jun 4 10:36:44] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Jun 4 10:36:44] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 5678 [Jun 4 10:36:44] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Jun 4 10:36:44] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Jun 4 10:36:44] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 4567 [Jun 4 10:36:44] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Jun 4 10:36:44] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:44] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = No match Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received ACK (6) - Command in SIP ACK [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' of Response 320336502: Match Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12482 check_pendings: Sending pending reinvite on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:6692 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:6693 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:6810 add_sdp: -- Done with adding codecs to SDP [Jun 4 10:36:44] DEBUG[29883]: channel.c:2458 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:6911 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:1669 initialize_initreq: Initializing already initialized SIP dialog 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 (presumably reinvite) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2270 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' Request 103: Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 100 to RE-invite on outgoing call 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2197 __sip_ack: Acked pending invite 103 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' of Request 103: Match Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 200 to RE-invite on outgoing call 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5662 process_sdp: T38 state changed to 0 on channel SIP/5678-0851fc00 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5742 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5749 process_sdp: We have an owner, now see if we need to change this call [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:3289 update_call_counter: Updating call counter for outgoing call [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = No match Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2270 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' Request 102: Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 100 to RE-invite on outgoing call 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = No match Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2197 __sip_ack: Acked pending invite 102 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' of Request 102: Match Found [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 200 to RE-invite on outgoing call 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5662 process_sdp: T38 state changed to 0 on channel SIP/4567-08519ae8 [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5742 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:5749 process_sdp: We have an owner, now see if we need to change this call [Jun 4 10:36:44] DEBUG[29883]: chan_sip.c:3289 update_call_counter: Updating call counter for incoming call [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:4712 find_call: = No match Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5320 process_sdp: T38 state changed to 3 on channel SIP/4567-08519ae8 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5553 process_sdp: T38MaxBitRate: 14400 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5627 process_sdp: RateManagement: transferredTCF [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5592 process_sdp: FillBitRemoval: 0 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5604 process_sdp: Transcoding MMR: 0 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5616 process_sdp: Transcoding JBIG: 0 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5577 process_sdp: FaxVersion: 0 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5635 process_sdp: UDP EC: t38UDPRedundancy [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:5697 process_sdp: Have T.38 but no audio codecs, accepting offer anyway [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:14922 handle_request_invite: SIP/4567-08519ae8: This call is UP.... [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:18504 sip_handle_t38_reinvite: Sending reinvite on SIP '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' - It's UDPTL soon redirected to IP 10.4.119.185:6004 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:6553 t38_get_rate: T38MaxBitRate 9600 found [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:6911 add_sdp: Done building SDP. Settling with this capability: 0x0 (nothing) [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:1669 initialize_initreq: Initializing already initialized SIP dialog 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 (presumably reinvite) [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:2270 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' Request 104: Found [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 100 to RE-invite on outgoing call 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:2197 __sip_ack: Acked pending invite 104 [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' of Request 104: Match Found [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:12518 handle_response_invite: SIP response 488 to RE-invite on outgoing call 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 [Jun 4 10:36:48] ERROR[29883]: chan_sip.c:12764 handle_response_invite: Got error on T.38 re-invite. Bad configuration. Peer needs to have T.38 disabled. [Jun 4 10:36:48] DEBUG[29900]: rtp.c:3118 bridge_native_loop: Got a FRAME_CONTROL (8) frame on channel SIP/5678-0851fc00 [Jun 4 10:36:48] DEBUG[29900]: channel.c:4398 ast_channel_bridge: Returning from native bridge, channels: SIP/4567-08519ae8, SIP/5678-0851fc00 [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '4567' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '4567' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '5678' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'default' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/4567-08519ae8' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-0851fc00' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-06-04 10:36:43' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-06-04 10:36:44' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '2009-06-04 10:36:48' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '5' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '4' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '1244126203.0' [Jun 4 10:36:48] DEBUG[29900]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '(null)' [Jun 4 10:36:48] DEBUG[29900]: channel.c:1519 ast_hangup: Hanging up channel 'SIP/5678-0851fc00' [Jun 4 10:36:48] DEBUG[29900]: chan_sip.c:3606 sip_hangup: Hangup call SIP/5678-0851fc00, SIP callid 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245) [Jun 4 10:36:48] DEBUG[29900]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Jun 4 10:36:48] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Jun 4 10:36:48] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 5678 [Jun 4 10:36:48] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Jun 4 10:36:48] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:48] DEBUG[29900]: rtp.c:1561 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jun 4 10:36:48] DEBUG[29900]: app_dial.c:1825 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jun 4 10:36:48] DEBUG[29900]: pbx.c:2430 __ast_pbx_run: Spawn extension (default,5678,1) exited non-zero on 'SIP/4567-08519ae8' [Jun 4 10:36:48] == Spawn extension (default, 5678, 1) exited non-zero on 'SIP/4567-08519ae8' [Jun 4 10:36:48] DEBUG[29900]: channel.c:1426 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/4567-08519ae8' [Jun 4 10:36:48] DEBUG[29900]: channel.c:1519 ast_hangup: Hanging up channel 'SIP/4567-08519ae8' [Jun 4 10:36:48] DEBUG[29900]: chan_sip.c:3606 sip_hangup: Hangup call SIP/4567-08519ae8, SIP callid 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245) [Jun 4 10:36:48] DEBUG[29900]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Jun 4 10:36:48] DEBUG[29870]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Jun 4 10:36:48] DEBUG[29870]: chan_sip.c:16861 sip_devicestate: Checking device state for peer 4567 [Jun 4 10:36:48] DEBUG[29870]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Jun 4 10:36:48] DEBUG[29882]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 06d243e941b0bf583a625b2d5bc8353c@10.4.119.245 Their Tag d2e1c8c7ea77abf Our tag: as5a3b25af [Jun 4 10:36:48] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' of Request 105: Match Found [Jun 4 10:36:48] Really destroying SIP dialog '06d243e941b0bf583a625b2d5bc8353c@10.4.119.245' Method: INVITE [Jun 4 10:36:53] DEBUG[29883]: chan_sip.c:2134 __sip_autodestruct: Auto destroying SIP dialog '7cf8c18e9b6ba514573345e50c64e46a@192.168.0.20' [Jun 4 10:36:53] DEBUG[29883]: chan_sip.c:3398 sip_destroy: Destroying SIP dialog 7cf8c18e9b6ba514573345e50c64e46a@192.168.0.20 [Jun 4 10:36:53] Really destroying SIP dialog '7cf8c18e9b6ba514573345e50c64e46a@192.168.0.20' Method: REGISTER [Jun 4 10:36:53] DEBUG[29883]: chan_sip.c:2134 __sip_autodestruct: Auto destroying SIP dialog '0986bc4d0ebcfab2f391e59958ca0d0f@192.168.0.20' [Jun 4 10:36:53] DEBUG[29883]: chan_sip.c:3398 sip_destroy: Destroying SIP dialog 0986bc4d0ebcfab2f391e59958ca0d0f@192.168.0.20 [Jun 4 10:36:53] Really destroying SIP dialog '0986bc4d0ebcfab2f391e59958ca0d0f@192.168.0.20' Method: REGISTER [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:1681 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received ACK (6) - Command in SIP ACK [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' of Response 320336503: Match Found [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:16087 handle_request: **** Received BYE (8) - Command in SIP BYE [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' of Request 103: Match Found [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:1681 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:15624 handle_request_bye: Received bye, no owner, selfdestruct soon. [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:4712 find_call: = Found Their Call ID: 0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245 Their Tag 2c66e511b33e27c Our tag: as404ce928 [Jun 4 10:36:58] DEBUG[29883]: chan_sip.c:2229 __sip_ack: Stopping retransmission on '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' of Request 103: Match Not Found [Jun 4 10:36:58] Really destroying SIP dialog '0ec20995c4b0795c3fdb4ec9d4be78fe@10.4.119.245' Method: BYE [Jun 4 10:37:17] Beginning asterisk shutdown.... [Jun 4 10:37:17] Executing last minute cleanups [Jun 4 10:37:17] == Destroying musiconhold processes [Jun 4 10:37:17] Asterisk cleanly ending (0).