Untitled

[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 21541fe0-3fd79332@10.2.0.210 - INVITE (With RTP)
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:14707 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:4365 find_call: = Found Their Call ID: 21541fe0-3fd79332@10.2.0.210 Their Tag bd696808a052a92ao0 Our tag: as51937dde
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:14707 handle_request: **** Received ACK (6) - Command in SIP ACK
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '21541fe0-3fd79332@10.2.0.210' of Response 101: Match Not Found
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:4365 find_call: = Found Their Call ID: 21541fe0-3fd79332@10.2.0.210 Their Tag bd696808a052a92ao0 Our tag: as51937dde
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:14707 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel <none>
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0xd0d (g723|ulaw|alaw|g726|g729|ilbc)
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:13416 handle_request_invite: Checking SIP call limits for device sipura
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call
[Apr 27 01:14:03] DEBUG[14136]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw)
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0xd0d (g723|ulaw|alaw|g726|g729|ilbc)
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3808 sip_new: *** Our capabilities are 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264)
[Apr 27 01:14:03] DEBUG[14136]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:3832 sip_new: This channel will not be able to handle video.
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:7992 build_route: build_route: Contact hop: 989-345-1343 <sip:sipura@10.2.0.210:5060>
[Apr 27 01:14:03] DEBUG[14136]: chan_sip.c:13490 handle_request_invite: SIP/sipura-081d1da8: New call is still down.... Trying...
[Apr 27 01:14:03] DEBUG[14136]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura-081d1da8
[Apr 27 01:14:03] DEBUG[14157]: pbx.c:1809 pbx_extension_helper: Launching 'Dial'
    -- Executing [18004664411@home:1] Dial("SIP/sipura-081d1da8", "Zap/1/8004664411") in new stack
[Apr 27 01:14:03] DEBUG[14157]: chan_zap.c:7804 zt_request: Using channel 1
[Apr 27 01:14:03] DEBUG[14157]: rtp.c:1551 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything
[Apr 27 01:14:03] DEBUG[14157]: channel.c:3374 ast_channel_inherit_variables: Not copying variable STACK-home-18004664411-1.
[Apr 27 01:14:03] DEBUG[14157]: channel.c:3374 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 27 01:14:03] DEBUG[14157]: channel.c:3374 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Apr 27 01:14:03] DEBUG[14157]: channel.c:3374 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 27 01:14:03] DEBUG[14157]: channel.c:3374 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 27 01:14:03] DEBUG[14157]: chan_zap.c:1942 zt_call: Dialing '8004664411'
[Apr 27 01:14:03] DEBUG[14157]: chan_zap.c:2018 zt_call: Deferring dialing...
[Apr 27 01:14:03] DEBUG[14157]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
    -- Called 1/8004664411
[Apr 27 01:14:03] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura
[Apr 27 01:14:03] DEBUG[14134]: chan_sip.c:15319 sip_devicestate: Checking device state for peer sipura
[Apr 27 01:14:03] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for SIP/sipura - state 1 (Not in use)
[Apr 27 01:14:03] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Apr 27 01:14:03] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)
[Apr 27 01:14:03] DEBUG[14158]: app_queue.c:546 changethread: Device 'SIP/sipura' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 27 01:14:03] DEBUG[14159]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 27 01:14:03] DEBUG[14157]: chan_zap.c:4563 __zt_exception: Exception on 10, channel 1
[Apr 27 01:14:03] DEBUG[14157]: chan_zap.c:3684 zt_handle_event: Got event Hook Transition Complete(12) on channel 1 (index 0)
[Apr 27 01:14:06] DEBUG[14157]: chan_zap.c:4563 __zt_exception: Exception on 10, channel 1
[Apr 27 01:14:06] DEBUG[14157]: chan_zap.c:3684 zt_handle_event: Got event Dial Complete(9) on channel 1 (index 0)
[Apr 27 01:14:06] DEBUG[14157]: chan_zap.c:1433 zt_enable_ec: Enabled echo cancellation on channel 1
[Apr 27 01:14:06] DEBUG[14157]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
    -- Zap/1-1 answered SIP/sipura-081d1da8
