-- Executing [execute_call@macro-internanruf:24] Dial("SIP/20-00000041", "SIP/11,120,jM(setanswering^SIP/20-00000041)") in new stack
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:25933 sip_request_call: Asked to create a SIP channel with formats: 0x1000 (g722)
  == Using UDPTL CoS mark 5
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:7536 sip_alloc: Allocating new SIP dialog for 63f767825062ab78474669464bada5d4@10.78.65.80:5060 - INVITE (No RTP)
[Jan 26 14:33:39] DEBUG[7092]: rtp_engine.c:345 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x1073f5f0'
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:483 ast_rtp_new: Allocated port 16590 for RTP instance '0x1073f5f0'
[Jan 26 14:33:39] DEBUG[7092]: rtp_engine.c:354 ast_rtp_instance_new: RTP instance '0x1073f5f0' is setup and ready to go
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:2418 ast_rtp_prop_set: Setup RTCP on RTP instance '0x1073f5f0'
  == Using SIP RTP CoS mark 5
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:4948 do_setnat: Setting NAT on RTP to Off
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:4956 do_setnat: Setting NAT on UDPTL to Off
[Jan 26 14:33:39] DEBUG[7092]: acl.c:725 ast_ouraddrfor: For destination '10.78.65.153', our source address is '10.78.65.80'.
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:3486 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.78.65.80:5060
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6866 sip_new: *** Our native formats are 0x1000 (g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6867 sip_new: *** Joint capabilities are 0x1000 (g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6868 sip_new: *** Our capabilities are 0x110e (gsm|ulaw|alaw|g729|g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6869 sip_new: *** AST_CODEC_CHOOSE formats are 0x1000 (g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6871 sip_new: *** Our preferred formats from the incoming channel are 0x1000 (g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:6899 sip_new: This channel will not be able to handle video.
[Jan 26 14:33:39] DEBUG[7092]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jan 26 14:33:39] DEBUG[7092]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable DIALEDTIME.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable DIALSTATUS.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable YYY.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable GRPS.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable GROUPCOUNT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable REDIRRING.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable DURCHWAHL.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable ESKALATION.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable TIMEOUT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable DIALOPT_OUTBOUND.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable extended_dialopt.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable extended_dialstring.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable SRC_EXTEN_11.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6056 ast_channel_inherit_variables: Copying soft-transferable variable REPLACEMENTNUM.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable DISPLAYNAME.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6056 ast_channel_inherit_variables: Copying soft-transferable variable FORWARD_CONTEXT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6056 ast_channel_inherit_variables: Copying soft-transferable variable TRANSFER_CONTEXT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable dialstring.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable replacename.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable incalllimit.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable secondary_exten.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable primary_exten.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable multicall_busy.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable forward_context.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable context.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_ring.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_busy_to.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_busy_active.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_internal.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_external.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_time.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_when.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_number.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable redirect_active.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable when_busy_macro.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable secondary_queue.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable when_busy_step2.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable when_busy_duration.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable primary_queue.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable when_busy_timeout.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable when_busy.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable displayname.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable access_system.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable enable_mailbox.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable ext_callerid.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable CALLSOURCE.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable ARG1.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable QUEUEMEMBER.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable QUEUECALL.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6063 ast_channel_inherit_variables: Copying hard-transferable variable XMLSENT.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:6067 ast_channel_inherit_variables: Not copying variable SIPURI.
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:5490 sip_call: Outgoing Call for 11
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:5755 update_call_counter: Updating call counter for outgoing call
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
[Jan 26 14:33:39] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 6 (Ringing)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:11033 add_sdp: ** Our capability: 0x100e (gsm|ulaw|alaw|g722) Video flag: False Text flag: False
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '6'
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:11034 add_sdp: ** Our prefcodec: 0x1000 (g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:11143 add_sdp: -- Done with adding codecs to SDP
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:11282 add_sdp: Done building SDP. Settling with this capability: 0x100e (gsm|ulaw|alaw|g722)
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:3061 initialize_initreq: Initializing initreq for method INVITE - callid 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060
[Jan 26 14:33:39] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 26 14:33:39] DEBUG[7092]: chan_sip.c:3332 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.78.65.153:5060
    -- Called SIP/11
[Jan 26 14:33:39] DEBUG[5805]: app_queue.c:1588 extension_state_cb: Extension '11@autohint' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #5333))
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.78.65.153:5060
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (Checking To) --From tag as7309ca20 --To-tag 960312401
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:4059 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Request 102: Found
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:19425 handle_response_invite: SIP response 180 to standard invite
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
    -- SIP/11-00000042 is ringing
[Jan 26 14:33:39] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 6 (Ringing)
[Jan 26 14:33:39] DEBUG[7092]: channel.c:4491 ast_indicate_data: Driver for channel 'SIP/20-00000041' does not support indication 3, emulating it
[Jan 26 14:33:39] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '6'
[Jan 26 14:33:39] DEBUG[7092]: channel.c:5146 set_format: Set channel SIP/20-00000041 to write format slin
[Jan 26 14:33:39] DEBUG[7092]: channel.c:3499 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 26 14:33:39] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 26 14:33:39] DEBUG[7092]: channel.c:4641 ast_prod: Prodding channel 'SIP/20-00000041'
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:1253 ast_rtp_write: Received frame with no data for RTP instance '0x106a4db8' so dropping frame
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (Checking To) --From tag as7309ca20 --To-tag 960312401
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:4059 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Request 102: Found
[Jan 26 14:33:39] DEBUG[5830]: chan_sip.c:19425 handle_response_invite: SIP response 180 to standard invite
    -- SIP/11-00000042 is ringing
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:1282 ast_rtp_write: Ooh, format changed from unknown to g722
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:1313 ast_rtp_write: Created smoother: format: g722 ms: 20 len: 160
[Jan 26 14:33:39] DEBUG[7092]: res_rtp_asterisk.c:1178 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x106a4db8'
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:40] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1247 ast_rtp_write: No remote address on RTP instance '0x1073f5f0' so dropping frame
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (Checking To) --From tag as7309ca20 --To-tag 960312401
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:3980 __sip_ack: Acked pending invite 102
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' of Request 102: Match Found
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:19425 handle_response_invite: SIP response 200 to standard invite
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP o=MxSIP 0 0 IN IP4 10.78.65.153... UNSUPPORTED.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153' into...
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port ''.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP c=IN IP4 10.78.65.153... OK.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6e0ca54
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6e0ca54
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0xb6e0ca54
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb6e0ca54
[Jan 26 14:33:41] DEBUG[5830]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1073f5f0'
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6e0ca54 to 0x1073f79c
[Jan 26 14:33:41] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6e0ca54 to 0x1073f79c
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:9067 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:9072 process_sdp: We have an owner, now see if we need to change this call
[Jan 26 14:33:41] DEBUG[7092]: channel.c:4776 ast_write: Deadlock avoided for write to channel 'SIP/11-00000042'
[Jan 26 14:33:41] DEBUG[5830]: channel.c:5146 set_format: Set channel SIP/11-00000042 to read format g722
[Jan 26 14:33:41] DEBUG[5830]: channel.c:5146 set_format: Set channel SIP/11-00000042 to write format g722
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:5755 update_call_counter: Updating call counter for outgoing call
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:13789 build_route: build_route: Contact hop: "11" <sip:11@10.78.65.153:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-1000-8000-00085D195BFC>"
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
[Jan 26 14:33:41] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 2 (In use)
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '2'
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'ACK sip:11@' onto UDP socket destined for 10.78.65.153:5060
[Jan 26 14:33:41] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
    -- SIP/11-00000042 answered SIP/20-00000041
[Jan 26 14:33:41] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:41] DEBUG[5805]: app_queue.c:1588 extension_state_cb: Extension '11@autohint' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 2 (In use)
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '2'
[Jan 26 14:33:41] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'ARG1' is 'SIP/20-00000041'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-setanswering:1] NoOp("SIP/11-00000042", "CHANNELARG = SIP/20-00000041") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: NoOp
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'CHANNEL' is 'SIP/11-00000042'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'NoOp'
    -- Executing [s@macro-setanswering:2] NoOp("SIP/11-00000042", "CHANNEL = SIP/11-00000042") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: NoOp
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3928 pbx_substitute_variables_helper_full: Function result is '11'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-setanswering:3] Set("SIP/11-00000042", "GROUP(int)=11") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: Set
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'QUEUECALL' is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3996 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3106 ast_str_retrieve_variable: Result of 'QUEUENAME' is NULL
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-setanswering:4] ExecIf("SIP/11-00000042", "0?Set(DEVICE_STATE(Custom:*grp*)=INUSE)") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3695 ast_str_substitute_variables_full: Evaluating 'QUEUECALL' (from 'QUEUECALL}" == "1"' len 9)
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'QUEUECALL' is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3787 ast_str_substitute_variables_full: Expression result is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3695 ast_str_substitute_variables_full: Evaluating 'QUEUENAME' (from 'QUEUENAME})=INUSE)' len 9)
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3106 ast_str_retrieve_variable: Result of 'QUEUENAME' is NULL
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'AGI'
    -- Executing [s@macro-setanswering:5] AGI("SIP/11-00000042", "set_answering_extension.php") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/set_answering_extension.php
    -- set_answering_extension.php: EXTENSION SIP/11 ANSWERD THIS CALL
    -- set_answering_extension.php: CHANNEL FOR THIS CALL IS: SIP/11-00000042
    -- <SIP/11-00000042>AGI Script set_answering_extension.php completed, returning 0
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: AGI
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'ARG1' is 'SIP/20-00000041'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'WHO_ANSWERED' is 'SIP/11'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'Set'
    -- Executing [s@macro-setanswering:6] Set("SIP/11-00000042", "SIP/20-00000041-ANSWEREDBY=SIP/11,g") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: Set
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'QUEUECALL' is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3996 pbx_substitute_variables_helper_full: Expression result is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'WHO_ANSWERED_CHAN' is 'SIP/11-00000042'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:4100 pbx_extension_helper: Launching 'ExecIf'
    -- Executing [s@macro-setanswering:7] ExecIf("SIP/11-00000042", "0?Set(SHARED(foo,SIP/11-00000042=456)") in new stack
