-- Executing [6001@from-internal:1] Dial("PJSIP/6002-00000013", "PJSIP/6001,15") in new stack [Apr 2 09:52:53] DEBUG[3580]: config.c:3167 ast_parse_arg: extract int from [10] in [0, 86400] gives [10](0) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d UAC dialog created [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d Module Outbound Authentica added as dialog usage, data=0x7f44840b7fe0 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d Module mod-invite added as dialog usage, data=0x7f44840b84e8 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d .Session count inc to 2 by mod-invite [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d Module mod-100rel added as dialog usage, data=0x7f44840b86a8 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d 100rel module attached [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : inv0x7f448403d UAC invite session created for dialog dlg0x7f448403d108 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d .Session count inc to 2 by Session Module [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d Module Session Module added as dialog usage, data=(nil) -- Called PJSIP/6001 [Apr 2 09:52:53] DEBUG[3580]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f44840f6748' [Apr 2 09:52:53] DEBUG[3580]: res_rtp_asterisk.c:1934 ast_rtp_new: Allocated port 13540 for RTP instance '0x7f44840f6748' [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : icess0x7f44840 ICE session created, comp_cnt=2, role is Unknown agent [Apr 2 09:52:53] DEBUG[3580]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.18.124' into... [Apr 2 09:52:53] DEBUG[3580]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.18.124' and port ''. [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : icess0x7f44840 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:13540, base=10.24.18.124:13540, prio=0x7effffff (2130706431) [Apr 2 09:52:53] DEBUG[3580]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x7f44840f6748' is setup and ready to go [Apr 2 09:52:53] DEBUG[3580]: res_rtp_asterisk.c:4104 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f44840f6748' [Apr 2 09:52:53] DEBUG[3580]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.18.124' into... [Apr 2 09:52:53] DEBUG[3580]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.18.124' and port ''. [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : icess0x7f44840 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:13541, base=10.24.18.124:13541, prio=0x7efffffe (2130706430) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : icess0x7f44840 Destroying ICE session 0x7f44840fd898 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : stuse0x7f44840 STUN session 0x7f448409b418 destroy request, ref_cnt=4 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : stuse0x7f44840 STUN session 0x7f44841000c8 destroy request, ref_cnt=3 [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : ice_session.c ICE session 0x7f44840fd898 destroyed [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : stun_session.c STUN session 0x7f448409b418 destroyed [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : stun_session.c STUN session 0x7f44841000c8 destroyed [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : endpoint Request msg INVITE/cseq=24279 (tdta0x7f4484011ac0) created. [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1786 handle_outgoing_request: Method is INVITE [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d Module NAT added as dialog usage, data=(nil) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : inv0x7f448403d .Sending Request msg INVITE/cseq=24279 (tdta0x7f4484011ac0) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ..Sending Request msg INVITE/cseq=24279 (tdta0x7f4484011ac0) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ...Transaction created for Request msg INVITE/cseq=24278 (tdta0x7f4484011ac0) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ..Sending Request msg INVITE/cseq=24278 (tdta0x7f4484011ac0) in state Null [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : sip_resolve.c ...Target '10.24.18.16:5060' type=Unspecified resolved to '10.24.18.16:5060' type=UDP (UDP transport) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ...State changed from Null to Calling, event=TX_MSG [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ....Transaction tsx0x7f4484075668 state changed to Calling [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1730 __print_debug_details: There is no transaction involved in this state change [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CALLING [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1868 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1813 handle_outgoing: Sending request [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1786 handle_outgoing_request: Method is INVITE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1726 __print_debug_details: The transaction involved in this state change is 0x7f4484075668 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1727 __print_debug_details: The current transaction state is Calling [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1728 __print_debug_details: The transaction state change event is TX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CALLING [Apr 2 09:52:53] DEBUG[3585]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=24278 (rdata0x7f44700008e8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 .Incoming Response msg 100/INVITE/cseq=24278 (rdata0x7f44700058b8) in state Calling [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ..State changed from Calling to Proceeding, event=RX_MSG [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Received Response msg 100/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Transaction tsx0x7f4484075668 state changed to Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1726 __print_debug_details: The transaction involved in this state change is 0x7f4484075668 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1727 __print_debug_details: The current transaction state is Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1728 __print_debug_details: The transaction state change event is RX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CALLING [Apr 2 09:52:53] DEBUG[3585]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=24278 (rdata0x7f44700008e8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 .Incoming Response msg 180/INVITE/cseq=24278 (rdata0x7f44700058b8) in state Proceeding [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ..State changed from Proceeding to Proceeding, event=RX_MSG [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Received Response msg 180/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ....Route-set updated [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Transaction tsx0x7f4484075668 state changed to Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1730 __print_debug_details: There is no transaction involved in this state change [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is EARLY [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1868 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1770 handle_incoming: Received response [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1758 handle_incoming_response: Response is 180 ringing [Apr 2 09:52:53] DEBUG[3568]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6001 [Apr 2 09:52:53] DEBUG[3568]: devicestate.c:431 do_state_change: Changing state for PJSIP/6001 - state 6 (Ringing) [Apr 2 09:52:53] DEBUG[3627]: app_queue.c:2316 device_state_cb: Device 'PJSIP/6001' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE -- PJSIP/6001-00000014 is ringing [Apr 2 09:52:53] DEBUG[3568]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6002 [Apr 2 09:52:53] DEBUG[3568]: devicestate.c:431 do_state_change: Changing state for PJSIP/6002 - state 2 (In use) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:53] DEBUG[3627]: app_queue.c:2316 device_state_cb: Device 'PJSIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1726 __print_debug_details: The transaction involved in this state change is 0x7f4484075668 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1727 __print_debug_details: The current transaction state is Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1728 __print_debug_details: The transaction state change event is RX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is EARLY [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1801 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : inv0x7f4484013 .Sending Response msg 180/INVITE/cseq=24021 (tdta0x7f4470002860) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f4484013 ..Sending Response msg 180/INVITE/cseq=24021 (tdta0x7f4470002860) [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f447c003 ..Sending Response msg 180/INVITE/cseq=24021 (tdta0x7f4470002860) in state Proceeding [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : tsx0x7f447c003 ...State changed from Proceeding to Proceeding, event=TX_MSG [Apr 2 09:52:53] DEBUG[3580]: pjsip:0 : dlg0x7f4484013 ....Transaction tsx0x7f447c003098 state changed to Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6002 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f447c003098) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1730 __print_debug_details: There is no transaction involved in this state change [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is EARLY [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1868 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1813 handle_outgoing: Sending response [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1801 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6002 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f447c003098) [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1726 __print_debug_details: The transaction involved in this state change is 0x7f447c003098 [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1727 __print_debug_details: The current transaction state is Proceeding [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1728 __print_debug_details: The transaction state change event is TX_MSG [Apr 2 09:52:53] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is EARLY [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tsx0x7f4484008 Timeout timer event [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tsx0x7f4484008 .State changed from Completed to Terminated, event=TIMER [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tsx0x7f4484008 Timeout timer event [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tsx0x7f4484008 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tdta0x7f448400 ..Destroying txdata Request msg OPTIONS/cseq=5118 (tdta0x7f448400cf80) [Apr 2 09:52:55] DEBUG[3585]: pjsip:0 : tsx0x7f4484008 Transaction destroyed! [Apr 2 09:52:56] DEBUG[3585]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=24278 (rdata0x7f44700008e8) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 .Incoming Response msg 200/INVITE/cseq=24278 (rdata0x7f44700058b8) in state Proceeding [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : tsx0x7f4484075 ..State changed from Proceeding to Terminated, event=RX_MSG [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Received Response msg 200/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ....Route-set updated [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ....Route-set frozen [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : dlg0x7f448403d ...Transaction tsx0x7f4484075668 state changed to Terminated [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1730 __print_debug_details: There is no transaction involved in this state change [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CONNECTING [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1868 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1770 handle_incoming: Received response [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1758 handle_incoming_response: Response is 200 OK [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : inv0x7f448403d ....Got SDP answer in Response msg 200/INVITE/cseq=24278 (rdata0x7f44700058b8) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : inv0x7f448403d ....SDP negotiation done, status=0 [Apr 2 09:52:56] DEBUG[3580]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.18.16' into... [Apr 2 09:52:56] DEBUG[3580]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.18.16' and port ''. -- PJSIP/6001-00000014 answered PJSIP/6002-00000013 [Apr 2 09:52:56] DEBUG[3568]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6001 [Apr 2 09:52:56] DEBUG[3580]: res_rtp_asterisk.c:4151 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f44840f6748' [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f44981509a0 [Apr 2 09:52:56] DEBUG[3568]: devicestate.c:431 do_state_change: Changing state for PJSIP/6001 - state 2 (In use) [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f44981509a0 [Apr 2 09:52:56] DEBUG[3627]: app_queue.c:2316 device_state_cb: Device 'PJSIP/6001' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f44981509a0 to 0x7f44840f6888 [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7f44981509a0 to 0x7f44840f6888 [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : inv0x7f448403d ....Received Response msg 200/INVITE/cseq=24278 (rdata0x7f44700058b8), sending ACK [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : endpoint ....Request msg ACK/cseq=24278 (tdta0x7f447c001030) created. [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : dlg0x7f448403d .....Sending Request msg ACK/cseq=24278 (tdta0x7f447c001030) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : sip_resolve.c .....Target '10.24.18.16:5060' type=Unspecified resolved to '10.24.18.16:5060' type=UDP (UDP transport) [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1721 __print_debug_details: The inv session still has an invite_tsx (0x7f4484075668) [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1730 __print_debug_details: There is no transaction involved in this state change [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CONFIRMED [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1813 handle_outgoing: Sending request [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1786 handle_outgoing_request: Method is ACK [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1707 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1718 __print_debug_details: The state change pertains to the session with 6001 [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1723 __print_debug_details: The inv session does NOT have an invite_tsx [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1726 __print_debug_details: The transaction involved in this state change is 0x7f4484075668 [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1727 __print_debug_details: The current transaction state is Terminated [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1728 __print_debug_details: The transaction state change event is RX_MSG [Apr 2 09:52:56] DEBUG[3580]: res_pjsip_session.c:1732 __print_debug_details: The current inv state is CONFIRMED [Apr 2 09:52:56] DEBUG[3568]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for PJSIP - 6002 [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: features.c:436 clear_dialed_interfaces: Removing dialed interfaces datastore on PJSIP/6001-00000014 since we're bridging [Apr 2 09:52:56] DEBUG[3568]: devicestate.c:431 do_state_change: Changing state for PJSIP/6002 - state 2 (In use) [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge_native_rtp.c:314 native_rtp_bridge_compatible: Bridge 'c9b8ba9e-1d76-42a9-8347-b8e14d1b5288' can not use native RTP bridge as two channels are required [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:496 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:491 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:505 find_best_technology: Chose bridge technology simple_bridge [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:775 bridge_base_init: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: calling simple_bridge technology constructor [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:783 bridge_base_init: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: calling simple_bridge technology start [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge_channel.c:2198 bridge_channel_internal_join: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: 0x7f447400d6e8(PJSIP/6002-00000013) is joining [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge_channel.c:2198 bridge_channel_internal_join: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: 0x7f447400d398(PJSIP/6001-00000014) is joining [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge_channel.c:1788 bridge_channel_internal_push: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: pushing 0x7f447400d6e8(PJSIP/6002-00000013) -- Channel PJSIP/6002-00000013 joined 'simple_bridge' basic-bridge [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge_native_rtp.c:314 native_rtp_bridge_compatible: Bridge 'c9b8ba9e-1d76-42a9-8347-b8e14d1b5288' can not use native RTP bridge as two channels are required [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:496 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:505 find_best_technology: Chose bridge technology simple_bridge [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:1068 smart_bridge_operation: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288 is already using the new technology. [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:962 bridge_make_compatible: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288 is happy that channel PJSIP/6002-00000013 already has read format ulaw [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:986 bridge_make_compatible: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288 is happy that channel PJSIP/6002-00000013 already has write format ulaw [Apr 2 09:52:56] DEBUG[4004][C-0000000d]: bridge.c:424 bridge_channel_complete_join: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: 0x7f447400d6e8(PJSIP/6002-00000013) is joining simple_bridge technology [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge_channel.c:1788 bridge_channel_internal_push: Bridge c9b8ba9e-1d76-42a9-8347-b8e14d1b5288: pushing 0x7f447400d398(PJSIP/6001-00000014) [Apr 2 09:52:56] DEBUG[3580]: pjsip:0 : inv0x7f4484013 .SDP negotiation done, status=0 -- Channel PJSIP/6001-00000014 joined 'simple_bridge' basic-bridge [Apr 2 09:52:56] DEBUG[3580]: sdp_srtp.c:289 ast_sdp_crypto_process: SRTP remote key unchanged; maintaining current policy [Apr 2 09:52:56] DEBUG[3580]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '216.207.245.1' into... [Apr 2 09:52:56] DEBUG[3580]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '216.207.245.1' and port ''. [Apr 2 09:52:56] DEBUG[3580]: res_rtp_asterisk.c:4151 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f44840d51b8' [Apr 2 09:52:56] DEBUG[3570]: cdr.c:1271 cdr_object_finalize: Finalized CDR for PJSIP/6001-00000014 - start 1396450373.444155 answer 1396450376.763776 end 1396450376.765775 dispo ANSWERED [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge.c:486 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f4498150bb0 [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge_native_rtp.c:333 native_rtp_bridge_compatible: Bridge 'c9b8ba9e-1d76-42a9-8347-b8e14d1b5288' can not use native RTP bridge as it was forbidden while getting details [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge.c:496 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 2 09:52:56] DEBUG[3580]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 126 based on m type on 0x7f4498150bb0 [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge.c:486 find_best_technology: Bridge technology softmix does not have any capabilities we want. asterisk: ../src/pj/lock.c:286: grp_lock_acquire: Assertion `pj_atomic_get(glock->ref_cnt) > 0' failed. [Apr 2 09:52:56] DEBUG[4007][C-0000000d]: bridge.c:505 find_best_technology: Chose bridge technology simple_bridge Aborted (core dumped)