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