[Jan 26 14:33:41] DEBUG[7092]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3695 ast_str_substitute_variables_full: Evaluating 'QUEUECALL' (from 'QUEUECALL}" == "1"' len 9)
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'QUEUECALL' is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3787 ast_str_substitute_variables_full: Expression result is '0'
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3695 ast_str_substitute_variables_full: Evaluating 'WHO_ANSWERED_CHAN' (from 'WHO_ANSWERED_CHAN}=456)' len 17)
[Jan 26 14:33:41] DEBUG[7092]: pbx.c:3109 ast_str_retrieve_variable: Result of 'WHO_ANSWERED_CHAN' is 'SIP/11-00000042'
[Jan 26 14:33:41] DEBUG[7092]: app_dial.c:2595 dial_exec_full: Macro exited with status 0
[Jan 26 14:33:41] DEBUG[7092]: channel.c:5146 set_format: Set channel SIP/20-00000041 to write format g722
[Jan 26 14:33:41] DEBUG[7092]: channel.c:3499 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:6329 sip_answer: SIP answering channel: SIP/20-00000041
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 20
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:753 ast_rtp_update_source: Setting the marker bit due to a source update
[Jan 26 14:33:41] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 20
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11387 transmit_response_with_sdp: Setting framing from config on incoming call
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/20 - state 2 (In use)
[Jan 26 14:33:41] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/20' state '2'
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11033 add_sdp: ** Our capability: 0x110c (ulaw|alaw|g729|g722) Video flag: True Text flag: True
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11034 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11143 add_sdp: -- Done with adding codecs to SDP
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11282 add_sdp: Done building SDP. Settling with this capability: 0x110c (ulaw|alaw|g729|g722)
[Jan 26 14:33:41] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/20' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:41] DEBUG[7092]: features.c:3806 ast_bridge_call: bridge answer set, chan answer set
[Jan 26 14:33:41] DEBUG[7092]: features.c:3654 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/11-00000042 since we're bridging
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:753 ast_rtp_update_source: Setting the marker bit due to a source update
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:753 ast_rtp_update_source: Setting the marker bit due to a source update
    -- Remotely bridging SIP/20-00000041 and SIP/11-00000042
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:28670 sip_set_rtp_peer: Deferring reinvite on SIP '1688579688@10.78.65.152' - It's audio will be redirected to IP 10.78.65.153:3000
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:28667 sip_set_rtp_peer: Sending reinvite on SIP '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' - It's audio soon redirected to IP 10.78.65.152:11786
[Jan 26 14:33:41] DEBUG[7092]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:41] DEBUG[7092]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11033 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11034 add_sdp: ** Our prefcodec: 0x1000 (g722)
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11038 add_sdp: ** Our native-bridge filtered capablity: 0x8 (alaw)
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11143 add_sdp: -- Done with adding codecs to SDP
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:11282 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:3059 initialize_initreq: Initializing already initialized SIP dialog 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (presumably reinvite)
[Jan 26 14:33:41] DEBUG[7092]: chan_sip.c:3332 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.78.65.153:5060
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: INVITE
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1282 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1313 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[Jan 26 14:33:41] DEBUG[7092]: res_rtp_asterisk.c:1178 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x1073f5f0'
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking From) --From tag 47411633 --To-tag as18adc4b6
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:24571 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '1688579688@10.78.65.152' of Response 2: Match Found
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:19261 check_pendings: Sending pending reinvite on '1688579688@10.78.65.152'
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:41] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:11033 add_sdp: ** Our capability: 0x110c (ulaw|alaw|g729|g722) Video flag: True Text flag: True
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:11034 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:11038 add_sdp: ** Our native-bridge filtered capablity: 0x8 (alaw)
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:11143 add_sdp: -- Done with adding codecs to SDP
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:11282 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:3059 initialize_initreq: Initializing already initialized SIP dialog 1688579688@10.78.65.152 (presumably reinvite)
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:41] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:4059 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1688579688@10.78.65.152' Request 102: Found
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:19423 handle_response_invite: SIP response 100 to RE-invite on outgoing call 1688579688@10.78.65.152
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:3980 __sip_ack: Acked pending invite 102
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '1688579688@10.78.65.152' of Request 102: Match Found
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:19423 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1688579688@10.78.65.152
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP o=- 20014 20015 IN IP4 10.78.65.152... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP s=SDP data... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152' into...
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port ''.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP c=IN IP4 10.78.65.152... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x106a4db8'
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6e0ca54 to 0x106a4f64
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6e0ca54 to 0x106a4f64
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:9067 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:9072 process_sdp: We have an owner, now see if we need to change this call
[Jan 26 14:33:42] DEBUG[5830]: channel.c:5146 set_format: Set channel SIP/20-00000041 to read format g722
[Jan 26 14:33:42] DEBUG[5830]: channel.c:5146 set_format: Set channel SIP/20-00000041 to write format g722
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:5755 update_call_counter: Updating call counter for incoming call
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 20
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:42] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 20
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/20 - state 2 (In use)
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/20' state '2'
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'ACK sip:20@' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:42] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/20' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (Checking To) --From tag as7309ca20 --To-tag 960312401
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:3980 __sip_ack: Acked pending invite 103
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' of Request 103: Match Found
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:19423 handle_response_invite: SIP response 200 to RE-invite on outgoing call 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP o=MxSIP 0 1 IN IP4 10.78.65.153... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153' into...
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port ''.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP c=IN IP4 10.78.65.153... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb6e0ca54
[Jan 26 14:33:42] DEBUG[5830]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1073f5f0'
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6e0ca54 to 0x1073f79c
[Jan 26 14:33:42] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6e0ca54 to 0x1073f79c
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:9067 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:9072 process_sdp: We have an owner, now see if we need to change this call
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:5755 update_call_counter: Updating call counter for outgoing call
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:42] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 2 (In use)
[Jan 26 14:33:42] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '2'
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:42] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'ACK sip:11@' onto UDP socket destined for 10.78.65.153:5060
[Jan 26 14:33:42] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:42] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:42] DEBUG[7092]: chan_sip.c:7234 sip_rtp_read: Bogus frame of format 'g722' received from 'SIP/20-00000041'!
[Jan 26 14:33:43] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:43] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:44] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:44] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:44] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:44] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:45] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:45] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:7536 sip_alloc: Allocating new SIP dialog for 6094eb3570b29127725419d41ff7eef9@10.78.65.80:5060 - OPTIONS (No RTP)
[Jan 26 14:33:46] DEBUG[5830]: acl.c:725 ast_ouraddrfor: For destination '192.168.1.20', our source address is '10.78.65.80'.
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:3486 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.78.65.80:5060
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:3061 initialize_initreq: Initializing initreq for method OPTIONS - callid 351b95e9089dc1002ac2233c77e06b32@10.78.65.80:5060
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.20:5060
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 351b95e9089dc1002ac2233c77e06b32@10.78.65.80:5060 (Checking To) --From tag as0bc132e0 --To-tag t-181e9f2054310d712ca
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '351b95e9089dc1002ac2233c77e06b32@10.78.65.80:5060' of Request 102: Match Found
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 351b95e9089dc1002ac2233c77e06b32@10.78.65.80:5060
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:46] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:47] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:47] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:48] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:48] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:49] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:49] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:49] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:49] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:7536 sip_alloc: Allocating new SIP dialog for 2e409bcf7384dbaa667e015c7a14e3c3@10.78.65.80:5060 - OPTIONS (No RTP)
[Jan 26 14:33:50] DEBUG[5830]: acl.c:725 ast_ouraddrfor: For destination '10.78.65.151', our source address is '10.78.65.80'.
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:3486 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.78.65.80:5060
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:3061 initialize_initreq: Initializing initreq for method OPTIONS - callid 7f4802f418daf6bf7c75149b0ae61109@10.78.65.80:5060
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.78.65.151:5063
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 7f4802f418daf6bf7c75149b0ae61109@10.78.65.80:5060 (Checking To) --From tag as6d0b5b2f --To-tag 420713463
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '7f4802f418daf6bf7c75149b0ae61109@10.78.65.80:5060' of Request 102: Match Found
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:50] DEBUG[5830]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 7f4802f418daf6bf7c75149b0ae61109@10.78.65.80:5060
[Jan 26 14:33:51] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:51] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:51] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:51] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:7536 sip_alloc: Allocating new SIP dialog for 50491f2f5836e275418bf67f598859cb@10.78.65.80:5060 - OPTIONS (No RTP)
[Jan 26 14:33:52] DEBUG[5830]: acl.c:725 ast_ouraddrfor: For destination '10.78.65.152', our source address is '10.78.65.80'.
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:3486 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.78.65.80:5060
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:3061 initialize_initreq: Initializing initreq for method OPTIONS - callid 5ef4f8e579f1a057309771b64aafc96f@10.78.65.80:5060
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 5ef4f8e579f1a057309771b64aafc96f@10.78.65.80:5060 (Checking To) --From tag as496ebfe8 --To-tag 446822349
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '5ef4f8e579f1a057309771b64aafc96f@10.78.65.80:5060' of Request 102: Match Found
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:52] DEBUG[5830]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 5ef4f8e579f1a057309771b64aafc96f@10.78.65.80:5060
[Jan 26 14:33:53] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:53] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:54] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:54] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:54] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:54] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:55] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:55] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3876 __sip_autodestruct: Auto destroying SIP dialog '7a5b3bc3735e3cd2782ddcdb6879980e@netforce.ath.cx'
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 7a5b3bc3735e3cd2782ddcdb6879980e@netforce.ath.cx
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: INVITE
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060 (Checking From) --From tag 960312401 --To-tag as7309ca20
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:24571 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.153:5060' into...
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.153' and port '5060'.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3074 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060
[Jan 26 14:33:56] DEBUG[5830]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1073f5f0'
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:23379 handle_request_bye: Received bye, issuing owner hangup
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.78.65.153:5060
[Jan 26 14:33:56] DEBUG[7092]: rtp_engine.c:1133 remote_bridge_loop: Oooh, got a hangup
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '1688579688@10.78.65.152' Method: ACK
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:16457 dialog_needdestroy: Bridge still active.  Delaying destroy of SIP dialog '56618d3048debc4863aa8c3b6343ea79@10.78.65.80:5060' Method: BYE
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:28667 sip_set_rtp_peer: Sending reinvite on SIP '1688579688@10.78.65.152' - It's audio soon redirected to IP 10.78.65.80:5060
[Jan 26 14:33:56] DEBUG[7092]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:56] DEBUG[7092]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:11033 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:11034 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:11143 add_sdp: -- Done with adding codecs to SDP
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:11282 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:3059 initialize_initreq: Initializing already initialized SIP dialog 1688579688@10.78.65.152 (presumably reinvite)
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:3332 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:56] DEBUG[7092]: channel.c:7399 ast_channel_bridge: Returning from native bridge, channels: SIP/20-00000041, SIP/11-00000042
[Jan 26 14:33:56] DEBUG[7092]: channel.c:2819 ast_hangup: Hanging up channel 'SIP/11-00000042'
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:6126 sip_hangup: Hanging up zombie call. Be scared.
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:5755 update_call_counter: Updating call counter for outgoing call
[Jan 26 14:33:56] DEBUG[7092]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x1073f5f0'
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
[Jan 26 14:33:56] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 1 (Not in use)
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '1'
[Jan 26 14:33:56] DEBUG[7092]: app_dial.c:2901 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 11
[Jan 26 14:33:56] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 11
[Jan 26 14:33:56] DEBUG[7092]: app_macro.c:429 _macro_exec: Spawn extension (macro-internanruf,execute_call,24) exited non-zero on 'SIP/20-00000041' in macro 'internanruf'
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/11 - state 1 (Not in use)
  == Spawn extension (macro-internanruf, execute_call, 24) exited non-zero on 'SIP/20-00000041' in macro 'internanruf'
