[Jan 12 16:12:33] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:33] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 1 (Not in use)
[Jan 12 16:12:33] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 60e875545b5315473a1ccf4f75e018f8@192.168.1.200:5060 (Checking To) --From tag as21b08cd4 --To-tag 8386  
[Jan 12 16:12:33] DEBUG[31416][C-00000004] chan_sip.c: Stopping retransmission on '60e875545b5315473a1ccf4f75e018f8@192.168.1.200:5060' of Request 103: Match Found
[Jan 12 16:12:33] DEBUG[31416] chan_sip.c: Destroying SIP dialog 60e875545b5315473a1ccf4f75e018f8@192.168.1.200:5060
[Jan 12 16:12:33] DEBUG[31416] rtp_engine.c: Destroyed RTP instance '0x9530404'
[Jan 12 16:12:33] DEBUG[31390] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"1003" <1003>','1003','2001','main','SIP/1003-00000007','SIP/1001-00000008','Dial','SIP/1001,,rotwh','2015-01-12 16:12:19','2015-01-12 16:12:22','2015-01-12 16:12:33','13','11','ANSWERED','DOCUMENTATION','1421079139.15')
[Jan 12 16:12:33] DEBUG[31390] cdr.c: CDR for SIP/1001-00000008 is dialed and has no Party B; discarding
[Jan 12 16:12:33] DEBUG[31416] chan_sip.c: Auto destroying SIP dialog '8d1fc999ea0a67f15a0@192.168.1.20'
[Jan 12 16:12:33] DEBUG[31416] chan_sip.c: Destroying SIP dialog 8d1fc999ea0a67f15a0@192.168.1.20
[Jan 12 16:12:41] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 8d1fc99b69468e415b0@192.168.1.20 (Checking From) --From tag 8d1fc99b69468e415af --To-tag   
[Jan 12 16:12:41] DEBUG[31416] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'.
[Jan 12 16:12:41] DEBUG[31416] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: Splitting '192.168.1.20:5060' into...
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: ...host '192.168.1.20' and port '5060'.
[Jan 12 16:12:41] DEBUG[31416] chan_sip.c: Allocating new SIP dialog for 8d1fc99b69468e415b0@192.168.1.20 - OPTIONS (No RTP)
[Jan 12 16:12:41] DEBUG[31416] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:41] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:41] DEBUG[31416] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.1.20:5060
[Jan 12 16:12:43] DEBUG[31416] chan_sip.c: Auto destroying SIP dialog '8d1fc99a49f948715a3@192.168.1.20'
[Jan 12 16:12:43] DEBUG[31416] chan_sip.c: Destroying SIP dialog 8d1fc99a49f948715a3@192.168.1.20
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: = Looking for  Call ID: NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI (Checking From) --From tag 2d856d6d --To-tag   
[Jan 12 16:12:44] DEBUG[31416] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'.
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: Splitting '192.168.1.20:6436' into...
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: ...host '192.168.1.20' and port '6436'.
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: Allocating new SIP dialog for NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI - INVITE (No RTP)
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 12 16:12:44] DEBUG[31416][C-00000005] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces"
[Jan 12 16:12:44] DEBUG[31416][C-00000005] sip/reqresp_parser.c: Found SIP option: -replaces-
[Jan 12 16:12:44] DEBUG[31416][C-00000005] sip/reqresp_parser.c: Matched SIP option: replaces
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20:6436' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port '6436'.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.20:6436
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: = Looking for  Call ID: NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI (Checking From) --From tag 2d856d6d --To-tag as2e9e238f  
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Stopping retransmission on 'NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI' of Response 1: Match Found
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: = Looking for  Call ID: NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI (Checking From) --From tag 2d856d6d --To-tag   
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20:6436' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port '6436'.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x9530404'
[Jan 12 16:12:44] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Allocated port 16040 for RTP instance '0x9530404'
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: RTP instance '0x9530404' is setup and ready to go
[Jan 12 16:12:44] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x9530404'
[Jan 12 16:12:44] VERBOSE[31416][C-00000005] netsock2.c: Using SIP RTP CoS mark 5
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Setting NAT on RTP to Off
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP o=- 13065552758555057 1 IN IP4 192.168.1.20... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP s=X-Lite release 4.7.1 stamp 74247... UNSUPPORTED OR FAILED.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.20... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 125 (0x973d174) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 100 (0x97c8ee4) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 0 (0x9f5614c) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 9 (0x9f2836c) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 8 (0x9e72d9c) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 101 (0x9e85a2c) based on m type on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:125 opus/48000/2... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Unsetting payload 125 on 0xb4b0fbe0
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:125 useinbandfec=1... UNSUPPORTED OR FAILED.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 speex/16000... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9530404'
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 0 (0x9f5614c) from 0xb4b0fbe0 to 0x953052c
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 8 (0x9e72d9c) from 0xb4b0fbe0 to 0x953052c
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 9 (0x9f2836c) from 0xb4b0fbe0 to 0x953052c
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 100 (0x97f0474) from 0xb4b0fbe0 to 0x953052c
[Jan 12 16:12:44] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 101 (0x974974c) from 0xb4b0fbe0 to 0x953052c
[Jan 12 16:12:44] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x9530404'
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: We're settling with these formats: (alaw)
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Checking SIP call limits for device 1003
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Updating call counter for incoming call
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1003
[Jan 12 16:12:44] DEBUG[31389] chan_sip.c: Checking device state for peer 1003
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: Changing state for SIP/1003 - state 2 (In use)
[Jan 12 16:12:44] DEBUG[31446] app_queue.c: Device 'SIP/1003' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:44] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: *** Our native formats are (alaw) 
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) 
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: *** Our capabilities are (alaw) 
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: This channel will not be able to handle video.
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: SIP/1003-00000009: New call is still down.... Trying... 
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.20:6436
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1003
[Jan 12 16:12:44] DEBUG[31389] chan_sip.c: Checking device state for peer 1003
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: Changing state for SIP/1003 - state 2 (In use)
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2001'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Launching 'NoOp'
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] pbx.c: Executing [2001@main:1] NoOp("SIP/1003-00000009", "This is the first priority of 2001") in new stack
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2001'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2001'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Launching 'NoOp'
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] pbx.c: Executing [2001@main:2] NoOp("SIP/1003-00000009", "This is the second priority of 2001 - about to dial SIP/1001") in new stack
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2001'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] pbx.c: Launching 'Dial'
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] pbx.c: Executing [2001@main:3] Dial("SIP/1003-00000009", "SIP/1001,,rotwh") in new stack
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Asked to create a SIP channel with formats: (alaw)
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Allocating new SIP dialog for 71be18cf0f4e984f3e38a8bb5603a5d3@192.168.1.200:5060 - INVITE (No RTP)
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa027664'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Allocated port 19038 for RTP instance '0xa027664'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: RTP instance '0xa027664' is setup and ready to go
[Jan 12 16:12:44] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa027664'
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] netsock2.c: Using SIP RTP CoS mark 5
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Setting NAT on RTP to Off
[Jan 12 16:12:44] DEBUG[31494][C-00000005] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'.
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060
[Jan 12 16:12:44] DEBUG[31494][C-00000005] netsock2.c: Splitting '192.168.1.20:5070' into...
[Jan 12 16:12:44] DEBUG[31494][C-00000005] netsock2.c: ...host '192.168.1.20' and port '5070'.
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Setting NAT on RTP to Off
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: SIP call-id changed from '71be18cf0f4e984f3e38a8bb5603a5d3@192.168.1.200:5060' to '50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: *** Our native formats are (alaw) 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: *** Our capabilities are (alaw) 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: This channel will not be able to handle video.
[Jan 12 16:12:44] DEBUG[31494][C-00000005] channel_internal_api.c: Channel Call ID changing from [C-00000005] to [C-00000005]
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 0 (0x9f5614c) from 0x953052c to 0xa02778c
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 8 (0x9e72d9c) from 0x953052c to 0xa02778c
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 9 (0x9f2836c) from 0x953052c to 0xa02778c
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 100 (0x97f0474) from 0x953052c to 0xa02778c
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 101 (0x974974c) from 0x953052c to 0xa02778c
[Jan 12 16:12:44] DEBUG[31494][C-00000005] rtp_engine.c: Seeded SDP of 'SIP/1001-0000000a' with that of 'SIP/1003-00000009'
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Outgoing Call for 1001
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Updating call counter for outgoing call
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:44] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 6 (Ringing)
[Jan 12 16:12:44] DEBUG[31446] app_queue.c: Device 'SIP/1001' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: ** Our prefcodec: (alaw) 
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: -- Done with adding codecs to SDP
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.20:5070
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] app_dial.c: Called SIP/1001
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.20:6436
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060 (Checking To) --From tag as79bb421f --To-tag 8387  
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060' Request 102: Found
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: SIP response 180 to standard invite
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:44] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:44] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 6 (Ringing)
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] app_dial.c: SIP/1001-0000000a is ringing
[Jan 12 16:12:44] DEBUG[31494][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.20:6436
[Jan 12 16:12:44] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060 (Checking To) --From tag as79bb421f --To-tag 8387  
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060' Request 102: Found
[Jan 12 16:12:44] DEBUG[31416][C-00000005] chan_sip.c: SIP response 180 to standard invite
[Jan 12 16:12:44] VERBOSE[31494][C-00000005] app_dial.c: SIP/1001-0000000a is ringing
[Jan 12 16:12:46] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060 (Checking To) --From tag as79bb421f --To-tag 8387  
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Acked pending invite 102
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Stopping retransmission on '50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060' of Request 102: Match Found
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: SIP response 200 to standard invite
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP o=NCHSoftware-Talk 1420242493 1420242589 IN IP4 192.168.1.20... OK.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP s=Express Talk Call... UNSUPPORTED OR FAILED.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20' into...
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port ''.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.20... OK.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 8 (0x9e81984) based on m type on 0xb4b0ec60
[Jan 12 16:12:46] DEBUG[31416][C-00000005] rtp_engine.c: Setting payload 101 (0x94e825c) based on m type on 0xb4b0ec60
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa027664'
[Jan 12 16:12:46] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 8 (0x9f53bc4) from 0xb4b0ec60 to 0xa02778c
[Jan 12 16:12:46] DEBUG[31416][C-00000005] rtp_engine.c: Copying payload 101 (0x951fe54) from 0xb4b0ec60 to 0xa02778c
[Jan 12 16:12:46] DEBUG[31416][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xa027664'
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: We're settling with these formats: (alaw)
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: We have an owner, now see if we need to change this call
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Updating call counter for outgoing call
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20:5070' into...
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port '5070'.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: Splitting '192.168.1.20:5070' into...
[Jan 12 16:12:46] DEBUG[31416][C-00000005] netsock2.c: ...host '192.168.1.20' and port '5070'.
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Trying to put 'ACK sip:100' onto UDP socket destined for 192.168.1.20:5070
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:46] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 2 (In use)
[Jan 12 16:12:46] DEBUG[31446] app_queue.c: Device 'SIP/1001' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] channel.c: SIP/1003-00000009: Dropping redundant connected line update "1001" <1001>.
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:46] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 2 (In use)
[Jan 12 16:12:46] VERBOSE[31494][C-00000005] app_dial.c: SIP/1001-0000000a answered SIP/1003-00000009
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1003
[Jan 12 16:12:46] DEBUG[31389] chan_sip.c: Checking device state for peer 1003
[Jan 12 16:12:46] DEBUG[31389] devicestate.c: Changing state for SIP/1003 - state 2 (In use)
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: SIP answering channel: SIP/1003-00000009
[Jan 12 16:12:46] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: Setting framing from config on incoming call
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: ** Our prefcodec: (nothing) 
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: -- Done with adding codecs to SDP
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[Jan 12 16:12:46] DEBUG[31494][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.20:6436
[Jan 12 16:12:46] DEBUG[31494][C-00000005] features.c: Removing dialed interfaces datastore on SIP/1001-0000000a since we're bridging
[Jan 12 16:12:46] DEBUG[31494][C-00000005] dahdi/bridge_native_dahdi.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: Cannot use native DAHDI.  Must have two channels.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge_native_rtp.c: Bridge '71c50b04-0420-4d33-b567-5932e8734ce6' can not use native RTP bridge as two channels are required
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Chose bridge technology simple_bridge
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: calling simple_bridge technology constructor
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: calling simple_bridge technology start
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x950b5ac(SIP/1003-00000009) is joining
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: pushing 0x950b5ac(SIP/1003-00000009)
[Jan 12 16:12:46] VERBOSE[31494][C-00000005] bridge_channel.c: Channel SIP/1003-00000009 joined 'simple_bridge' basic-bridge <71c50b04-0420-4d33-b567-5932e8734ce6>
[Jan 12 16:12:46] DEBUG[31494][C-00000005] dahdi/bridge_native_dahdi.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: Cannot use native DAHDI.  Must have two channels.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge_native_rtp.c: Bridge '71c50b04-0420-4d33-b567-5932e8734ce6' can not use native RTP bridge as two channels are required
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Chose bridge technology simple_bridge
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is already using the new technology.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is happy that channel SIP/1003-00000009 already has read format alaw
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is happy that channel SIP/1003-00000009 already has write format alaw
[Jan 12 16:12:46] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x950b5ac(SIP/1003-00000009) is joining simple_bridge technology
[Jan 12 16:12:46] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x9e4a2dc(SIP/1001-0000000a) is joining
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: pushing 0x9e4a2dc(SIP/1001-0000000a)
[Jan 12 16:12:46] VERBOSE[31495][C-00000005] bridge_channel.c: Channel SIP/1001-0000000a joined 'simple_bridge' basic-bridge <71c50b04-0420-4d33-b567-5932e8734ce6>
[Jan 12 16:12:46] DEBUG[31390] cdr.c: Finalized CDR for SIP/1001-0000000a - start 1421079164.328988 answer 1421079166.082798 end 1421079166.087864 dispo ANSWERED
[Jan 12 16:12:46] DEBUG[31495][C-00000005] dahdi/bridge_native_dahdi.c: Channel 'SIP/1003-00000009' is not DAHDI.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] dahdi/bridge_native_dahdi.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: Cannot use native DAHDI.  Channel 'SIP/1003-00000009' not compatible.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge_native_rtp.c: Bridge '71c50b04-0420-4d33-b567-5932e8734ce6' can not use native RTP bridge as channel 'SIP/1001-0000000a' has DTMF hooks
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Chose bridge technology simple_bridge
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is already using the new technology.
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is happy that channel SIP/1001-0000000a already has read format alaw
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is happy that channel SIP/1001-0000000a already has write format alaw
[Jan 12 16:12:46] DEBUG[31495][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x9e4a2dc(SIP/1001-0000000a) is joining simple_bridge technology
[Jan 12 16:12:46] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet
[Jan 12 16:12:46] DEBUG[31416] chan_sip.c: = Looking for  Call ID: NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI (Checking From) --From tag 2d856d6d --To-tag as5e7114ab  
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 12 16:12:46] DEBUG[31416][C-00000005] chan_sip.c: Stopping retransmission on 'NTliNWI5M2FiMTQxMTUzOWQ1YmJkZTFhNzJiMWYyYjI' of Response 2: Match Found
[Jan 12 16:12:46] DEBUG[31494][C-00000005] res_rtp_asterisk.c: 0x9ef7750 -- Probation learning mode pass with source address 192.168.1.20:54834
[Jan 12 16:12:46] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Ooh, format changed from none to alaw
[Jan 12 16:12:46] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xa027664'
[Jan 12 16:12:46] DEBUG[31495][C-00000005] res_rtp_asterisk.c: 0x9f030a0 -- Probation learning mode pass with source address 192.168.1.20:8000
[Jan 12 16:12:46] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Ooh, format changed from none to alaw
[Jan 12 16:12:46] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jan 12 16:12:46] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] netsock2.c: Splitting 'dusty' into...
[Jan 12 16:12:46] DEBUG[31494][C-00000005] netsock2.c: ...host 'dusty' and port ''.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:46] DEBUG[31494][C-00000005] acl.c: Attached to given IP address
[Jan 12 16:12:46] DEBUG[31444] netsock2.c: Splitting '192.168.1.20:54835' into...
[Jan 12 16:12:46] DEBUG[31444] netsock2.c: ...host '192.168.1.20' and port '54835'.
[Jan 12 16:12:46] DEBUG[31444] netsock2.c: Splitting '192.168.1.200:0' into...
[Jan 12 16:12:46] DEBUG[31444] netsock2.c: ...host '192.168.1.200' and port '0'.
[Jan 12 16:12:47] DEBUG[31416] chan_sip.c: Auto destroying SIP dialog '06A4ABE0BFA14C14B4149D13FBC14DC40xc0a80114'
[Jan 12 16:12:47] DEBUG[31416] chan_sip.c: Destroying SIP dialog 06A4ABE0BFA14C14B4149D13FBC14DC40xc0a80114
[Jan 12 16:12:47] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 35 (#), at 192.168.1.20:8000
[Jan 12 16:12:47] DTMF[31495][C-00000005] channel.c: DTMF begin '#' received on SIP/1001-0000000a
[Jan 12 16:12:47] DTMF[31495][C-00000005] channel.c: DTMF begin passthrough '#' on SIP/1001-0000000a
[Jan 12 16:12:47] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 12 16:12:47] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 35 (#), at 192.168.1.20:8000
[Jan 12 16:12:47] DTMF[31495][C-00000005] channel.c: DTMF end '#' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:47] DTMF[31495][C-00000005] channel.c: DTMF end accepted with begin '#' on SIP/1001-0000000a
[Jan 12 16:12:47] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '#' on SIP/1001-0000000a
[Jan 12 16:12:47] DEBUG[31495][C-00000005] bridge_channel.c: DTMF feature string on 0x9e4a2dc(SIP/1001-0000000a) is now '#'
[Jan 12 16:12:48] NOTICE[31494][C-00000005] res_rtp_asterisk.c: Unknown RTP codec 126 received from '192.168.1.20:54834'
[Jan 12 16:12:48] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 49 (1), at 192.168.1.20:8000
[Jan 12 16:12:48] DTMF[31495][C-00000005] channel.c: DTMF begin '1' received on SIP/1001-0000000a
[Jan 12 16:12:48] DTMF[31495][C-00000005] channel.c: DTMF begin ignored '1' on SIP/1001-0000000a
[Jan 12 16:12:48] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 49 (1), at 192.168.1.20:8000
[Jan 12 16:12:48] DTMF[31495][C-00000005] channel.c: DTMF end '1' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:48] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '1' on SIP/1001-0000000a
[Jan 12 16:12:48] DEBUG[31495][C-00000005] bridge_channel.c: DTMF feature string on 0x9e4a2dc(SIP/1001-0000000a) is now '#1'
[Jan 12 16:12:48] DEBUG[31495][C-00000005] bridge_channel.c: DTMF feature hook 0x96d2ffc matched DTMF string '#1' on 0x9e4a2dc(SIP/1001-0000000a)
[Jan 12 16:12:48] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 12 16:12:48] VERBOSE[31494][C-00000005] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/1003-00000009'
[Jan 12 16:12:48] DEBUG[31494][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 12 16:12:48] DEBUG[31495][C-00000005] channel.c: Set channel SIP/1001-0000000a to write format gsm
[Jan 12 16:12:48] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Difference is 8664, ms is 1103
[Jan 12 16:12:48] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 12 16:12:48] VERBOSE[31495][C-00000005] file.c: <SIP/1001-0000000a> Playing 'pbx-transfer.gsm' (language 'en')
[Jan 12 16:12:48] DEBUG[31494][C-00000005] channel.c: Set channel SIP/1003-00000009 to write format slin
[Jan 12 16:12:48] DEBUG[31494][C-00000005] res_musiconhold.c: SIP/1003-00000009 Opened file 0 '/var/lib/asterisk/moh/OrderlyQ/unity'
[Jan 12 16:12:48] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Difference is 8744, ms is 1113
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Set channel SIP/1001-0000000a to write format alaw
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Set channel SIP/1001-0000000a to write format slin
[Jan 12 16:12:49] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 12 16:12:50] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 50 (2), at 192.168.1.20:8000
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF begin '2' received on SIP/1001-0000000a
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF begin ignored '2' on SIP/1001-0000000a
[Jan 12 16:12:50] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 50 (2), at 192.168.1.20:8000
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF end '2' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '2' on SIP/1001-0000000a
[Jan 12 16:12:50] DEBUG[31495][C-00000005] channel.c: Set channel SIP/1001-0000000a to write format alaw
[Jan 12 16:12:50] DEBUG[31495][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 12 16:12:50] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.1.20:8000
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF begin '0' received on SIP/1001-0000000a
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF begin ignored '0' on SIP/1001-0000000a
[Jan 12 16:12:50] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.1.20:8000
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF end '0' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:50] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '0' on SIP/1001-0000000a
[Jan 12 16:12:51] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jan 12 16:12:51] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] netsock2.c: Splitting 'dusty' into...
[Jan 12 16:12:51] DEBUG[31494][C-00000005] netsock2.c: ...host 'dusty' and port ''.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] acl.c: Attached to given IP address
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.20:54835' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.20' and port '54835'.
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.200:0' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.200' and port '0'.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 48 (0), at 192.168.1.20:8000
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF begin '0' received on SIP/1001-0000000a
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF begin ignored '0' on SIP/1001-0000000a
[Jan 12 16:12:51] DEBUG[31416] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: Splitting 'dusty' into...
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: ...host 'dusty' and port ''.
[Jan 12 16:12:51] DEBUG[31416] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31416] acl.c: Attached to given IP address
[Jan 12 16:12:51] DEBUG[31416] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: Splitting 'dusty' into...
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: ...host 'dusty' and port ''.
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.200:0' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.200' and port '0'.
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.20:54835' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.20' and port '54835'.
[Jan 12 16:12:51] DEBUG[31416] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:51] DEBUG[31416] acl.c: Attached to given IP address
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.200:0' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.200' and port '0'.
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: Splitting '192.168.1.20:8001' into...
[Jan 12 16:12:51] DEBUG[31444] netsock2.c: ...host '192.168.1.20' and port '8001'.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 48 (0), at 192.168.1.20:8000
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF end '0' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '0' on SIP/1001-0000000a
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 53 (5), at 192.168.1.20:8000
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF begin '5' received on SIP/1001-0000000a
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF begin ignored '5' on SIP/1001-0000000a
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 8d1fc99bc93d17615b3@192.168.1.20 (Checking From) --From tag 8d1fc99bc93d17615b2 --To-tag   
[Jan 12 16:12:51] DEBUG[31416] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'.
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: Splitting '192.168.1.20:5060' into...
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: ...host '192.168.1.20' and port '5060'.
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: Allocating new SIP dialog for 8d1fc99bc93d17615b3@192.168.1.20 - OPTIONS (No RTP)
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: Splitting '192.168.1.200' into...
[Jan 12 16:12:51] DEBUG[31416] netsock2.c: ...host '192.168.1.200' and port ''.
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.1.20:5060
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 53 (5), at 192.168.1.20:8000
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF end '5' received on SIP/1001-0000000a, duration 200 ms
[Jan 12 16:12:51] DTMF[31495][C-00000005] channel.c: DTMF end passthrough '5' on SIP/1001-0000000a
[Jan 12 16:12:51] DEBUG[31495][C-00000005] parking/parking_bridge_features.c: Checking if 2005@main is a parking exten
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge_channel.c: Setting 0x9e4a2dc(SIP/1001-0000000a) state from:0 to:2
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: pulling 0x9e4a2dc(SIP/1001-0000000a)
[Jan 12 16:12:51] VERBOSE[31495][C-00000005] bridge_channel.c: Channel SIP/1001-0000000a left 'simple_bridge' basic-bridge <71c50b04-0420-4d33-b567-5932e8734ce6>
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x9e4a2dc(SIP/1001-0000000a) is leaving simple_bridge technology
[Jan 12 16:12:51] DEBUG[31495][C-00000005] dahdi/bridge_native_dahdi.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: Cannot use native DAHDI.  Must have two channels.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Bridge technology holding_bridge does not have any capabilities we want.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Bridge technology softmix does not have any capabilities we want.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge_native_rtp.c: Bridge '71c50b04-0420-4d33-b567-5932e8734ce6' can not use native RTP bridge as two channels are required
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Chose bridge technology simple_bridge
[Jan 12 16:12:51] DEBUG[31495][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is already using the new technology.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Changing ssrc from 83056439 to 334479466 due to a source change
[Jan 12 16:12:51] DEBUG[31495][C-00000005] channel.c: Hanging up channel 'SIP/1001-0000000a'
[Jan 12 16:12:51] DEBUG[31495][C-00000005] chan_sip.c: Hangup call SIP/1001-0000000a, SIP callid 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060
[Jan 12 16:12:51] DEBUG[31495][C-00000005] chan_sip.c: Updating call counter for outgoing call
[Jan 12 16:12:51] DEBUG[31495][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa027664'
[Jan 12 16:12:51] DEBUG[31495][C-00000005] netsock2.c: Splitting '192.168.1.20:5070' into...
[Jan 12 16:12:51] DEBUG[31495][C-00000005] netsock2.c: ...host '192.168.1.20' and port '5070'.
[Jan 12 16:12:51] DEBUG[31495][C-00000005] chan_sip.c: Trying to put 'BYE sip:100' onto UDP socket destined for 192.168.1.20:5070
[Jan 12 16:12:51] DEBUG[31390] cdr.c: Finalized CDR for SIP/1003-00000009 - start 1421079164.322130 answer 1421079166.083700 end 1421079171.769600 dispo ANSWERED
[Jan 12 16:12:51] DEBUG[31390] cdr.c: CDR for SIP/1001-0000000a is dialed and has no Party B; discarding
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:51] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 1 (Not in use)
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1001
[Jan 12 16:12:51] DEBUG[31389] chan_sip.c: Checking device state for peer 1001
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: Changing state for SIP/1001 - state 1 (Not in use)
[Jan 12 16:12:51] DEBUG[31446] app_queue.c: Device 'SIP/1001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] res_musiconhold.c: Stopped music on hold on SIP/1003-00000009
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Set channel SIP/1003-00000009 to write format alaw
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Soft-Hanging (0x02) up channel 'SIP/1003-00000009'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge_channel.c: Setting 0x950b5ac(SIP/1003-00000009) state from:0 to:1
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: pulling 0x950b5ac(SIP/1003-00000009)
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] bridge_channel.c: Channel SIP/1003-00000009 left 'simple_bridge' basic-bridge <71c50b04-0420-4d33-b567-5932e8734ce6>
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge_channel.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: 0x950b5ac(SIP/1003-00000009) is leaving simple_bridge technology
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: dissolving bridge with cause 16(Normal Clearing)
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: queueing action type:13 sub:1001
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6 is dissolved, not performing smart bridge operation.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: actually destroying basic bridge, nobody wants it anymore
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: calling basic bridge destructor
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: calling simple_bridge technology stop
[Jan 12 16:12:51] DEBUG[31494][C-00000005] bridge.c: Bridge 71c50b04-0420-4d33-b567-5932e8734ce6: calling simple_bridge technology destructor
[Jan 12 16:12:51] DEBUG[31494][C-00000005] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2005'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Launching 'NoOp'