[Apr 27 01:14:06] DEBUG[14157]: rtp.c:1476 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Apr 27 01:14:06] DEBUG[14157]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura-081d1da8
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/sipura-081d1da8
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:6430 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:6198 add_sdp: ** Our capability: 0xd0d (g723|ulaw|alaw|g726|g729|ilbc) Video flag: True
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP
[Apr 27 01:14:06] DEBUG[14157]: channel.c:2445 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=16)
[Apr 27 01:14:06] DEBUG[14157]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xd0d (g723|ulaw|alaw|g726|g729|ilbc)
[Apr 27 01:14:06] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Apr 27 01:14:06] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)
[Apr 27 01:14:06] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura
[Apr 27 01:14:06] DEBUG[14134]: chan_sip.c:15319 sip_devicestate: Checking device state for peer sipura
[Apr 27 01:14:06] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for SIP/sipura - state 1 (Not in use)
[Apr 27 01:14:06] DEBUG[14160]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 27 01:14:06] DEBUG[14161]: app_queue.c:546 changethread: Device 'SIP/sipura' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 27 01:14:06] DEBUG[14157]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Apr 27 01:14:06] DEBUG[14157]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 27 01:14:06] DEBUG[14136]: chan_sip.c:4365 find_call: = Found Their Call ID: 21541fe0-3fd79332@10.2.0.210 Their Tag bd696808a052a92ao0 Our tag: as7b650aca
[Apr 27 01:14:06] DEBUG[14136]: chan_sip.c:14707 handle_request: **** Received ACK (6) - Command in SIP ACK
[Apr 27 01:14:06] DEBUG[14136]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '21541fe0-3fd79332@10.2.0.210' of Response 102: Match Not Found
[Apr 27 01:14:06] DEBUG[14136]: chan_sip.c:4365 find_call: = No match Their Call ID: 21541fe0-3fd79332@10.2.0.210 Their Tag bd696808a052a92ao0 Our tag: as7b650aca
[Apr 27 01:14:06] DEBUG[14136]: chan_sip.c:14891 sipsock_read: Invalid SIP message - rejected , no callid, len 327
[Apr 27 01:14:12] DEBUG[14136]: chan_sip.c:4365 find_call: = Found Their Call ID: 21541fe0-3fd79332@10.2.0.210 Their Tag bd696808a052a92ao0 Our tag: as7b650aca
[Apr 27 01:14:12] DEBUG[14136]: chan_sip.c:14707 handle_request: **** Received BYE (8) - Command in SIP BYE
[Apr 27 01:14:12] DEBUG[14136]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 21541fe0-3fd79332@10.2.0.210
[Apr 27 01:14:12] DEBUG[14136]: chan_sip.c:14261 handle_request_bye: Received bye, issuing owner hangup
[Apr 27 01:14:12] DEBUG[14157]: channel.c:3879 ast_generic_bridge: Didn't get a frame from channel: SIP/sipura-081d1da8
[Apr 27 01:14:12] DEBUG[14157]: channel.c:4197 ast_channel_bridge: Bridge stops bridging channels SIP/sipura-081d1da8 and Zap/1-1
[Apr 27 01:14:12] DEBUG[14157]: channel.c:1724 ast_hangup: Hanging up channel 'Zap/1-1'
[Apr 27 01:14:12] DEBUG[14157]: chan_zap.c:2410 zt_hangup: zt_hangup(Zap/1-1)
[Apr 27 01:14:12] DEBUG[14157]: chan_zap.c:2443 zt_hangup: Hangup: channel: 1 index = 0, normal = 10, callwait = -1, thirdcall = -1
[Apr 27 01:14:12] DEBUG[14157]: chan_zap.c:1465 zt_disable_ec: disabled echo cancellation on channel 1
[Apr 27 01:14:12] DEBUG[14157]: chan_zap.c:2870 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1
[Apr 27 01:14:12] DEBUG[14157]: chan_zap.c:1402 update_conf: Updated conferencing on 1, with 0 conference users
    -- Hungup 'Zap/1-1'
[Apr 27 01:14:12] DEBUG[14157]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Apr 27 01:14:12] DEBUG[14157]: rtp.c:1476 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Apr 27 01:14:12] DEBUG[14157]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Apr 27 01:14:12] DEBUG[14157]: pbx.c:2407 __ast_pbx_run: Spawn extension (home,18004664411,1) exited non-zero on 'SIP/sipura-081d1da8'
  == Spawn extension (home, 18004664411, 1) exited non-zero on 'SIP/sipura-081d1da8'
[Apr 27 01:14:12] DEBUG[14157]: channel.c:1724 ast_hangup: Hanging up channel 'SIP/sipura-081d1da8'
[Apr 27 01:14:12] DEBUG[14157]: chan_sip.c:3313 sip_hangup: Hangup call SIP/sipura-081d1da8, SIP callid 21541fe0-3fd79332@10.2.0.210)
[Apr 27 01:14:12] DEBUG[14157]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura-081d1da8
[Apr 27 01:14:12] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Apr 27 01:14:12] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown)
[Apr 27 01:14:12] DEBUG[14134]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura
[Apr 27 01:14:12] DEBUG[14134]: chan_sip.c:15319 sip_devicestate: Checking device state for peer sipura
[Apr 27 01:14:12] DEBUG[14134]: devicestate.c:287 do_state_change: Changing state for SIP/sipura - state 1 (Not in use)
[Apr 27 01:14:12] DEBUG[14164]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Apr 27 01:14:12] DEBUG[14165]: app_queue.c:546 changethread: Device 'SIP/sipura' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Really destroying SIP dialog '21541fe0-3fd79332@10.2.0.210' Method: BYE