Connected to Asterisk 13.17.0 currently running on asterisk13 (pid = 1397) asterisk13*CLI> core set verbose 9 Console verbose was OFF and is now 9. asterisk13*CLI> core set debug 9 Core debug was OFF and is now 9. [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 3b5e66ca2c092e09 (Checking From) --From tag 1163192f0552706a --To-tag [Aug 9 13:42:12] DEBUG[1430]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:3911 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.67:5060 [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into... [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'. [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:9016 __sip_alloc: Allocating new SIP dialog for 3b5e66ca2c092e09 - INVITE (No RTP) [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 3b5e66ca2c092e09 (Checking From) --From tag 1163192f0552706a --To-tag as7cffa048 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:28770 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '3b5e66ca2c092e09' of Response 20731: Match Found [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 3b5e66ca2c092e09 (Checking From) --From tag 1163192f0552706a --To-tag [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1430]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:28770 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff74c00fa60' [Aug 9 13:42:12] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 15358 for RTP instance '0x7ff74c00fa60' [Aug 9 13:42:12] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session 0.0.0.0:15358 (15358) for RTP instance '0x7ff74c00fa60' [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff74c00fa60' is setup and ready to go [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'asterisk13.test' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'asterisk13.test' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: acl.c:795 resolve_first: Multiple addresses. Using the first only [Aug 9 13:42:12] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff74c00fa60' == Using SIP RTP CoS mark 5 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP o=- 112927836 1745970335 IN IP4 192.168.1.49... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP a=tool:baresip 0.4.6... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff74bf80b40 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7ff74bf80b40 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7ff74bf80b40 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP b=AS:125... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=label:1... UNSUPPORTED OR FAILED. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff74c00fa60' [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff74c00a2d8) from 0x7ff74bf80b40 to 0x7ff74c00fc28 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff74c00b7e8) from 0x7ff74bf80b40 to 0x7ff74c00fc28 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff74c016028) from 0x7ff74bf80b40 to 0x7ff74c00fc28 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff74c00fa60' [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:11097 process_sdp: We're settling with these formats: (ulaw|alaw) [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:26354 handle_request_invite: Checking SIP call limits for device 0x229c580 [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:6768 update_call_counter: Updating call counter for incoming call [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67:5060' into... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff74c019fe0 'SIP/7777-00000000' allocated [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:8165 sip_new: *** Our native formats are (ulaw) [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:8166 sip_new: *** Joint capabilities are (ulaw|alaw) [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:8167 sip_new: *** Our capabilities are (ulaw|alaw|gsm|h263) [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:8168 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:8201 sip_new: This channel will not be able to handle video. [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:26558 handle_request_invite: SIP/7777-00000000: New call is still down.... Trying... [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:12] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 9 13:42:12] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777 [Aug 9 13:42:12] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [8888@buh:1] NoOp("SIP/7777-00000000", "") in new stack [Aug 9 13:42:12] DEBUG[1446][C-00000000]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '8888' [Aug 9 13:42:12] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'Dial' -- Executing [8888@buh:2] Dial("SIP/7777-00000000", "SIP/8888,20,tirU(subAnswer)") in new stack [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:30413 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:9016 __sip_alloc: Allocating new SIP dialog for 25f686412395209f755c91442b4ba8e6@[fe80::a00:27ff:fede:24f1]:5060 - INVITE (No RTP) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff74c0188a0' [Aug 9 13:42:12] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3030 ast_rtp_new: Allocated port 12816 for RTP instance '0x7ff74c0188a0' [Aug 9 13:42:12] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3061 ast_rtp_new: Creating ICE session 0.0.0.0:12816 (12816) for RTP instance '0x7ff74c0188a0' [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.67' into... [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.67' and port ''. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7ff74c0188a0' is setup and ready to go [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'asterisk13.test' into... [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'asterisk13.test' and port ''. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: acl.c:795 resolve_first: Multiple addresses. Using the first only [Aug 9 13:42:12] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:5452 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff74c0188a0' == Using SIP RTP CoS mark 5 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off [Aug 9 13:42:12] DEBUG[1446][C-00000000]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:3911 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.1.67:5060 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into... [Aug 9 13:42:12] DEBUG[1446][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:5799 do_setnat: Setting NAT on RTP to Off [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8801 change_callid_pvt: SIP call-id changed from '25f686412395209f755c91442b4ba8e6@[fe80::a00:27ff:fede:24f1]:5060' to '0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060' [Aug 9 13:42:12] DEBUG[1446][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7ff74c019010 'SIP/8888-00000001' allocated [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8165 sip_new: *** Our native formats are (ulaw) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8166 sip_new: *** Joint capabilities are (ulaw) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8167 sip_new: *** Our capabilities are (ulaw|alaw|gsm|h263) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8168 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8170 sip_new: *** Our preferred formats from the incoming channel are (ulaw) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:8201 sip_new: This channel will not be able to handle video. [Aug 9 13:42:12] DEBUG[1446][C-00000000]: channel_internal_api.c:935 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:6474 sip_call: Outgoing Call for 8888 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:6768 update_call_counter: Updating call counter for outgoing call [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:13487 add_sdp: This call needs video offers, but there's no video support enabled! [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw|gsm|h263) Video flag: False Text flag: False [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (ulaw) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:13680 add_sdp: -- Done with adding codecs to SDP [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:13899 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|gsm|h263) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:3397 initialize_initreq: Initializing initreq for method INVITE - callid 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.49:6640 -- Called SIP/8888 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:12] DEBUG[1446][C-00000000]: channel.c:4560 indicate_connected_line: SIP/7777-00000000: Dropping redundant connected line update "OneUser" <8888>. [Aug 9 13:42:12] DEBUG[1400]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Aug 9 13:42:12] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 (Checking To) --From tag as3ff8789b --To-tag d030da0d [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:4579 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060' Request 102: Found [Aug 9 13:42:12] DEBUG[1430][C-00000000]: chan_sip.c:23613 handle_response_invite: SIP response 180 to standard invite [Aug 9 13:42:12] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 9 13:42:12] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888 -- SIP/8888-00000001 is ringing [Aug 9 13:42:12] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 9 13:42:12] DEBUG[1446][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:14] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 (Checking To) --From tag as3ff8789b --To-tag d030da0d [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:4522 __sip_ack: Acked pending invite 102 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060' of Request 102: Match Found [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:23613 handle_response_invite: SIP response 200 to standard invite [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP o=3cxVCE 254566245 168793185 IN IP4 192.168.1.49... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49' into... [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port ''. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP c=IN IP4 192.168.1.49... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10339 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7ff74bf7fae0 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7ff74bf7fae0 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7ff74bf7fae0 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:763 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7ff74bf7fae0 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:10802 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:937 ast_rtp_ice_set_role: Set role to CONTROLLING (0x7ff74c0188a0) [Aug 9 13:42:14] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:940 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7ff74c0188a0) [Aug 9 13:42:14] DEBUG[1430][C-00000000]: acl.c:957 ast_ouraddrfor: For destination '192.168.1.49', our source address is '192.168.1.67'. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:5515 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff74c0188a0' [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7ff74c019e38) from 0x7ff74bf7fae0 to 0x7ff74c018a68 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7ff74c023fc8) from 0x7ff74bf7fae0 to 0x7ff74c018a68 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff74c00bf08) from 0x7ff74bf7fae0 to 0x7ff74c018a68 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff74c00a298) from 0x7ff74bf7fae0 to 0x7ff74c018a68 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: res_rtp_asterisk.c:5351 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7ff74c0188a0' [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:11097 process_sdp: We're settling with these formats: (ulaw|alaw|gsm) [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:11104 process_sdp: We have an owner, now see if we need to change this call [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:6768 update_call_counter: Updating call counter for outgoing call [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into... [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into... [Aug 9 13:42:14] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'. [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'ACK sip:888' onto UDP socket destined for 192.168.1.49:6640 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: channel.c:4560 indicate_connected_line: SIP/7777-00000000: Dropping redundant connected line update "OneUser" <8888>. -- SIP/8888-00000001 answered SIP/7777-00000000 -- SIP/8888-00000001 Internal Gosub(subAnswer,s,1) start [Aug 9 13:42:14] DEBUG[1446][C-00000000]: app_stack.c:1006 gosub_run: SIP/8888-00000001 Original location: ato,,1 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: app_stack.c:606 gosub_exec: Channel SIP/8888-00000001 has no datastore, so we're allocating one. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: app_stack.c:1010 gosub_run: Gosub exited with status 0 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'NoOp' -- Executing [s@subAnswer:1] NoOp("SIP/8888-00000001", "") in new stack [Aug 9 13:42:14] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 9 13:42:14] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888 [Aug 9 13:42:14] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(userfield) result is '' [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@subAnswer:2] Set("SIP/8888-00000001", "CDR(userfield)=:subAnswer") in new stack [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(userfield) result is ':subAnswer' [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'Set' -- Executing [s@subAnswer:3] Set("SIP/8888-00000001", "CDR(userfield)=:subAnswer:moreData") in new stack [Aug 9 13:42:14] DEBUG[1446][C-00000000]: pbx.c:2875 pbx_extension_helper: Launching 'Return' -- Executing [s@subAnswer:4] Return("SIP/8888-00000001", "") in new stack [Aug 9 13:42:14] DEBUG[1446][C-00000000]: app_stack.c:1068 gosub_run: Spawn extension (ato,,1) exited with -1 on 'SIP/8888-00000001' == Spawn extension (ato, , 1) exited non-zero on 'SIP/8888-00000001' -- SIP/8888-00000001 Internal Gosub(subAnswer,s,1) complete GOSUB_RETVAL= [Aug 9 13:42:14] DEBUG[1446][C-00000000]: app_stack.c:1094 gosub_run: SIP/8888-00000001 Ending location: ato,,1 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:7413 sip_answer: SIP answering channel: SIP/7777-00000000 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3430 ast_rtp_update_source: Setting the marker bit due to a source update [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:13509 add_sdp: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:13510 add_sdp: ** Our prefcodec: (nothing) [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:13680 add_sdp: -- Done with adding codecs to SDP [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:13705 add_sdp: Setting framing on incoming call: 0 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:13899 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) [Aug 9 13:42:14] DEBUG[1446][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:502 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge 'b3474dd0-320f-4ddd-81d0-d92d84abe13b' can not use native RTP bridge as two channels are required [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:795 bridge_base_init: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: calling simple_bridge technology constructor [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:803 bridge_base_init: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: calling simple_bridge technology start [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c028290(SIP/8888-00000001) is joining [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: pushing 0x7ff74c028290(SIP/8888-00000001) -- Channel SIP/8888-00000001 joined 'simple_bridge' basic-bridge [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge_native_rtp.c:727 native_rtp_bridge_compatible: Bridge 'b3474dd0-320f-4ddd-81d0-d92d84abe13b' can not use native RTP bridge as two channels are required [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b is already using the new technology. [Aug 9 13:42:14] DEBUG[1449][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c028290(SIP/8888-00000001) is joining simple_bridge technology [Aug 9 13:42:14] DEBUG[1449][C-00000000]: res_rtp_asterisk.c:3444 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge_channel.c:2650 bridge_channel_internal_join: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c01f140(SIP/7777-00000000) is joining [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge_channel.c:2133 bridge_channel_internal_push_full: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: pushing 0x7ff74c01f140(SIP/7777-00000000) -- Channel SIP/7777-00000000 joined 'simple_bridge' basic-bridge [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge_native_rtp.c:617 native_rtp_bridge_compatible_check: Bridge 'b3474dd0-320f-4ddd-81d0-d92d84abe13b'. Checking compatability for channels 'SIP/8888-00000001' and 'SIP/7777-00000000' [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge_native_rtp.c:651 native_rtp_bridge_compatible_check: Bridge 'b3474dd0-320f-4ddd-81d0-d92d84abe13b' can not use native RTP bridge as channel 'SIP/8888-00000001' has DTMF hooks [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:1047 smart_bridge_operation: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b is already using the new technology. [Aug 9 13:42:14] DEBUG[1446][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c01f140(SIP/7777-00000000) is joining simple_bridge technology [Aug 9 13:42:14] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3444 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Aug 9 13:42:14] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 9 13:42:14] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777 [Aug 9 13:42:14] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 9 13:42:14] DEBUG[1412]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/8888-00000001 - start 1502275332.819903 answer 1502275334.227286 end 1502275334.231462 dispo ANSWERED [Aug 9 13:42:14] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 3b5e66ca2c092e09 (Checking From) --From tag 1163192f0552706a --To-tag as752fd0c0 [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:28770 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Aug 9 13:42:14] DEBUG[1430][C-00000000]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '3b5e66ca2c092e09' of Response 20732: Match Found [Aug 9 13:42:14] DEBUG[1449][C-00000000]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7ff74c024e40 -- Probation learning mode pass with source address 192.168.1.49:40020 > 0x7ff74c024e40 -- Probation passed - setting RTP source address to 192.168.1.49:40020 [Aug 9 13:42:14] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:4017 ast_rtp_write: Ooh, format changed from none to ulaw [Aug 9 13:42:14] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3860 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7ff74c00fa60' [Aug 9 13:42:14] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:4996 ast_rtp_read: 0x7ff74c010560 -- Probation learning mode pass with source address 192.168.1.49:32984 > 0x7ff74c010560 -- Probation passed - setting RTP source address to 192.168.1.49:32984 [Aug 9 13:42:14] DEBUG[1449][C-00000000]: res_rtp_asterisk.c:4017 ast_rtp_write: Ooh, format changed from none to ulaw [Aug 9 13:42:15] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 (Checking From) --From tag d030da0d --To-tag as3ff8789b [Aug 9 13:42:15] DEBUG[1430][C-00000000]: chan_sip.c:28770 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Aug 9 13:42:15] DEBUG[1430][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:6640' into... [Aug 9 13:42:15] DEBUG[1430][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '6640'. [Aug 9 13:42:15] DEBUG[1430][C-00000000]: chan_sip.c:3410 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 [Aug 9 13:42:15] DEBUG[1430][C-00000000]: chan_sip.c:27377 handle_request_bye: Received bye, issuing owner hangup [Aug 9 13:42:15] DEBUG[1430][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.49:6640 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff74c028290(SIP/8888-00000001) state from:0 to:1 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: pulling 0x7ff74c028290(SIP/8888-00000001) -- Channel SIP/8888-00000001 left 'simple_bridge' basic-bridge [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c028290(SIP/8888-00000001) is leaving simple_bridge technology [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge.c:322 bridge_dissolve: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: dissolving bridge with cause 16(Normal Clearing) [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge_channel.c:289 ast_bridge_channel_leave_bridge_nolock: Setting 0x7ff74c01f140(SIP/7777-00000000) state from:0 to:2 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge.c:283 bridge_queue_action_nodup: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: queueing action type:13 sub:1001 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: bridge.c:1004 smart_bridge_operation: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b is dissolved, not performing smart bridge operation. [Aug 9 13:42:15] DEBUG[1449][C-00000000]: channel.c:2681 ast_hangup: Channel 0x7ff74c019010 'SIP/8888-00000001' hanging up. Refs: 2 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: chan_sip.c:7155 sip_hangup: Hangup call SIP/8888-00000001, SIP callid 0e3cc3e67288ffba735ba2c03fcdab47@192.168.1.67:5060 [Aug 9 13:42:15] DEBUG[1449][C-00000000]: channel.c:2233 ast_channel_destructor: Channel 0x7ff74c019010 'SIP/8888-00000001' destroying [Aug 9 13:42:15] DEBUG[1412]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/7777-00000000 - start 1502275332.810062 answer 1502275334.231441 end 1502275335.332334 dispo ANSWERED [Aug 9 13:42:15] DEBUG[1412]: cdr.c:1121 cdr_object_create_public_records: CDR for SIP/8888-00000001 is dialed and has no Party B; discarding [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge_channel.c:2070 bridge_channel_internal_pull: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: pulling 0x7ff74c01f140(SIP/7777-00000000) -- Channel SIP/7777-00000000 left 'simple_bridge' basic-bridge [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge_channel.c:2082 bridge_channel_internal_pull: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: 0x7ff74c01f140(SIP/7777-00000000) is leaving simple_bridge technology [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge.c:1004 smart_bridge_operation: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b is dissolved, not performing smart bridge operation. [Aug 9 13:42:15] DEBUG[1446][C-00000000]: res_rtp_asterisk.c:3451 ast_rtp_change_source: Changing ssrc from 1006008509 to 1709993623 due to a source change [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge.c:649 destroy_bridge: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: actually destroying basic bridge, nobody wants it anymore [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge.c:674 destroy_bridge: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: calling basic bridge destructor [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge.c:680 destroy_bridge: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: calling simple_bridge technology stop [Aug 9 13:42:15] DEBUG[1446][C-00000000]: bridge.c:687 destroy_bridge: Bridge b3474dd0-320f-4ddd-81d0-d92d84abe13b: calling simple_bridge technology destructor [Aug 9 13:42:15] DEBUG[1446][C-00000000]: app_dial.c:3233 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 9 13:42:15] DEBUG[1446][C-00000000]: pbx.c:4347 __ast_pbx_run: Spawn extension (buh,8888,2) exited non-zero on 'SIP/7777-00000000' == Spawn extension (buh, 8888, 2) exited non-zero on 'SIP/7777-00000000' [Aug 9 13:42:15] DEBUG[1446][C-00000000]: channel.c:2590 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/7777-00000000' [Aug 9 13:42:15] DEBUG[1446][C-00000000]: channel.c:2681 ast_hangup: Channel 0x7ff74c019fe0 'SIP/7777-00000000' hanging up. Refs: 2 [Aug 9 13:42:15] DEBUG[1446][C-00000000]: chan_sip.c:7155 sip_hangup: Hangup call SIP/7777-00000000, SIP callid 3b5e66ca2c092e09 [Aug 9 13:42:15] DEBUG[1446][C-00000000]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.49:4527' into... [Aug 9 13:42:15] DEBUG[1446][C-00000000]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.49' and port '4527'. [Aug 9 13:42:15] DEBUG[1446][C-00000000]: chan_sip.c:3754 __sip_xmit: Trying to put 'BYE sip:0x2' onto UDP socket destined for 192.168.1.49:4527 [Aug 9 13:42:15] DEBUG[1446][C-00000000]: channel.c:2233 ast_channel_destructor: Channel 0x7ff74c019fe0 'SIP/7777-00000000' destroying [Aug 9 13:42:15] DEBUG[1412]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x30ad7c0 from class 'asteriskdb' [Aug 9 13:42:15] DEBUG[1412]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,userfield,uniqueid,linkedid,sequence) VALUES ({ ts '2017-08-09 13:42:12' },'"ExtUser" <7777>','7777','8888','buh','SIP/7777-00000000','SIP/8888-00000001','Dial','SIP/8888,20,tirU(subAnswer)',2,1,'ANSWERED',3,';:subAnswer:moreData','1502275332.0','1502275332.0','0')] [Aug 9 13:42:15] DEBUG[1430]: chan_sip.c:9429 __find_call: = Looking for Call ID: 3b5e66ca2c092e09 (Checking To) --From tag as752fd0c0 --To-tag 1163192f0552706a [Aug 9 13:42:15] DEBUG[1430][C-00000000]: chan_sip.c:4538 __sip_ack: Stopping retransmission on '3b5e66ca2c092e09' of Request 102: Match Found [Aug 9 13:42:15] DEBUG[1430]: chan_sip.c:6590 sip_pvt_dtor: Destroying SIP dialog 3b5e66ca2c092e09 [Aug 9 13:42:15] DEBUG[1430]: rtp_engine.c:402 instance_destructor: Destroyed RTP instance '0x7ff74c00fa60' [Aug 9 13:42:15] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 8888 [Aug 9 13:42:15] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 8888 [Aug 9 13:42:15] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/8888 - state 1 (Not in use) [Aug 9 13:42:15] DEBUG[1411]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Aug 9 13:42:15] DEBUG[1411]: chan_sip.c:30307 sip_devicestate: Checking device state for peer 7777 [Aug 9 13:42:15] DEBUG[1411]: devicestate.c:474 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Aug 9 13:42:15] DEBUG[1412]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x30ad7c0 into pool asterisk13*CLI> exit Asterisk cleanly ending (0). Executing last minute cleanups