[Jan 26 14:33:56] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/11' state '1'
[Jan 26 14:33:56] DEBUG[7092]: pbx.c:4902 __ast_pbx_run: Spawn extension (internal-direct,11,2) exited non-zero on 'SIP/20-00000041'
[Jan 26 14:33:56] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/11' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
  == Spawn extension (internal-direct, 11, 2) exited non-zero on 'SIP/20-00000041'
[Jan 26 14:33:56] DEBUG[5805]: app_queue.c:1588 extension_state_cb: Extension '11@autohint' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[7092]: channel.c:2679 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/20-00000041'
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:56] DEBUG[7092]: channel.c:2819 ast_hangup: Hanging up channel 'SIP/20-00000041'
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:6126 sip_hangup: Hanging up zombie call. Be scared.
[Jan 26 14:33:56] DEBUG[7092]: chan_sip.c:5755 update_call_counter: Updating call counter for incoming call
[Jan 26 14:33:56] DEBUG[7092]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x106a4db8'
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 20
[Jan 26 14:33:56] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 20
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/20 - state 1 (Not in use)
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/20' state '1'
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:4059 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1688579688@10.78.65.152' Request 103: Found
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:19425 handle_response_invite: SIP response 100 to standard invite
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 20
[Jan 26 14:33:56] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 20
[Jan 26 14:33:56] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/20' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/20 - state 1 (Not in use)
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/20' state '1'
[Jan 26 14:33:56] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/20' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[5805]: app_queue.c:1588 extension_state_cb: Extension '20@autohint' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[5805]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:56] DEBUG[5805]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:56] DEBUG[5805]: chan_sip.c:3332 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.78.65.152:5062
  == Extension Changed 20[autohint] new state Idle for Notify User 20
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3980 __sip_ack: Acked pending invite 103
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '1688579688@10.78.65.152' of Request 103: Match Found
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:19425 handle_response_invite: SIP response 200 to standard invite
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP v=0... UNSUPPORTED.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP o=- 20014 20016 IN IP4 10.78.65.152... UNSUPPORTED.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP s=SDP data... UNSUPPORTED.
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152' into...
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port ''.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP c=IN IP4 10.78.65.152... OK.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8647 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb6e0ca54
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb6e0ca54
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:8834 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0xb6e0ca54
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb6e0ca54
[Jan 26 14:33:56] DEBUG[5830]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x106a4db8'
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb6e0ca54 to 0x106a4f64
[Jan 26 14:33:56] DEBUG[5830]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb6e0ca54 to 0x106a4f64
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:9067 process_sdp: We're settling with these formats: 0x8 (alaw)
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:5755 update_call_counter: Updating call counter for incoming call
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:13726 build_route: build_route: Retaining previous route: <sip:20@10.78.65.152:5062>
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 20
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:56] DEBUG[5804]: chan_sip.c:25831 sip_devicestate: Checking device state for peer 20
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:458 do_state_change: Changing state for SIP/20 - state 1 (Not in use)
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:56] DEBUG[5804]: devicestate.c:438 devstate_event: device 'SIP/20' state '1'
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'ACK sip:20@' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.78.65.152:5062' into...
[Jan 26 14:33:56] DEBUG[5830]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.78.65.152' and port '5062'.
[Jan 26 14:33:56] DEBUG[5843]: app_queue.c:1493 handle_statechange: Device 'SIP/20' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 14:33:56] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'BYE sip:20@' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #5352))
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #5353))
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:3332 __sip_xmit: Trying to put 'BYE sip:20@' onto UDP socket destined for 10.78.65.152:5062
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 986471660@10.78.65.152 (Checking To) --From tag as5289a8a2 --To-tag 309382739
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:3980 __sip_ack: Acked pending invite 166
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '986471660@10.78.65.152' of Request 166: Match Found
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '1688579688@10.78.65.152' of Request 104: Match Found
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 1688579688@10.78.65.152
[Jan 26 14:33:57] DEBUG[5830]: rtp_engine.c:293 instance_destructor: Destroyed RTP instance '0x106a4db8'
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 986471660@10.78.65.152 (Checking To) --From tag as5289a8a2 --To-tag 309382739
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:4018 __sip_ack: Stopping retransmission on '986471660@10.78.65.152' of Request 166: Match Not Found
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:7856 find_call: = Looking for  Call ID: 1688579688@10.78.65.152 (Checking To) --From tag as18adc4b6 --To-tag 47411633
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:7975 find_call: That's odd...  Got a response on a call we don't know about. Callid 1688579688@10.78.65.152
[Jan 26 14:33:57] DEBUG[5830]: chan_sip.c:24814 handle_request_do: Invalid SIP message - rejected , no callid, len 270