FAULT the Newexten event created for this line is garbage.  The correct Newexten is never sent.
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] pbx.c: Executing [2005@main:1] NoOp("SIP/1003-00000009", "This is the first priority of 2005") in new stack

[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2005'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2005'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Launching 'NoOp'
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] pbx.c: Executing [2005@main:2] NoOp("SIP/1003-00000009", "This is the second priority of 2005 - about to dial SIP/1005") in new stack
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Result of 'EXTEN' is '2005'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] pbx.c: Launching 'Dial'
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] pbx.c: Executing [2005@main:3] Dial("SIP/1003-00000009", "SIP/1005,,rotwh") in new stack
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Asked to create a SIP channel with formats: (alaw)
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Allocating new SIP dialog for 5826e9375db91e0b605cc05e51b4bd94@192.168.1.200:5060 - INVITE (No RTP)
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x96cd40c'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Allocated port 16588 for RTP instance '0x96cd40c'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: RTP instance '0x96cd40c' is setup and ready to go
[Jan 12 16:12:51] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x96cd40c'
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] netsock2.c: Using SIP RTP CoS mark 5
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Setting NAT on RTP to Off
[Jan 12 16:12:51] DEBUG[31494][C-00000005] acl.c: For destination '192.168.1.20', our source address is '192.168.1.200'.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.200:5060
[Jan 12 16:12:51] DEBUG[31494][C-00000005] netsock2.c: Splitting '192.168.1.20' into...
[Jan 12 16:12:51] DEBUG[31494][C-00000005] netsock2.c: ...host '192.168.1.20' and port ''.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Setting NAT on RTP to Off
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: SIP call-id changed from '5826e9375db91e0b605cc05e51b4bd94@192.168.1.200:5060' to '4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: *** Our native formats are (alaw) 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: *** Our capabilities are (alaw) 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw) 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: This channel will not be able to handle video.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel_internal_api.c: Channel Call ID changing from [C-00000005] to [C-00000005]
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 0 (0x9f5614c) from 0x953052c to 0x96cd534
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 8 (0x9e72d9c) from 0x953052c to 0x96cd534
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 9 (0x9f2836c) from 0x953052c to 0x96cd534
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 100 (0x97f0474) from 0x953052c to 0x96cd534
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Copying payload 101 (0x974974c) from 0x953052c to 0x96cd534
[Jan 12 16:12:51] DEBUG[31494][C-00000005] rtp_engine.c: Seeded SDP of 'SIP/1005-0000000b' with that of 'SIP/1003-00000009'
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Outgoing Call for 1005
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Updating call counter for outgoing call
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1005
[Jan 12 16:12:51] DEBUG[31389] chan_sip.c: Checking device state for peer 1005
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: Changing state for SIP/1005 - state 6 (Ringing)
[Jan 12 16:12:51] DEBUG[31446] app_queue.c: Device 'SIP/1005' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: ** Our prefcodec: (alaw) 
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: -- Done with adding codecs to SDP
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid 4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060
[Jan 12 16:12:51] DEBUG[31494][C-00000005] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.20:5060
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] app_dial.c: Called SIP/1005
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Driver for channel 'SIP/1003-00000009' does not support indication 3, emulating it
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Set channel SIP/1003-00000009 to write format slin
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060 (Checking To) --From tag as79bb421f --To-tag 8387  
[Jan 12 16:12:51] DEBUG[31416][C-00000005] chan_sip.c: Stopping retransmission on '50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060' of Request 103: Match Found
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: Destroying SIP dialog 50805e0840b40ac6495a9ca27c8f3dc0@192.168.1.200:5060
[Jan 12 16:12:51] DEBUG[31416] rtp_engine.c: Destroyed RTP instance '0xa027664'
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060 (Checking To) --From tag as6ecefe83 --To-tag   
[Jan 12 16:12:51] DEBUG[31416][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060' Request 102: Found
[Jan 12 16:12:51] DEBUG[31416][C-00000005] chan_sip.c: SIP response 100 to standard invite
[Jan 12 16:12:51] DEBUG[31416] chan_sip.c: = Looking for  Call ID: 4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060 (Checking To) --From tag as6ecefe83 --To-tag 8d1fc99bca7718e15b5  
[Jan 12 16:12:51] DEBUG[31416][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4577a80d2753d2616ec9845810adadb7@192.168.1.200:5060' Request 102: Found
[Jan 12 16:12:51] DEBUG[31416][C-00000005] chan_sip.c: SIP response 180 to standard invite
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: No provider found, checking channel drivers for SIP - 1005
[Jan 12 16:12:51] DEBUG[31389] chan_sip.c: Checking device state for peer 1005
[Jan 12 16:12:51] DEBUG[31389] devicestate.c: Changing state for SIP/1005 - state 6 (Ringing)
[Jan 12 16:12:51] VERBOSE[31494][C-00000005] app_dial.c: SIP/1005-0000000b is ringing
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Driver for channel 'SIP/1003-00000009' does not support indication 3, emulating it
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Set channel SIP/1003-00000009 to write format alaw
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Set channel SIP/1003-00000009 to write format slin
[Jan 12 16:12:51] DEBUG[31494][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jan 12 16:12:53] DEBUG[31416] chan_sip.c: Auto destroying SIP dialog '8d1fc99aa9f083b15aa@192.168.1.20'
[Jan 12 16:12:53] DEBUG[31416] chan_sip.c: Destroying SIP dialog 8d1fc99aa9f083b15aa@192.168.1.20
[Jan 12 16:12:54] DEBUG[31494][C-00000005] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jan 12 16:12:54] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:54] DEBUG[31494][C-00000005] netsock2.c: Splitting 'dusty' into...
[Jan 12 16:12:54] DEBUG[31494][C-00000005] netsock2.c: ...host 'dusty' and port ''.
[Jan 12 16:12:54] DEBUG[31494][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port.
[Jan 12 16:12:54] DEBUG[31494][C-00000005] acl.c: Attached to given IP address
[Jan 12 16:12:54] DEBUG[31444] netsock2.c: Splitting '192.168.1.20:54835' into...
[Jan 12 16:12:54] DEBUG[31444] netsock2.c: ...host '192.168.1.20' and port '54835'.
[Jan 12 16:12:54] DEBUG[31444] netsock2.c: Splitting '192.168.1.200:0' into...
[Jan 12 16:12:54] DEBUG[31444] netsock2.c: ...host '192.168.1.200' and port '0'.