[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for d6f3a6d9-40b5be5f-6fe73df0@10.1.3.104 - INVITE (With RTP)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2234 __sip_ack: Stopping retransmission on 'd6f3a6d9-40b5be5f-6fe73df0@10.1.3.104' of Response 1: Match Found
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel <none>
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:14056 handle_request_invite: Checking SIP call limits for device 204
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4128 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4159 sip_new: This channel will not be able to handle video.
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:8478 build_route: build_route: Contact hop: <sip:204@10.1.3.104>
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:14131 handle_request_invite: SIP/204-b7d63390: New call is still down.... Trying... 
[Feb 27 17:06:32] DEBUG[12654]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/204-b7d63390
[Feb 27 17:06:32] DEBUG[12654]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 204
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 204
[Feb 27 17:06:32] DEBUG[12654]: devicestate.c:428 do_state_change: Changing state for SIP/204 - state 1 (Not in use)
[Feb 27 17:06:32] DEBUG[12654]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 204
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 204
[Feb 27 17:06:32] DEBUG[12654]: pbx.c:1693 pbx_extension_helper: Launching 'Macro'
    -- Executing [214@iax-trunk:1] Macro("SIP/204-b7d63390", "stdexten|214|SIP/214") in new stack
[Feb 27 17:06:32] DEBUG[12654]: db.c:198 ast_db_get: Unable to find key '214' in family 'CFI'
[Feb 27 17:06:32] DEBUG[12654]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0'
[Feb 27 17:06:32] DEBUG[12654]: pbx.c:1693 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [s@macro-stdexten:1] GotoIf("SIP/204-b7d63390", "0?s|2:s|3") in new stack
    -- Goto (macro-stdexten,s,3)
[Feb 27 17:06:32] DEBUG[12654]: pbx.c:1693 pbx_extension_helper: Launching 'Dial'
    -- Executing [s@macro-stdexten:3] Dial("SIP/204-b7d63390", "SIP/214|20|t") in new stack
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:15966 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4128 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4131 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:4159 sip_new: This channel will not be able to handle video.
[Feb 27 17:06:32] DEBUG[12654]: rtp.c:1677 ast_rtp_make_compatible: Seeded SDP of 'SIP/214-08b9c7d0' with that of 'SIP/204-b7d63390'
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-3.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable ARG2.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable ARG1.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable STACK-iax-trunk-214-1.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable SIPURI.
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:3122 sip_call: Outgoing Call for 214
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:3140 sip_call: Our T38 capability (0), joint T38 capability (0)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:6674 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False Text flag: False
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method INVITE - callid 2ba724991b2a8bba188595a65064e623@10.1.4.9
    -- Called 214
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2ba724991b2a8bba188595a65064e623@10.1.4.9' Request 102: Found
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:12287 handle_response_invite: SIP response 100 to standard invite
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2218 __sip_ack: Acked pending invite 102
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '2ba724991b2a8bba188595a65064e623@10.1.4.9' of Request 102: Match Found
    -- Got SIP response 302 "Moved Temporarily" back from 10.1.3.114
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:12245 parse_moved_contact: Received 302 Redirect to extension '431' (domain 10.1.4.9:5060)
[Feb 27 17:06:32] DEBUG[12654]: chan_sip.c:1731 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2ba724991b2a8bba188595a65064e623@10.1.4.9
    -- Now forwarding SIP/204-b7d63390 to 'Local/431@iax-trunk' (thanks to SIP/214-08b9c7d0)
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-3.
[Feb 27 17:06:32] DEBUG[12654]: channel.c:3225 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.