[Jul 13 16:49:49] Asterisk 13.4.0 built by root @ asterisk-1 on a x86_64 running Linux on 2015-07-03 11:06:05 UTC [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag [Jul 13 16:49:53] DEBUG[10363] acl.c: For destination '192.168.1.199', our source address is '192.168.1.146'. [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.146:5060 [Jul 13 16:49:53] DEBUG[10363] netsock2.c: Splitting '192.168.1.199:52422' into... [Jul 13 16:49:53] DEBUG[10363] netsock2.c: ...host '192.168.1.199' and port '52422'. [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: Allocating new SIP dialog for 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ - INVITE (No RTP) [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.199:52422' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.199' and port '52422'. [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Connection okay. [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1001' AND host = 'dynamic' [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Connection okay. [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1001' [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #140)) [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag as57bb1683 [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Stopping retransmission on '76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ' of Response 1: Match Found [Jul 13 16:49:53] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag [Jul 13 16:49:53] DEBUG[10363] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.199:52422' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.199' and port '52422'. [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f288801bb68' [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Allocated port 10808 for RTP instance '0x7f288801bb68' [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: icess0x7f28880 ICE session created, comp_cnt=2, role is Unknown agent [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: icess0x7f28880 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80192, addr=192.168.1.146:10808, base=192.168.1.146:10808, prio=0x7effffff (2130706431) [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.122.1' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.122.1' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: icess0x7f28880 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:10808, base=192.168.122.1:10808, prio=0x7effffff (2130706431) [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: RTP instance '0x7f288801bb68' is setup and ready to go [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: icess0x7f28880 Destroying ICE session 0x7f288800e3b8 [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: stuse0x7f28880 STUN session 0x7f2888000d98 destroy request, ref_cnt=4 [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: stuse0x7f28880 STUN session 0x7f2888001d98 destroy request, ref_cnt=3 [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: ice_session.c ICE session 0x7f288800e3b8 destroyed [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: stun_session.c STUN session 0x7f2888000d98 destroyed [Jul 13 16:49:53] DEBUG[10363][C-00000003] pjsip: stun_session.c STUN session 0x7f2888001d98 destroyed [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f288801bb68' [Jul 13 16:49:53] VERBOSE[10363][C-00000003] netsock2.c: Using SIP RTP TOS bits 184 [Jul 13 16:49:53] VERBOSE[10363][C-00000003] netsock2.c: Using SIP RTP CoS mark 5 [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Setting NAT on RTP to Off [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP o=- 1436795393693652 1 IN IP4 192.168.1.199... OK. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP s=X-Lite release 4.8.4 stamp 76590... UNSUPPORTED OR FAILED. [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.199' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.199' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.199... OK. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 9 (0x7f2888016748) based on m type on 0x7f283e6e92d0 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 8 (0x7f28880128d8) based on m type on 0x7f283e6e92d0 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 0 (0x7f2888009568) based on m type on 0x7f283e6e92d0 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 101 (0x7f2888025738) based on m type on 0x7f283e6e92d0 [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f288801bb68' [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 0 (0x7f2888009568) from 0x7f283e6e92d0 to 0x7f288801bd30 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 8 (0x7f28880128d8) from 0x7f283e6e92d0 to 0x7f288801bd30 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 9 (0x7f2888016748) from 0x7f283e6e92d0 to 0x7f288801bd30 [Jul 13 16:49:53] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 101 (0x7f2888025b98) from 0x7f283e6e92d0 to 0x7f288801bd30 [Jul 13 16:49:53] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f288801bb68' [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: We're settling with these formats: (ulaw|alaw) [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Checking SIP call limits for device 111 [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Updating call counter for incoming call [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:53] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: *** Our native formats are (ulaw) [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: *** Joint capabilities are (ulaw|alaw) [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: *** Our capabilities are (ulaw|alaw|gsm|h263) [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: This channel will not be able to handle video. [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: SIP/111-00000006: New call is still down.... Trying... [Jul 13 16:49:53] DEBUG[10363][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer 111 [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer 111 [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Jul 13 16:49:54] DEBUG[10303] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jul 13 16:49:54] DEBUG[10312] app_queue.c: Extension '111@subscribe' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 13 16:49:54] DEBUG[10379] app_queue.c: Device 'SIP/111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 13 16:49:54] DEBUG[10322] threadpool.c: Increasing threadpool SIP's size by 5 [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Connection okay. [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1001' AND host = 'dynamic' [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Connection okay. [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1001' [Jul 13 16:49:54] DEBUG[11073][C-00000003] pbx.c: Result of 'EXTEN' is '1001' [Jul 13 16:49:54] DEBUG[11073][C-00000003] pbx.c: Launching 'Dial' [Jul 13 16:49:54] VERBOSE[11073][C-00000003] pbx.c: Executing [1001@home:1] Dial("SIP/111-00000006", "SIP/freesw/1001") in new stack [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Allocating new SIP dialog for 56b8d68d3af4523a50e8832628069f5e@127.0.0.1:5060 - INVITE (No RTP) [Jul 13 16:49:54] DEBUG[11073][C-00000003] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f2880114328' [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Allocated port 18268 for RTP instance '0x7f2880114328' [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: icess0x7f28801 ICE session created, comp_cnt=2, role is Unknown agent [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: Splitting '192.168.1.146' into... [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: ...host '192.168.1.146' and port ''. [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: icess0x7f28801 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80192, addr=192.168.1.146:18268, base=192.168.1.146:18268, prio=0x7effffff (2130706431) [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: Splitting '192.168.122.1' into... [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: ...host '192.168.122.1' and port ''. [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: icess0x7f28801 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:18268, base=192.168.122.1:18268, prio=0x7effffff (2130706431) [Jul 13 16:49:54] DEBUG[11073][C-00000003] rtp_engine.c: RTP instance '0x7f2880114328' is setup and ready to go [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: icess0x7f28801 Destroying ICE session 0x7f2880158a48 [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: stuse0x7f28801 STUN session 0x7f288001fc58 destroy request, ref_cnt=4 [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: stuse0x7f28800 STUN session 0x7f288015aa58 destroy request, ref_cnt=3 [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: ice_session.c ICE session 0x7f2880158a48 destroyed [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: stun_session.c STUN session 0x7f288001fc58 destroyed [Jul 13 16:49:54] DEBUG[11073][C-00000003] pjsip: stun_session.c STUN session 0x7f288015aa58 destroyed [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f2880114328' [Jul 13 16:49:54] VERBOSE[11073][C-00000003] netsock2.c: Using SIP RTP TOS bits 184 [Jul 13 16:49:54] VERBOSE[11073][C-00000003] netsock2.c: Using SIP RTP CoS mark 5 [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Setting NAT on RTP to Off [Jul 13 16:49:54] DEBUG[11073][C-00000003] acl.c: For destination '192.168.1.143', our source address is '192.168.1.146'. [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.146:5060 [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Setting NAT on RTP to Off [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: SIP call-id changed from '56b8d68d3af4523a50e8832628069f5e@127.0.0.1:5060' to '5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060' [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: *** Our native formats are (ulaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: *** Joint capabilities are (ulaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: *** Our capabilities are (alaw|ulaw|g722) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: This channel will not be able to handle video. [Jul 13 16:49:54] DEBUG[11073][C-00000003] channel_internal_api.c: Channel Call ID changing from [C-00000003] to [C-00000003] [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Outgoing Call for 1001 [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: ** Our capability: (ulaw|alaw|g722) Video flag: False Text flag: False [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: ** Our prefcodec: (ulaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: -- Done with adding codecs to SDP [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw|g722) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Initializing initreq for method INVITE - callid 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.143:5080 [Jul 13 16:49:54] VERBOSE[11073][C-00000003] app_dial.c: Called SIP/freesw/1001 [Jul 13 16:49:54] DEBUG[10303] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: = Looking for Call ID: 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 (Checking To) --From tag as71e7950d --To-tag [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060' Request 102: Found [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: SIP response 100 to standard invite [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - freesw [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer freesw [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/freesw - state 6 (Ringing) [Jul 13 16:49:54] DEBUG[10379] app_queue.c: Device 'SIP/freesw' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag as57bb1683 [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: Invalid SIP message - rejected , no callid, len 318 [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: = Looking for Call ID: 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 (Checking To) --From tag as71e7950d --To-tag 9NNB4jHjtXFFD [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Acked pending invite 102 [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Stopping retransmission on '5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060' of Request 102: Match Found [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: SIP response 200 to standard invite [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP o=FreeSWITCH 1436768760 1436768761 IN IP4 192.168.1.143... OK. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED. [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.143' into... [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.143' and port ''. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.143... OK. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jul 13 16:49:54] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 0 (0x7f2888028ac8) based on m type on 0x7f283e6e8950 [Jul 13 16:49:54] DEBUG[10363][C-00000003] rtp_engine.c: Setting payload 101 (0x7f2888004c18) based on m type on 0x7f283e6e8950 [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f2880114328' [Jul 13 16:49:54] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 0 (0x7f28880025e8) from 0x7f283e6e8950 to 0x7f28801144f0 [Jul 13 16:49:54] DEBUG[10363][C-00000003] rtp_engine.c: Copying payload 101 (0x7f2888028ac8) from 0x7f283e6e8950 to 0x7f28801144f0 [Jul 13 16:49:54] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f2880114328' [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: We're settling with these formats: (ulaw) [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: We have an owner, now see if we need to change this call [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.143:5080' into... [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.143' and port '5080'. [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.143:5080' into... [Jul 13 16:49:54] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.143' and port '5080'. [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Trying to put 'ACK sip:100' onto UDP socket destined for 192.168.1.143:5080 [Jul 13 16:49:54] VERBOSE[11073][C-00000003] app_dial.c: SIP/freesw-00000007 answered SIP/111-00000006 [Jul 13 16:49:54] DEBUG[11073][C-00000003] rtp_engine.c: Setting early bridge SDP of 'SIP/111-00000006' with that of 'SIP/freesw-00000007' [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: SIP answering channel: SIP/111-00000006 [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Setting framing from config on incoming call [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: ** Our prefcodec: (nothing) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: -- Done with adding codecs to SDP [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [Jul 13 16:49:54] DEBUG[11073][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:49:54] DEBUG[11073][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: Cannot use native DAHDI. Must have two channels. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge_native_rtp.c: Bridge '96f55fff-6575-41cb-bd9f-20ff964c43a7' can not use native RTP bridge as two channels are required [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Chose bridge technology simple_bridge [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling simple_bridge technology constructor [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling simple_bridge technology start [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f288008df18(SIP/111-00000006) is joining [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: pushing 0x7f288008df18(SIP/111-00000006) [Jul 13 16:49:54] VERBOSE[11073][C-00000003] bridge_channel.c: Channel SIP/111-00000006 joined 'simple_bridge' basic-bridge <96f55fff-6575-41cb-bd9f-20ff964c43a7> [Jul 13 16:49:54] DEBUG[11073][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: Cannot use native DAHDI. Must have two channels. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge_native_rtp.c: Bridge '96f55fff-6575-41cb-bd9f-20ff964c43a7' can not use native RTP bridge as two channels are required [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Chose bridge technology simple_bridge [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7 is already using the new technology. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f288008df18(SIP/111-00000006) is joining simple_bridge technology [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - freesw [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer freesw [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/freesw - state 2 (In use) [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - freesw [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer freesw [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/freesw - state 2 (In use) [Jul 13 16:49:54] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Jul 13 16:49:54] DEBUG[10310] chan_sip.c: Checking device state for peer 111 [Jul 13 16:49:54] DEBUG[10310] devicestate.c: Changing state for SIP/111 - state 2 (In use) [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f2880021118(SIP/freesw-00000007) is joining [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: pushing 0x7f2880021118(SIP/freesw-00000007) [Jul 13 16:49:54] VERBOSE[11081][C-00000003] bridge_channel.c: Channel SIP/freesw-00000007 joined 'simple_bridge' basic-bridge <96f55fff-6575-41cb-bd9f-20ff964c43a7> [Jul 13 16:49:54] DEBUG[11081][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'SIP/111-00000006' is not DAHDI. [Jul 13 16:49:54] DEBUG[11081][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: Cannot use native DAHDI. Channel 'SIP/111-00000006' not compatible. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Chose bridge technology native_rtp [Jul 13 16:49:54] VERBOSE[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: switching from simple_bridge technology to native_rtp [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling native_rtp technology constructor [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: moving 0x7f288008df18(SIP/111-00000006) to dummy bridge temporarily [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f288008df18(SIP/111-00000006) is leaving simple_bridge technology (dummy) [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling simple_bridge technology stop [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f2880021118(SIP/freesw-00000007) is joining native_rtp technology [Jul 13 16:49:54] VERBOSE[11081][C-00000003] bridge_native_rtp.c: Locally RTP bridged 'SIP/freesw-00000007' and 'SIP/111-00000006' in stack [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f288008df18(SIP/111-00000006) is joining native_rtp technology [Jul 13 16:49:54] VERBOSE[11081][C-00000003] bridge_native_rtp.c: Locally RTP bridged 'SIP/freesw-00000007' and 'SIP/111-00000006' in stack [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling native_rtp technology start [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling simple_bridge technology destructor [Jul 13 16:49:54] DEBUG[11081][C-00000003] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jul 13 16:49:54] DEBUG[11081][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'SIP/freesw-00000007' is not DAHDI. [Jul 13 16:49:54] DEBUG[11081][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: Cannot use native DAHDI. Channel 'SIP/freesw-00000007' not compatible. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Chose bridge technology native_rtp [Jul 13 16:49:54] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7 is already using the new technology. [Jul 13 16:49:54] DEBUG[10379] app_queue.c: Device 'SIP/freesw' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 13 16:49:54] DEBUG[10311] cdr.c: Finalized CDR for SIP/freesw-00000007 - start 1436795394.008183 answer 1436795394.023276 end 1436795394.026163 dispo ANSWERED [Jul 13 16:49:54] DEBUG[11073][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'SIP/freesw-00000007' is not DAHDI. [Jul 13 16:49:54] DEBUG[11073][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: Cannot use native DAHDI. Channel 'SIP/freesw-00000007' not compatible. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Chose bridge technology native_rtp [Jul 13 16:49:54] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7 is already using the new technology. [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #145)) [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag as6ff98f6e [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: Stopping retransmission on '76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ' of Response 2: Match Found [Jul 13 16:49:54] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag as6ff98f6e [Jul 13 16:49:54] DEBUG[10363][C-00000003] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: 0x7f288801f1e0 -- Probation learning mode pass with source address 192.168.1.199:54478 [Jul 13 16:49:54] VERBOSE[11073][C-00000003] res_rtp_asterisk.c: 0x7f288801f1e0 -- Probation passed - setting RTP source address to 192.168.1.199:54478 [Jul 13 16:49:54] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Got RTCP report of 56 bytes [Jul 13 16:49:54] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: Splitting 'ast-1' into... [Jul 13 16:49:54] DEBUG[11073][C-00000003] netsock2.c: ...host 'ast-1' and port ''. [Jul 13 16:49:54] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:49:54] DEBUG[11073][C-00000003] acl.c: Attached to given IP address [Jul 13 16:49:54] DEBUG[10373] netsock2.c: Splitting '192.168.1.199:54479' into... [Jul 13 16:49:54] DEBUG[10373] netsock2.c: ...host '192.168.1.199' and port '54479'. [Jul 13 16:49:54] DEBUG[10373] netsock2.c: Splitting '127.0.0.1:0' into... [Jul 13 16:49:54] DEBUG[10373] netsock2.c: ...host '127.0.0.1' and port '0'. [Jul 13 16:49:55] DEBUG[11081][C-00000003] res_rtp_asterisk.c: 0x7f2880115530 -- Probation learning mode pass with source address 192.168.1.143:26634 [Jul 13 16:49:55] VERBOSE[11081][C-00000003] res_rtp_asterisk.c: 0x7f2880115530 -- Probation passed - setting RTP source address to 192.168.1.143:26634 [Jul 13 16:49:57] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Got RTCP report of 80 bytes [Jul 13 16:49:57] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:49:57] DEBUG[11073][C-00000003] netsock2.c: Splitting 'ast-1' into... [Jul 13 16:49:57] DEBUG[11073][C-00000003] netsock2.c: ...host 'ast-1' and port ''. [Jul 13 16:49:57] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:49:57] DEBUG[11073][C-00000003] acl.c: Attached to given IP address [Jul 13 16:49:57] DEBUG[10373] netsock2.c: Splitting '192.168.1.199:54479' into... [Jul 13 16:49:57] DEBUG[10373] netsock2.c: ...host '192.168.1.199' and port '54479'. [Jul 13 16:49:57] DEBUG[10373] netsock2.c: Splitting '127.0.0.1:0' into... [Jul 13 16:49:57] DEBUG[10373] netsock2.c: ...host '127.0.0.1' and port '0'. [Jul 13 16:50:00] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Got RTCP report of 68 bytes [Jul 13 16:50:00] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:50:00] DEBUG[11073][C-00000003] netsock2.c: Splitting 'ast-1' into... [Jul 13 16:50:00] DEBUG[11073][C-00000003] netsock2.c: ...host 'ast-1' and port ''. [Jul 13 16:50:00] DEBUG[11073][C-00000003] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jul 13 16:50:00] DEBUG[11073][C-00000003] acl.c: Attached to given IP address [Jul 13 16:50:00] DEBUG[10373] netsock2.c: Splitting '192.168.1.199:54479' into... [Jul 13 16:50:00] DEBUG[10373] netsock2.c: ...host '192.168.1.199' and port '54479'. [Jul 13 16:50:00] DEBUG[10373] netsock2.c: Splitting '127.0.0.1:0' into... [Jul 13 16:50:00] DEBUG[10373] netsock2.c: ...host '127.0.0.1' and port '0'. [Jul 13 16:50:01] DEBUG[10363] chan_sip.c: = Looking for Call ID: 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ (Checking From) --From tag 71f6606d --To-tag as6ff98f6e [Jul 13 16:50:01] DEBUG[10363][C-00000003] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jul 13 16:50:01] DEBUG[10363][C-00000003] netsock2.c: Splitting '192.168.1.199:52422' into... [Jul 13 16:50:01] DEBUG[10363][C-00000003] netsock2.c: ...host '192.168.1.199' and port '52422'. [Jul 13 16:50:01] DEBUG[10363][C-00000003] chan_sip.c: Setting SIP_ALREADYGONE on dialog 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ [Jul 13 16:50:01] DEBUG[10363][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f288801bb68' [Jul 13 16:50:01] DEBUG[10363][C-00000003] chan_sip.c: Received bye, issuing owner hangup [Jul 13 16:50:01] DEBUG[10363][C-00000003] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.199:52422 [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge_channel.c: Setting 0x7f288008df18(SIP/111-00000006) state from:0 to:1 [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: pulling 0x7f288008df18(SIP/111-00000006) [Jul 13 16:50:01] VERBOSE[11073][C-00000003] bridge_channel.c: Channel SIP/111-00000006 left 'native_rtp' basic-bridge <96f55fff-6575-41cb-bd9f-20ff964c43a7> [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f288008df18(SIP/111-00000006) is leaving native_rtp technology [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/freesw-00000007' and 'SIP/111-00000006' - media will flow through Asterisk core [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: dissolving bridge with cause 16(Normal Clearing) [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge_channel.c: Setting 0x7f2880021118(SIP/freesw-00000007) state from:0 to:2 [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: queueing action type:13 sub:1001 [Jul 13 16:50:01] DEBUG[11073][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7 is dissolved, not performing smart bridge operation. [Jul 13 16:50:01] DEBUG[11073][C-00000003] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Spawn extension (home,1001,1) exited non-zero on 'SIP/111-00000006' [Jul 13 16:50:01] VERBOSE[11073][C-00000003] pbx.c: Spawn extension (home, 1001, 1) exited non-zero on 'SIP/111-00000006' [Jul 13 16:50:01] DEBUG[11073][C-00000003] channel.c: Soft-Hanging (0x10) up channel 'SIP/111-00000006' [Jul 13 16:50:01] DEBUG[11073][C-00000003] channel.c: Soft-Hanging (0x80) up channel 'SIP/111-00000006' [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Launching 'NoOp' [Jul 13 16:50:01] VERBOSE[11073][C-00000003] pbx.c: Executing [h@home:1] NoOp("SIP/111-00000006", "") in new stack [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Result of 'UNIQUEID' is 'ast-1-1436795393.12' [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Function STAT(e,/var/spool/asterisk/recording/ast-1-1436795393.12.wav) result is '0' [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Expression result is '0' [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Result of 'UNIQUEID' is 'ast-1-1436795393.12' [Jul 13 16:50:01] DEBUG[11073][C-00000003] pbx.c: Launching 'ExecIf' [Jul 13 16:50:01] VERBOSE[11073][C-00000003] pbx.c: Executing [h@home:2] ExecIf("SIP/111-00000006", "0?System(/bin/rm -f /var/spool/asterisk/recording/ast-1-1436795393.12.wav)") in new stack [Jul 13 16:50:01] DEBUG[11073][C-00000003] channel.c: Hanging up channel 'SIP/111-00000006' [Jul 13 16:50:01] DEBUG[11073][C-00000003] chan_sip.c: Hangup call SIP/111-00000006, SIP callid 76590MWUwZDY4YmUwMzgyMTI5ZTViZTkzOTFkZmEwNjczYzQ [Jul 13 16:50:01] DEBUG[11073][C-00000003] chan_sip.c: Updating call counter for incoming call [Jul 13 16:50:01] DEBUG[11073][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f288801bb68' [Jul 13 16:50:01] DEBUG[11081][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: pulling 0x7f2880021118(SIP/freesw-00000007) [Jul 13 16:50:01] VERBOSE[11081][C-00000003] bridge_channel.c: Channel SIP/freesw-00000007 left 'native_rtp' basic-bridge <96f55fff-6575-41cb-bd9f-20ff964c43a7> [Jul 13 16:50:01] DEBUG[11081][C-00000003] bridge_channel.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: 0x7f2880021118(SIP/freesw-00000007) is leaving native_rtp technology [Jul 13 16:50:01] DEBUG[11081][C-00000003] bridge_channel.c: Channel SIP/freesw-00000007 will survive this bridge; clearing outgoing (dialed) flag [Jul 13 16:50:01] DEBUG[11081][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7 is dissolved, not performing smart bridge operation. [Jul 13 16:50:01] DEBUG[11081][C-00000003] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jul 13 16:50:01] DEBUG[11081][C-00000003] channel.c: Hanging up channel 'SIP/freesw-00000007' [Jul 13 16:50:01] DEBUG[11081][C-00000003] chan_sip.c: Hangup call SIP/freesw-00000007, SIP callid 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 [Jul 13 16:50:01] DEBUG[11081][C-00000003] chan_sip.c: Updating call counter for outgoing call [Jul 13 16:50:01] DEBUG[11081][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f2880114328' [Jul 13 16:50:01] DEBUG[11081][C-00000003] netsock2.c: Splitting '192.168.1.143:5080' into... [Jul 13 16:50:01] DEBUG[11081][C-00000003] netsock2.c: ...host '192.168.1.143' and port '5080'. [Jul 13 16:50:01] DEBUG[11081][C-00000003] chan_sip.c: Trying to put 'BYE sip:100' onto UDP socket destined for 192.168.1.143:5080 [Jul 13 16:50:01] DEBUG[10309][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: actually destroying basic bridge, nobody wants it anymore [Jul 13 16:50:01] DEBUG[10309][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling basic bridge destructor [Jul 13 16:50:01] DEBUG[10309][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling native_rtp technology stop [Jul 13 16:50:01] DEBUG[10309][C-00000003] bridge.c: Bridge 96f55fff-6575-41cb-bd9f-20ff964c43a7: calling native_rtp technology destructor [Jul 13 16:50:01] DEBUG[10311] cdr.c: Finalized CDR for SIP/111-00000006 - start 1436795394.002433 answer 1436795394.023292 end 1436795401.098920 dispo ANSWERED [Jul 13 16:50:01] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Jul 13 16:50:01] DEBUG[10310] chan_sip.c: Checking device state for peer 111 [Jul 13 16:50:01] DEBUG[10310] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Jul 13 16:50:01] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - 111 [Jul 13 16:50:01] DEBUG[10310] chan_sip.c: Checking device state for peer 111 [Jul 13 16:50:01] DEBUG[10310] devicestate.c: Changing state for SIP/111 - state 1 (Not in use) [Jul 13 16:50:01] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - freesw [Jul 13 16:50:01] DEBUG[10310] chan_sip.c: Checking device state for peer freesw [Jul 13 16:50:01] DEBUG[10310] devicestate.c: Changing state for SIP/freesw - state 1 (Not in use) [Jul 13 16:50:01] DEBUG[10310] devicestate.c: No provider found, checking channel drivers for SIP - freesw [Jul 13 16:50:01] DEBUG[10310] chan_sip.c: Checking device state for peer freesw [Jul 13 16:50:01] DEBUG[10310] devicestate.c: Changing state for SIP/freesw - state 1 (Not in use) [Jul 13 16:50:01] DEBUG[10312] app_queue.c: Extension '111@subscribe' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 13 16:50:01] DEBUG[10379] app_queue.c: Device 'SIP/111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 13 16:50:01] DEBUG[10379] app_queue.c: Device 'SIP/freesw' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 13 16:50:01] DEBUG[10311] cdr_mysql.c: Inserting a CDR record. [Jul 13 16:50:01] DEBUG[10311] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`src`,`dst`,`dcontext`,`clid`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`start`,`answer`,`end`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`linkedid`,`sequence`) VALUES ('111','1001','home','\"111\" <111>','SIP/111-00000006','SIP/freesw-00000007','Dial','SIP/freesw/1001','2015-07-13 16:49:54','2015-07-13 16:49:54','2015-07-13 16:50:01','7','7','ANSWERED','DOCUMENTATION','ast-1-1436795393.12','ast-1-1436795393.12','6') [Jul 13 16:50:01] DEBUG[10311] cdr_radius.c: Unable to create RADIUS record. CDR not recorded! [Jul 13 16:50:01] DEBUG[10311] 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 ('"111" <111>','111','1001','home','SIP/111-00000006','SIP/freesw-00000007','Dial','SIP/freesw/1001','2015-07-13 16:49:54','2015-07-13 16:49:54','2015-07-13 16:50:01','7','7','ANSWERED','DOCUMENTATION','ast-1-1436795393.12') [Jul 13 16:50:01] DEBUG[10363] chan_sip.c: = Looking for Call ID: 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 (Checking To) --From tag as71e7950d --To-tag 9NNB4jHjtXFFD [Jul 13 16:50:01] DEBUG[10363][C-00000003] chan_sip.c: Stopping retransmission on '5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060' of Request 103: Match Found [Jul 13 16:50:01] DEBUG[10363] chan_sip.c: Destroying SIP dialog 5aee1d732a14f6ce5af273b95a7db198@192.168.1.146:5060 [Jul 13 16:50:01] DEBUG[10363] rtp_engine.c: Destroyed RTP instance '0x7f2880114328' [Jul 13 16:50:01] DEBUG[10311] cdr.c: CDR for SIP/freesw-00000007 is dialed and has no Party B; discarding