[Apr 2 17:28:01] Asterisk SVN-trunk-r431522M built by root @ stnrd5652 on a x86_64 running Linux on 2015-03-31 13:49:49 UTC [Apr 2 17:28:01] DEBUG[19280] config.c: Parsing /etc/asterisk/logger.conf [Apr 2 17:28:58] DEBUG[19262] manager.c: Running action 'Originate' [Apr 2 17:28:58] DEBUG[19208] threadpool.c: Increasing threadpool SIP's size by 5 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 UAC dialog created [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module Outbound Authentica added as dialog usage, data=0x7fa6b4002f40 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module mod-invite added as dialog usage, data=0x7fa6b4003428 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 .Session count inc to 2 by mod-invite [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module mod-100rel added as dialog usage, data=0x7fa6b4002f50 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 100rel module attached [Apr 2 17:28:58] DEBUG[19286] pjsip: inv0x7fa6b0011 UAC invite session created for dialog dlg0x7fa6b00117a8 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 .Session count inc to 2 by Session Module [Apr 2 17:28:58] DEBUG[19286] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 2 17:28:58] DEBUG[19286] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module Session Module added as dialog usage, data=(nil) [Apr 2 17:28:58] DEBUG[19185] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 2 17:28:58] DEBUG[19286] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa6b40063d8' [Apr 2 17:28:58] DEBUG[19286] res_rtp_asterisk.c: Allocated port 17842 for RTP instance '0x7fa6b40063d8' [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 ICE session created, comp_cnt=2, role is Unknown agent [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha020071, addr=10.2.0.113:17842, base=10.2.0.113:17842, prio=0x7effffff (2130706431) [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 1 added: comp_id=1, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:17842, base=10.2.0.113:17842, prio=0x64ffffff (1694498815) [Apr 2 17:28:58] DEBUG[19286] rtp_engine.c: RTP instance '0x7fa6b40063d8' is setup and ready to go [Apr 2 17:28:58] DEBUG[19286] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa6b40063d8' [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 2 added: comp_id=2, type=host, foundation=Ha020071, addr=10.2.0.113:17843, base=10.2.0.113:17843, prio=0x7efffffe (2130706430) [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 3 added: comp_id=2, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:17843, base=10.2.0.113:17843, prio=0x64fffffe (1694498814) [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Destroying ICE session 0x7fa6b400a788 [Apr 2 17:28:58] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b400c798 destroy request, ref_cnt=4 [Apr 2 17:28:58] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b400d388 destroy request, ref_cnt=3 [Apr 2 17:28:58] DEBUG[19286] pjsip: ice_session.c ICE session 0x7fa6b400a788 destroyed [Apr 2 17:28:58] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b400c798 destroyed [Apr 2 17:28:58] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b400d388 destroyed [Apr 2 17:28:58] DEBUG[19286] pjsip: endpoint Request msg INVITE/cseq=1677 (tdta0x7fa6b0043010) created. [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module NAT added as dialog usage, data=(nil) [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 Module WebSocket Transport Module added as dialog usage, data=(nil) [Apr 2 17:28:58] DEBUG[19286] pjsip: inv0x7fa6b0011 .Sending Request msg INVITE/cseq=1677 (tdta0x7fa6b0043010) [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 ..Sending Request msg INVITE/cseq=1677 (tdta0x7fa6b0043010) [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b003b ...Transaction created for Request msg INVITE/cseq=1676 (tdta0x7fa6b0043010) [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b003b ..Sending Request msg INVITE/cseq=1676 (tdta0x7fa6b0043010) in state Null [Apr 2 17:28:58] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:0' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b003b ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b0011 ....Transaction tsx0x7fa6b003bad8 state changed to Calling [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:58] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1676 (rdata0x7fa71000f888) [Apr 2 17:28:58] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:58] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:58] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:58] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:58] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1676 (rdata0x7fa71000d538) [Apr 2 17:28:58] DEBUG[19286] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username 'b3f6fd9b-c34b-444a-bc05-8403a0a6bb37' [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:58] DEBUG[19286] res_pjsip_endpoint_identifier_ip.c: Source address 127.0.0.1:5060 matches identify 'receiver' [Apr 2 17:28:58] DEBUG[19286] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint receiver [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b0014 ..Transaction created for Request msg INVITE/cseq=1676 (rdata0x7fa71000d538) [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b0014 .Incoming Request msg INVITE/cseq=1676 (rdata0x7fa71000d538) in state Null [Apr 2 17:28:58] DEBUG[19286] pjsip: tsx0x7fa6b0014 ..State changed from Null to Trying, event=RX_MSG [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d ...Transaction tsx0x7fa6b0014b98 state changed to Trying [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d .UAS dialog created [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d .Module mod-invite added as dialog usage, data=0x7fa6b4019c38 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d ..Session count inc to 2 by mod-invite [Apr 2 17:28:58] DEBUG[19286] pjsip: inv0x7fa6b003d .UAS invite session created for dialog dlg0x7fa6b003d8c8 [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d .Module Session Module added as dialog usage, data=(nil) [Apr 2 17:28:58] DEBUG[19286] pjsip: dlg0x7fa6b003d ..Session count inc to 2 by Session Module [Apr 2 17:28:58] DEBUG[19286] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 2 17:28:58] DEBUG[19286] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 2 17:28:58] DEBUG[19286] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:58] DEBUG[19286] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa6b4014448' [Apr 2 17:28:58] DEBUG[19286] res_rtp_asterisk.c: Allocated port 18000 for RTP instance '0x7fa6b4014448' [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 ICE session created, comp_cnt=2, role is Unknown agent [Apr 2 17:28:58] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:58] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:58] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha020071, addr=10.2.0.113:18000, base=10.2.0.113:18000, prio=0x7effffff (2130706431) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 1 added: comp_id=1, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18000, base=10.2.0.113:18000, prio=0x64ffffff (1694498815) [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: RTP instance '0x7fa6b4014448' is setup and ready to go [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa6b4014448' [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 2 added: comp_id=2, type=host, foundation=Ha020071, addr=10.2.0.113:18001, base=10.2.0.113:18001, prio=0x7efffffe (2130706430) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 3 added: comp_id=2, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18001, base=10.2.0.113:18001, prio=0x64fffffe (1694498814) [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Destroying ICE session 0x7fa6b40218e8 [Apr 2 17:28:59] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b4023f18 destroy request, ref_cnt=4 [Apr 2 17:28:59] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b4024f18 destroy request, ref_cnt=3 [Apr 2 17:28:59] DEBUG[19286] pjsip: ice_session.c ICE session 0x7fa6b40218e8 destroyed [Apr 2 17:28:59] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b4023f18 destroyed [Apr 2 17:28:59] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b4024f18 destroyed [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Setting payload 8 (0x7fa6b40150d8) based on m type on 0x7fa7240c7580 [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Copying payload 8 (0x7fa6b40139d8) from 0x7fa7240c7580 to 0x7fa6b4014610 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint .Response msg 100/INVITE/cseq=1676 (tdta0x7fa710012360) created [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b003d .Initial answer Response msg 100/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b003d .Sending Response msg 100/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b003d ..Sending Response msg 100/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0014 ..Sending Response msg 100/INVITE/cseq=1676 (tdta0x7fa710012360) in state Trying [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0014 ...State changed from Trying to Proceeding, event=TX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b0014b98 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is INCOMING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is INCOMING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=1676 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b003d Module NAT added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=1676 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19286] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/receiver-00000005 [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b003b .Incoming Response msg 100/INVITE/cseq=1676 (rdata0x7fa71000cd78) in state Calling [Apr 2 17:28:59] DEBUG[19293][C-00000003] pbx.c: Launching 'NoOp' [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b003b ..State changed from Calling to Proceeding, event=RX_MSG [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0011 ...Received Response msg 100/INVITE/cseq=1676 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0011 ...Transaction tsx0x7fa6b003bad8 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Response is 100 Trying [Apr 2 17:28:59] DEBUG[19293][C-00000003] pbx.c: Launching 'Dial' [Apr 2 17:28:59] DEBUG[19293][C-00000003] pbx_lua.c: Looking up dtmf_inband@default:-1 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c UAC dialog created [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module Outbound Authentica added as dialog usage, data=0x7fa6b402a760 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module mod-invite added as dialog usage, data=0x7fa6b402ac58 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c .Session count inc to 2 by mod-invite [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module mod-100rel added as dialog usage, data=0x7fa6b402a770 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c 100rel module attached [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c UAC invite session created for dialog dlg0x7fa6b000c648 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c .Session count inc to 2 by Session Module [Apr 2 17:28:59] DEBUG[19286] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 2 17:28:59] DEBUG[19286] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module Session Module added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa6b40154f8' [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Allocated port 18222 for RTP instance '0x7fa6b40154f8' [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 ICE session created, comp_cnt=2, role is Unknown agent [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 0 added: comp_id=1, type=host, foundation=Ha020071, addr=10.2.0.113:18222, base=10.2.0.113:18222, prio=0x7effffff (2130706431) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 1 added: comp_id=1, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18222, base=10.2.0.113:18222, prio=0x64ffffff (1694498815) [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: RTP instance '0x7fa6b40154f8' is setup and ready to go [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa6b40154f8' [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 2 added: comp_id=2, type=host, foundation=Ha020071, addr=10.2.0.113:18223, base=10.2.0.113:18223, prio=0x7efffffe (2130706430) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Candidate 3 added: comp_id=2, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18223, base=10.2.0.113:18223, prio=0x64fffffe (1694498814) [Apr 2 17:28:59] DEBUG[19286] pjsip: icess0x7fa6b40 Destroying ICE session 0x7fa6b402bcd8 [Apr 2 17:28:59] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b4026298 destroy request, ref_cnt=4 [Apr 2 17:28:59] DEBUG[19286] pjsip: stuse0x7fa6b40 STUN session 0x7fa6b401d308 destroy request, ref_cnt=3 [Apr 2 17:28:59] DEBUG[19286] pjsip: ice_session.c ICE session 0x7fa6b402bcd8 destroyed [Apr 2 17:28:59] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b4026298 destroyed [Apr 2 17:28:59] DEBUG[19286] pjsip: stun_session.c STUN session 0x7fa6b401d308 destroyed [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint Request msg INVITE/cseq=6368 (tdta0x7fa6b4017630) created. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module NAT added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c Module WebSocket Transport Module added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c .Sending Request msg INVITE/cseq=6368 (tdta0x7fa6b4017630) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ..Sending Request msg INVITE/cseq=6368 (tdta0x7fa6b4017630) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e ...Transaction created for Request msg INVITE/cseq=6367 (tdta0x7fa6b4017630) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e ..Sending Request msg INVITE/cseq=6367 (tdta0x7fa6b4017630) in state Null [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:0' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b003d .Sending Response msg 180/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ..Sending Response msg 180/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Sending Response msg 180/INVITE/cseq=1676 (tdta0x7fa710012360) in state Proceeding [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Proceeding to Proceeding, event=TX_MSG [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b0014b98 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is EARLY [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=1676 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Transaction tsx0x7fa6b001e2c8 state changed to Calling [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is EARLY [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=1676 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=6367 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b003b .Incoming Response msg 180/INVITE/cseq=1676 (rdata0x7fa71000cd78) in state Proceeding [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b003b ..State changed from Proceeding to Proceeding, event=RX_MSG [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ...Received Response msg 180/INVITE/cseq=1676 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ....Route-set updated [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ...Transaction tsx0x7fa6b003bad8 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19288] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=6367 (rdata0x7fa7100068e8) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username 'b3f6fd9b-c34b-444a-bc05-8403a0a6bb37' [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19288] res_pjsip_endpoint_identifier_ip.c: Source address 127.0.0.1:5060 matches identify 'receiver' [Apr 2 17:28:59] DEBUG[19288] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint receiver [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0004 ..Transaction created for Request msg INVITE/cseq=6367 (rdata0x7fa7100068e8) [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0004 .Incoming Request msg INVITE/cseq=6367 (rdata0x7fa7100068e8) in state Null [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0004 ..State changed from Null to Trying, event=RX_MSG [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 ...Transaction tsx0x7fa6b0004e28 state changed to Trying [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 .UAS dialog created [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 .Module mod-invite added as dialog usage, data=0x7fa70c005fc8 [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 ..Session count inc to 2 by mod-invite [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b0033 .UAS invite session created for dialog dlg0x7fa6b00335e8 [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 .Module Session Module added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 ..Session count inc to 2 by Session Module [Apr 2 17:28:59] DEBUG[19288] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 2 17:28:59] DEBUG[19288] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fa70c00c1f8' [Apr 2 17:28:59] DEBUG[19288] res_rtp_asterisk.c: Allocated port 18162 for RTP instance '0x7fa70c00c1f8' [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 ICE session created, comp_cnt=2, role is Unknown agent [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 Candidate 0 added: comp_id=1, type=host, foundation=Ha020071, addr=10.2.0.113:18162, base=10.2.0.113:18162, prio=0x7effffff (2130706431) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is EARLY [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 180 Ringing [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is EARLY [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 180 Ringing [Apr 2 17:28:59] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - dtmf_inband [Apr 2 17:28:59] DEBUG[19197] devicestate.c: Changing state for PJSIP/dtmf_inband - state 6 (Ringing) [Apr 2 17:28:59] DEBUG[19255] app_queue.c: Device 'PJSIP/dtmf_inband' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 Candidate 1 added: comp_id=1, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18162, base=10.2.0.113:18162, prio=0x64ffffff (1694498815) [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: RTP instance '0x7fa70c00c1f8' is setup and ready to go [Apr 2 17:28:59] DEBUG[19288] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa70c00c1f8' [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 Candidate 2 added: comp_id=2, type=host, foundation=Ha020071, addr=10.2.0.113:18163, base=10.2.0.113:18163, prio=0x7efffffe (2130706430) [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '62.219.92.22' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '62.219.92.22' and port ''. [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '10.2.0.113' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '10.2.0.113' and port ''. [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 Candidate 3 added: comp_id=2, type=srflx, foundation=S3edb5c16, addr=62.219.92.22:18163, base=10.2.0.113:18163, prio=0x64fffffe (1694498814) [Apr 2 17:28:59] DEBUG[19288] pjsip: icess0x7fa70c0 Destroying ICE session 0x7fa70c00fd68 [Apr 2 17:28:59] DEBUG[19288] pjsip: stuse0x7fa70c0 STUN session 0x7fa70c0125a8 destroy request, ref_cnt=4 [Apr 2 17:28:59] DEBUG[19288] pjsip: stuse0x7fa70c0 STUN session 0x7fa70c0135a8 destroy request, ref_cnt=3 [Apr 2 17:28:59] DEBUG[19288] pjsip: ice_session.c ICE session 0x7fa70c00fd68 destroyed [Apr 2 17:28:59] DEBUG[19288] pjsip: stun_session.c STUN session 0x7fa70c0125a8 destroyed [Apr 2 17:28:59] DEBUG[19288] pjsip: stun_session.c STUN session 0x7fa70c0135a8 destroyed [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Setting payload 8 (0x7fa70c0047d8) based on m type on 0x7fa725310580 [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Copying payload 8 (0x7fa70c007638) from 0x7fa725310580 to 0x7fa70c00c3c0 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 2 17:28:59] DEBUG[19288] pjsip: endpoint .Response msg 100/INVITE/cseq=6367 (tdta0x7fa6b4005310) created [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 .Initial answer Response msg 100/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b0033 .Sending Response msg 100/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 ..Sending Response msg 100/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0004 ..Sending Response msg 100/INVITE/cseq=6367 (tdta0x7fa6b4005310) in state Trying [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0004 ...State changed from Trying to Proceeding, event=TX_MSG [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0004e28 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0004e28) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current inv state is INCOMING [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=6367 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0004e28) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current inv state is INCOMING [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0033 Module NAT added as dialog usage, data=(nil) [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=6367 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e .Incoming Response msg 100/INVITE/cseq=6367 (rdata0x7fa71000cd78) in state Calling [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e ..State changed from Calling to Proceeding, event=RX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Received Response msg 100/INVITE/cseq=6367 (rdata0x7fa71000cd78) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Transaction tsx0x7fa6b001e2c8 state changed to Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Proceeding [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CALLING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 100 Trying [Apr 2 17:28:59] DEBUG[19288] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/receiver-00000007 [Apr 2 17:28:59] DEBUG[19294][C-00000004] pbx.c: Launching 'NoOp' [Apr 2 17:28:59] DEBUG[19294][C-00000004] pbx.c: Launching 'DumpChan' [Apr 2 17:28:59] DEBUG[19294][C-00000004] pbx.c: Launching 'Answer' [Apr 2 17:28:59] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - receiver [Apr 2 17:28:59] DEBUG[19197] devicestate.c: Changing state for PJSIP/receiver - state 2 (In use) [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b0033 .SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19255] app_queue.c: Device 'PJSIP/receiver' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa70c00c1f8' [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Setting payload 8 (0x7fa6b4026868) based on m type on 0x7fa7240c6f60 [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Copying payload 8 (0x7fa6b40325a8) from 0x7fa7240c6f60 to 0x7fa70c00c3c0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b0033 .Sending Response msg 200/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0033 ..Sending Response msg 200/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ..Sending Response msg 200/INVITE/cseq=6367 (tdta0x7fa6b4005310) in state Proceeding [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ...State changed from Proceeding to Completed, event=TX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0004e28 state changed to Completed [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0004e28) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=6367 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0004e28) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=6367 (rdata0x7fa710005148) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e .Incoming Response msg 200/INVITE/cseq=6367 (rdata0x7fa710005148) in state Proceeding [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b001e ..State changed from Proceeding to Terminated, event=RX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Received Response msg 200/INVITE/cseq=6367 (rdata0x7fa710005148) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Route-set updated [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Route-set frozen [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Transaction tsx0x7fa6b001e2c8 state changed to Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....Got SDP answer in Response msg 200/INVITE/cseq=6367 (rdata0x7fa710005148) [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b40154f8' [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Setting payload 8 (0x7fa6b4014a68) based on m type on 0x7fa7240c6c90 [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Copying payload 8 (0x7fa6b4032138) from 0x7fa7240c6c90 to 0x7fa6b40156c0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....Received Response msg 200/INVITE/cseq=6367 (rdata0x7fa710005148), sending ACK [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint ....Request msg ACK/cseq=6367 (tdta0x7fa71000bd40) created. [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c .....Sending Request msg ACK/cseq=6367 (tdta0x7fa71000bd40) [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_resolve.c .....Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is ACK [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=6367 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19185] threadpool.c: Increasing threadpool stasis-core's size by 1 [Apr 2 17:28:59] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - dtmf_inband [Apr 2 17:28:59] DEBUG[19197] devicestate.c: Changing state for PJSIP/dtmf_inband - state 7 (Ring+Inuse) [Apr 2 17:28:59] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - receiver [Apr 2 17:28:59] DEBUG[19197] devicestate.c: Changing state for PJSIP/receiver - state 2 (In use) [Apr 2 17:28:59] DEBUG[19255] app_queue.c: Device 'PJSIP/dtmf_inband' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=6367 (rdata0x7fa710007c88) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0033 .Received Request msg ACK/cseq=6367 (rdata0x7fa710007c88) [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b003d .SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ..Request to terminate transaction [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ...State changed from Completed to Terminated, event=USER [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0004e28 state changed to Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19287] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b4014448' [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is USER [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Setting payload 8 (0x7fa6a80011f8) based on m type on 0x7fa6bf7b4f60 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Copying payload 8 (0x7fa6a8002078) from 0x7fa6bf7b4f60 to 0x7fa6b4014610 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received request [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is ACK [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b003d .Sending Response msg 200/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ..Sending Response msg 200/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Sending Response msg 200/INVITE/cseq=1676 (tdta0x7fa710012360) in state Proceeding [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Proceeding to Completed, event=TX_MSG [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b0014b98 state changed to Completed [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Source of transaction state change is TX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=1676 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e Timeout timer event [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=1676 (rdata0x7fa710007c88) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b003b .Incoming Response msg 200/INVITE/cseq=1676 (rdata0x7fa710007c88) in state Proceeding [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e Transaction destroyed! [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b003b ..State changed from Proceeding to Terminated, event=RX_MSG [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 Timeout timer event [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ...Received Response msg 200/INVITE/cseq=1676 (rdata0x7fa710007c88) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ....Route-set updated [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa6b400 ..Destroying txdata Response msg 200/INVITE/cseq=6367 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ....Route-set frozen [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 Transaction destroyed! [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 ...Transaction tsx0x7fa6b003bad8 state changed to Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19293][C-00000003] features.c: Removing dialed interfaces datastore on PJSIP/dtmf_inband-00000006 since we're bridging [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19293][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: Cannot use native DAHDI. Must have two channels. [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b0011 ....Got SDP answer in Response msg 200/INVITE/cseq=1676 (rdata0x7fa710007c88) [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge_native_rtp.c: Bridge '01da7821-9859-4d88-bbde-55efe5bb7aaf' can not use native RTP bridge as two channels are required [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Chose bridge technology simple_bridge [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling simple_bridge technology constructor [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b0011 ....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling simple_bridge technology start [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014818(PJSIP/receiver-00000005) is joining [Apr 2 17:28:59] DEBUG[19286] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b40063d8' [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: pushing 0x7fa6d4014818(PJSIP/receiver-00000005) [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Setting payload 8 (0x7fa6b4014a68) based on m type on 0x7fa7240c6c30 [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Copying payload 8 (0x7fa6b4012ea8) from 0x7fa7240c6c30 to 0x7fa6b40065a0 [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) is joining [Apr 2 17:28:59] DEBUG[19293][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: Cannot use native DAHDI. Must have two channels. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge_native_rtp.c: Bridge '01da7821-9859-4d88-bbde-55efe5bb7aaf' can not use native RTP bridge as two channels are required [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Chose bridge technology simple_bridge [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is already using the new technology. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/receiver-00000005 already has read format alaw [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/receiver-00000005 already has write format alaw [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014818(PJSIP/receiver-00000005) is joining simple_bridge technology [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b0011 ....Received Response msg 200/INVITE/cseq=1676 (rdata0x7fa710007c88), sending ACK [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint ....Request msg ACK/cseq=1676 (tdta0x7fa6b4005310) created. [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b0011 .....Sending Request msg ACK/cseq=1676 (tdta0x7fa6b4005310) [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_resolve.c .....Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b003bad8) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1676 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is ACK [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - dtmf_inband [Apr 2 17:28:59] DEBUG[19197] devicestate.c: Changing state for PJSIP/dtmf_inband - state 2 (In use) [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1676 (rdata0x7fa710014318) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d .Received Request msg ACK/cseq=1676 (rdata0x7fa710014318) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Request to terminate transaction [Apr 2 17:28:59] DEBUG[19292][C-00000005] pbx.c: Launching 'NoOp' [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Completed to Terminated, event=USER [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b0014b98 state changed to Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is USER [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONNECTING [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19255] app_queue.c: Device 'PJSIP/dtmf_inband' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984938.7 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Received request [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is ACK [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984938.7 Extension: s Application: AppDial2 AppData: (Outgoing Line) [Apr 2 17:28:59] DEBUG[19292][C-00000005] pbx.c: Launching 'DumpChan' [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: PJSIP/dtmf_inband-00000004 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1427984938.7 DialString: dtmf_inband@dtmf_inband [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: pushing 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984939.8 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 1 Uniqueid: 1427984939.8 Extension: dtmf_inband Application: NoOp AppData: YARON Is HERE DIAL [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 Extension: dtmf_inband Application: Dial AppData: PJSIP/receiver@dtmf_inband [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984939.9 [Apr 2 17:28:59] DEBUG[19199] cdr.c: Finalized CDR for PJSIP/dtmf_inband-00000006 - start 1427984939.124828 answer 1427984939.472173 end 1427984939.473451 dispo ANSWERED [Apr 2 17:28:59] DEBUG[19296][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/receiver-00000005' is not DAHDI. [Apr 2 17:28:59] DEBUG[19296][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: Cannot use native DAHDI. Channel 'PJSIP/receiver-00000005' not compatible. [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 1 Uniqueid: 1427984939.9 Extension: dtmf_inband Application: AppDial AppData: (Outgoing Line) [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19292][C-00000005] pbx.c: Launching 'SendDTMF' [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 1 Uniqueid: 1427984939.9 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Chose bridge technology native_rtp [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 1 Uniqueid: 1427984939.9 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 DestChannel: PJSIP/dtmf_inband-00000006 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: dtmf_inband DestCallerIDName: DestConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: dtmf_inband DestPriority: 1 DestUniqueid: 1427984939.9 DialString: receiver@dtmf_inband [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling native_rtp technology constructor [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: moving 0x7fa6d4014818(PJSIP/receiver-00000005) to dummy bridge temporarily [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014818(PJSIP/receiver-00000005) is leaving simple_bridge technology (dummy) [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling simple_bridge technology stop [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984938.7 [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/dtmf_inband-00000006 already has read format alaw [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/dtmf_inband-00000006 already has write format alaw [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) is joining native_rtp technology [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/dtmf_inband State: RINGING [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984939.10 [Apr 2 17:28:59] DEBUG[19296][C-00000003] chan_pjsip.c: RTP changed on PJSIP/dtmf_inband-00000006; initiating direct media update [Apr 2 17:28:59] DEBUG[19296][C-00000003] chan_pjsip.c: RTP changed on PJSIP/receiver-00000005; initiating direct media update [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 1 Uniqueid: 1427984939.10 Extension: receiver Application: NoOp AppData: YARON Is HERE RECEIVER [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/receiver-00000005 already has read format alaw [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 2 Uniqueid: 1427984939.10 Extension: receiver Application: DumpChan AppData: [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is happy that channel PJSIP/receiver-00000005 already has write format alaw [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014818(PJSIP/receiver-00000005) is joining native_rtp technology [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 3 Uniqueid: 1427984939.10 Extension: receiver Application: Answer AppData: [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling native_rtp technology start [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 3 Uniqueid: 1427984939.10 [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling simple_bridge technology destructor [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/receiver State: INUSE [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 1 Uniqueid: 1427984939.9 [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint .Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) created. [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 DestChannel: PJSIP/dtmf_inband-00000006 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: dtmf_inband DestCallerIDName: DestConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: DestPriority: 1 DestUniqueid: 1427984939.9 DialStatus: ANSWER [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/dtmf_inband State: RINGINUSE [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1427984939.9 Extension: Application: AppDial AppData: (Outgoing Line) [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1427984938.7 [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: PJSIP/dtmf_inband-00000004 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1427984938.7 DialStatus: ANSWER [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c .Sending Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) [Apr 2 17:28:59] DEBUG[19287] pjsip: endpoint .Request msg INVITE/cseq=28771 (tdta0x7fa6b001d210) created. [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/dtmf_inband State: INUSE [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ..Sending Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 1 Uniqueid: 1427984938.7 Extension: senddtmf Application: NoOp AppData: YARON Is HERE SENDDTMF [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 2 Uniqueid: 1427984938.7 Extension: senddtmf Application: DumpChan AppData: [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 Channel: PJSIP/dtmf_inband-00000006 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1427984939.9 [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ...Transaction created for Request msg INVITE/cseq=6368 (tdta0x7fa710001cb0) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ..Sending Request msg INVITE/cseq=6368 (tdta0x7fa710001cb0) in state Null [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 3 Uniqueid: 1427984938.7 Extension: senddtmf Application: SendDTMF AppData: 1 [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b003d .Sending Request msg INVITE/cseq=28771 (tdta0x7fa6b001d210) [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ..Sending Request msg INVITE/cseq=28771 (tdta0x7fa6b001d210) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b001e ...Transaction created for Request msg INVITE/cseq=28770 (tdta0x7fa6b001d210) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b001e ..Sending Request msg INVITE/cseq=28770 (tdta0x7fa6b001d210) in state Null [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_resolve.c ...Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19293][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/dtmf_inband-00000006' is not DAHDI. [Apr 2 17:28:59] DEBUG[19293][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: Cannot use native DAHDI. Channel 'PJSIP/dtmf_inband-00000006' not compatible. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Chose bridge technology native_rtp [Apr 2 17:28:59] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is already using the new technology. [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b001e ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b001e2c8 state changed to Calling [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=6368 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19296][C-00000003] dahdi/bridge_native_dahdi.c: Channel 'PJSIP/dtmf_inband-00000006' is not DAHDI. [Apr 2 17:28:59] DEBUG[19296][C-00000003] dahdi/bridge_native_dahdi.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: Cannot use native DAHDI. Channel 'PJSIP/dtmf_inband-00000006' not compatible. [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=28770 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge technology softmix does not have any capabilities we want. [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Chose bridge technology native_rtp [Apr 2 17:28:59] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is already using the new technology. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 .Received Request msg INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ...Transaction created for Request msg INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ..Incoming Request msg INVITE/cseq=6368 (rdata0x7fa710014ad8) in state Null [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ...State changed from Null to Trying, event=RX_MSG [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0016988 state changed to Trying [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b0033 .....Got SDP offer in Request msg INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=28770 (rdata0x7fa710018d68) [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa71001 ..Destroying txdata Response msg 200/INVITE/cseq=1676 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 Transaction destroyed! [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0011 .Received Request msg INVITE/cseq=28770 (rdata0x7fa710018d68) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b003b Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b003b .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Setting payload 8 (0x7fa6a8002188) based on m type on 0x7fa6bf7b5030 [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0014 ...Transaction created for Request msg INVITE/cseq=28770 (rdata0x7fa710018d68) [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0014 ..Incoming Request msg INVITE/cseq=28770 (rdata0x7fa710018d68) in state Null [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Copying payload 8 (0x7fa6a8003088) from 0x7fa6bf7b5030 to 0x7fa70c00c3c0 [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0014 ...State changed from Null to Trying, event=RX_MSG [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0011 ....Transaction tsx0x7fa6b0014b98 state changed to Trying [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b0011 .....Got SDP offer in Request msg INVITE/cseq=28770 (rdata0x7fa710018d68) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Transaction tsx0x7fa6b0004e28 state changed to Calling [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0004e28) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Setting payload 8 (0x7fa70c007638) based on m type on 0x7fa725310030 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Copying payload 8 (0x7fa70c01dc58) from 0x7fa725310030 to 0x7fa6b40065a0 [Apr 2 17:28:59] DEBUG[19287] pjsip: endpoint .....Response msg 200/INVITE/cseq=6368 (tdta0x7fa710012360) created [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b0033 .....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19288] pjsip: endpoint .....Response msg 200/INVITE/cseq=28770 (tdta0x7fa710004110) created [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b0011 .....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19288] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b40063d8' [Apr 2 17:28:59] DEBUG[19287] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa70c00c1f8' [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Setting payload 8 (0x7fa70c007638) based on m type on 0x7fa72530fae0 [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Copying payload 8 (0x7fa70c011528) from 0x7fa72530fae0 to 0x7fa6b40065a0 [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Setting payload 8 (0x7fa6a8004cd8) based on m type on 0x7fa6bf7b4ae0 [Apr 2 17:28:59] DEBUG[19287] rtp_engine.c: Copying payload 8 (0x7fa6a8003e78) from 0x7fa6bf7b4ae0 to 0x7fa70c00c3c0 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b003b Transaction destroyed! [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b0011 ......Sending Response msg 200/INVITE/cseq=28770 (tdta0x7fa710004110) [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0011 .......Sending Response msg 200/INVITE/cseq=28770 (tdta0x7fa710004110) [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0014 .......Sending Response msg 200/INVITE/cseq=28770 (tdta0x7fa710004110) in state Trying [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b0014 ........State changed from Trying to Completed, event=TX_MSG [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b0011 .........Transaction tsx0x7fa6b0014b98 state changed to Completed [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=28770 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Received request [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19287] pjsip: inv0x7fa6b0033 ......Sending Response msg 200/INVITE/cseq=6368 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19288] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=28770 (rdata0x7fa71001e358) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 .......Sending Response msg 200/INVITE/cseq=6368 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b001e .Incoming Response msg 200/INVITE/cseq=28770 (rdata0x7fa71001e358) in state Calling [Apr 2 17:28:59] DEBUG[19288] pjsip: tsx0x7fa6b001e ..State changed from Calling to Terminated, event=RX_MSG [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b003d ...Received Response msg 200/INVITE/cseq=28770 (rdata0x7fa71001e358) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 .......Sending Response msg 200/INVITE/cseq=6368 (tdta0x7fa710012360) in state Trying [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b003d ...Transaction tsx0x7fa6b001e2c8 state changed to Terminated [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b003d ....Got SDP answer in Response msg 200/INVITE/cseq=28770 (rdata0x7fa71001e358) [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b003d ....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Setting payload 8 (0x7fa70c007638) based on m type on 0x7fa72530fb20 [Apr 2 17:28:59] DEBUG[19288] rtp_engine.c: Copying payload 8 (0x7fa70c004748) from 0x7fa72530fb20 to 0x7fa6b4014610 [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19288] pjsip: inv0x7fa6b003d ....Received Response msg 200/INVITE/cseq=28770 (rdata0x7fa71001e358), sending ACK [Apr 2 17:28:59] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] pjsip: endpoint ....Request msg ACK/cseq=28770 (tdta0x7fa70c0280b0) created. [Apr 2 17:28:59] DEBUG[19288] pjsip: dlg0x7fa6b003d .....Sending Request msg ACK/cseq=28770 (tdta0x7fa70c0280b0) [Apr 2 17:28:59] DEBUG[19288] pjsip: sip_resolve.c .....Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ........State changed from Trying to Completed, event=TX_MSG [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 .........Transaction tsx0x7fa6b0016988 state changed to Completed [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0016988) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:28:59] DEBUG[19288] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=6368 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19288] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0016988) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Received request [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Method is INVITE [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19288] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 .Incoming Response msg 200/INVITE/cseq=6368 (rdata0x7fa710014ad8) in state Calling [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=28770 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19286] pjsip: tsx0x7fa6b0004 ..State changed from Calling to Terminated, event=RX_MSG [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Received Response msg 200/INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Transaction tsx0x7fa6b0004e28 state changed to Terminated [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....Got SDP answer in Response msg 200/INVITE/cseq=6368 (rdata0x7fa710014ad8) [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....SDP negotiation done, status=0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Setting payload 8 (0x7fa6b40139d8) based on m type on 0x7fa7240c6b20 [Apr 2 17:28:59] DEBUG[19286] rtp_engine.c: Copying payload 8 (0x7fa6b40325a8) from 0x7fa7240c6b20 to 0x7fa6b40156c0 [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=28770 (rdata0x7fa710023998) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0011 .Received Request msg ACK/cseq=28770 (rdata0x7fa710023998) [Apr 2 17:28:59] DEBUG[19286] pjsip: inv0x7fa6b000c ....Received Response msg 200/INVITE/cseq=6368 (rdata0x7fa710014ad8), sending ACK [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Request to terminate transaction [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Completed to Terminated, event=USER [Apr 2 17:28:59] DEBUG[19286] pjsip: tdta0x7fa71000 ....Destroying txdata Request msg ACK/cseq=6367 (tdta0x7fa71000bd40) [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0011 ....Transaction tsx0x7fa6b0014b98 state changed to Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19286] pjsip: endpoint ....Request msg ACK/cseq=6368 (tdta0x7fa71000bd40) created. [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is USER [Apr 2 17:28:59] DEBUG[19286] pjsip: dlg0x7fa6b000c .....Sending Request msg ACK/cseq=6368 (tdta0x7fa71000bd40) [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19286] pjsip: sip_resolve.c .....Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=6368 (rdata0x7fa71000f888) [Apr 2 17:28:59] DEBUG[19293][C-00000003] channel.c: Ignoring answer on an inbound call! [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:28:59] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa71000 ..Destroying txdata Response msg 200/INVITE/cseq=28770 (tdta0x7fa710004110) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0014 Transaction destroyed! [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa6b001 ..Destroying txdata Request msg INVITE/cseq=28770 (tdta0x7fa6b001d210) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b001e Transaction destroyed! [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:28:59] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=6368 (rdata0x7fa710023998) [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:28:59] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 .Received Request msg ACK/cseq=6368 (rdata0x7fa710023998) [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ..Request to terminate transaction [Apr 2 17:28:59] DEBUG[19287] pjsip: tsx0x7fa6b0016 ...State changed from Completed to Terminated, event=USER [Apr 2 17:28:59] DEBUG[19287] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0016988 state changed to Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:28:59] DEBUG[19296][C-00000003] channel.c: Dropping duplicate answer! [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The transaction state change event is USER [Apr 2 17:28:59] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa71000 ..Destroying txdata Request msg INVITE/cseq=6368 (tdta0x7fa710001cb0) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0004 Transaction destroyed! [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0016 Timeout timer event [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0016 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:28:59] DEBUG[19214] pjsip: tdta0x7fa71001 ..Destroying txdata Response msg 200/INVITE/cseq=6368 (tdta0x7fa710012360) [Apr 2 17:28:59] DEBUG[19214] pjsip: tsx0x7fa6b0016 Transaction destroyed! [Apr 2 17:28:59] DEBUG[19292][C-00000005] channel.c: Set channel PJSIP/dtmf_inband-00000004 to write format slin [Apr 2 17:28:59] DEBUG[19292][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 2 17:28:59] DEBUG[19292][C-00000005] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Apr 2 17:28:59] DEBUG[19292][C-00000005] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fa6b40063d8' [Apr 2 17:28:59] DEBUG[19294][C-00000004] res_rtp_asterisk.c: 0x7fa70c00cf00 -- Probation learning mode pass with source address 127.0.0.1:17842 [Apr 2 17:28:59] DEBUG[19294][C-00000004] pbx.c: Launching 'Read' [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 4 Uniqueid: 1427984939.10 Extension: receiver Application: Read AppData: var,hello-world,1,,1,15 [Apr 2 17:28:59] DEBUG[19294][C-00000004] res_rtp_asterisk.c: Ooh, format changed from none to alaw [Apr 2 17:28:59] DEBUG[19294][C-00000004] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 2 17:28:59] DEBUG[19292][C-00000005] res_rtp_asterisk.c: 0x7fa6b4007d00 -- Probation learning mode pass with source address 127.0.0.1:18162 [Apr 2 17:28:59] DEBUG[19292][C-00000005] channel.c: Set channel PJSIP/dtmf_inband-00000004 to write format alaw [Apr 2 17:28:59] DEBUG[19292][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 2 17:28:59] DEBUG[19292][C-00000005] pbx.c: Launching 'Wait' [Apr 2 17:28:59] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 4 Uniqueid: 1427984938.7 Extension: senddtmf Application: Wait AppData: 5 [Apr 2 17:29:01] DEBUG[19294][C-00000004] channel.c: Scheduling timer at (381 requested / 381 actual) timer ticks per second [Apr 2 17:29:01] DEBUG[19294][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 2 17:29:01] DEBUG[19294][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 2 17:29:01] DEBUG[19294][C-00000004] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 2 17:29:04] DEBUG[19240] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19240] netsock2.c: Splitting 'stnrd5652' into... [Apr 2 17:29:04] DEBUG[19240] netsock2.c: ...host 'stnrd5652' and port ''. [Apr 2 17:29:04] DEBUG[19294][C-00000004] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Apr 2 17:29:04] DEBUG[19294][C-00000004] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19294][C-00000004] netsock2.c: Splitting 'stnrd5652' into... [Apr 2 17:29:04] DEBUG[19294][C-00000004] netsock2.c: ...host 'stnrd5652' and port ''. [Apr 2 17:29:04] DEBUG[19240] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19240] acl.c: Attached to given IP address [Apr 2 17:29:04] DEBUG[19294][C-00000004] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19294][C-00000004] acl.c: Attached to given IP address [Apr 2 17:29:04] DEBUG[19240] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19240] netsock2.c: Splitting 'stnrd5652' into... [Apr 2 17:29:04] DEBUG[19240] netsock2.c: ...host 'stnrd5652' and port ''. [Apr 2 17:29:04] DEBUG[19240] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19240] acl.c: Attached to given IP address [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '[::1]:0' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '::1' and port '0'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '127.0.0.1:18163' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '127.0.0.1' and port '18163'. [Apr 2 17:29:04] DEBUG[19292][C-00000005] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Apr 2 17:29:04] DEBUG[19292][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19292][C-00000005] netsock2.c: Splitting 'stnrd5652' into... [Apr 2 17:29:04] DEBUG[19292][C-00000005] netsock2.c: ...host 'stnrd5652' and port ''. [Apr 2 17:29:04] DEBUG[19292][C-00000005] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Apr 2 17:29:04] DEBUG[19292][C-00000005] acl.c: Attached to given IP address [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '127.0.0.1:17843' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '127.0.0.1' and port '17843'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '[::1]:0' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '::1' and port '0'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '[::1]:0' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '::1' and port '0'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '127.0.0.1:17843' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '127.0.0.1' and port '17843'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '127.0.0.1:18163' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '127.0.0.1' and port '18163'. [Apr 2 17:29:04] DEBUG[19247] netsock2.c: Splitting '[::1]:0' into... [Apr 2 17:29:04] DEBUG[19247] netsock2.c: ...host '::1' and port '0'. [Apr 2 17:29:04] DEBUG[19292][C-00000005] pbx.c: Launching 'Hangup' [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 5 Uniqueid: 1427984938.7 Extension: senddtmf Application: Hangup AppData: [Apr 2 17:29:04] DEBUG[19292][C-00000005] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/dtmf_inband-00000004' [Apr 2 17:29:04] DEBUG[19292][C-00000005] pbx.c: Spawn extension (default,senddtmf,5) exited non-zero on 'PJSIP/dtmf_inband-00000004' [Apr 2 17:29:04] DEBUG[19292][C-00000005] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/dtmf_inband-00000004' [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 5 Uniqueid: 1427984938.7 Cause: 16 [Apr 2 17:29:04] DEBUG[19292][C-00000005] pbx_lua.c: Looking up h@default:1 [Apr 2 17:29:04] DEBUG[19292][C-00000005] pbx_lua.c: Looking up h@demo:1 [Apr 2 17:29:04] DEBUG[19292][C-00000005] channel.c: Hanging up channel 'PJSIP/dtmf_inband-00000004' [Apr 2 17:29:04] DEBUG[19292][C-00000005] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 2 17:29:04] DEBUG[19286] pjsip: endpoint .Request msg BYE/cseq=1678 (tdta0x7fa710012360) created. [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b0011 .Sending Request msg BYE/cseq=1678 (tdta0x7fa710012360) [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0011 ..Sending Request msg BYE/cseq=1678 (tdta0x7fa710012360) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0016 ...Transaction created for Request msg BYE/cseq=1677 (tdta0x7fa710012360) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0016 ..Sending Request msg BYE/cseq=1677 (tdta0x7fa710012360) in state Null [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0016 ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0011 ....Transaction tsx0x7fa6b0016988 state changed to Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=1677 (rdata0x7fa71000f888) [Apr 2 17:29:04] DEBUG[19199] cdr.c: Finalized CDR for PJSIP/dtmf_inband-00000004 - start 1427984939.473392 answer 1427984939.473262 end 1427984944.928711 dispo ANSWERED [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/dtmf_inband-00000004 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: senddtmf Priority: 5 Uniqueid: 1427984938.7 Cause: 16 Cause-txt: Normal Clearing [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=1677 (rdata0x7fa710005148) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b003d .Received Request msg BYE/cseq=1677 (rdata0x7fa710005148) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0004 ...Transaction created for Request msg BYE/cseq=1677 (rdata0x7fa710005148) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0004 ..Incoming Request msg BYE/cseq=1677 (rdata0x7fa710005148) in state Null [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0004 ...State changed from Null to Trying, event=RX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b003d ....Transaction tsx0x7fa6b0004e28 state changed to Trying [Apr 2 17:29:04] DEBUG[19287] pjsip: endpoint .....Response msg 200/BYE/cseq=1677 (tdta0x7fa6a8006f40) created [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b003d ......Sending Response msg 200/BYE/cseq=1677 (tdta0x7fa6a8006f40) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0004 ......Sending Response msg 200/BYE/cseq=1677 (tdta0x7fa6a8006f40) in state Trying [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - dtmf_inband [Apr 2 17:29:04] DEBUG[19197] devicestate.c: Changing state for PJSIP/dtmf_inband - state 2 (In use) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0004 .......State changed from Trying to Completed, event=TX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b003d ........Transaction tsx0x7fa6b0004e28 state changed to Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Method is BYE, Response is 200 OK [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Received request [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19287] pjsip: tdta0x7fa70c02 .....Destroying txdata Request msg ACK/cseq=28770 (tdta0x7fa70c0280b0) [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b003d ......Session count dec to 4 by mod-invite [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: inv_session 0x7fa6b4019c38 has no ast session [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0004e28 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge_channel.c: Setting 0x7fa6d4014818(PJSIP/receiver-00000005) state from:0 to:1 [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: pulling 0x7fa6d4014818(PJSIP/receiver-00000005) [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014818(PJSIP/receiver-00000005) is leaving native_rtp technology [Apr 2 17:29:04] DEBUG[19293][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa6b40154f8' [Apr 2 17:29:04] DEBUG[19293][C-00000003] chan_pjsip.c: RTP changed on PJSIP/dtmf_inband-00000006; initiating direct media update [Apr 2 17:29:04] DEBUG[19293][C-00000003] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fa6b4014448' [Apr 2 17:29:04] DEBUG[19293][C-00000003] chan_pjsip.c: RTP changed on PJSIP/receiver-00000005; initiating direct media update [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/dtmf_inband-00000006' and 'PJSIP/receiver-00000005' - media will flow through Asterisk core [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: dissolving bridge with cause 16(Normal Clearing) [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge_channel.c: Setting 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) state from:0 to:2 [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: queueing action type:13 sub:1001 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Not sending reinvite to receiver because of disconnected state... [Apr 2 17:29:04] DEBUG[19293][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is dissolved, not performing smart bridge operation. [Apr 2 17:29:04] DEBUG[19286] pjsip: endpoint .Request msg INVITE/cseq=6370 (tdta0x7fa710001cb0) created. [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=1677 (rdata0x7fa71000f888) [Apr 2 17:29:04] DEBUG[19199] cdr.c: Finalized CDR for PJSIP/receiver-00000005 - start 1427984939.122570 answer 1427984939.472194 end 1427984944.929547 dispo ANSWERED [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 [Apr 2 17:29:04] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=1677 (rdata0x7fa71000cd78) [Apr 2 17:29:04] DEBUG[19293][C-00000003] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Apr 2 17:29:04] DEBUG[19293][C-00000003] pbx.c: Spawn extension (default,dtmf_inband,2) exited non-zero on 'PJSIP/receiver-00000005' [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0016 .Incoming Response msg 200/BYE/cseq=1677 (rdata0x7fa71000cd78) in state Calling [Apr 2 17:29:04] DEBUG[19293][C-00000003] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/receiver-00000005' [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0016 ..State changed from Calling to Completed, event=RX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0011 ...Received Response msg 200/BYE/cseq=1677 (rdata0x7fa71000cd78) [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: pulling 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0011 ...Transaction tsx0x7fa6b0016988 state changed to Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge_channel.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: 0x7fa6d4014268(PJSIP/dtmf_inband-00000006) is leaving native_rtp technology [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19293][C-00000003] pbx_lua.c: Looking up h@default:1 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 Cause: 16 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Received response [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Response is 200 OK [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge_channel.c: Channel PJSIP/dtmf_inband-00000006 will survive this bridge; clearing outgoing (dialed) flag [Apr 2 17:29:04] DEBUG[19293][C-00000003] pbx_lua.c: Looking up h@demo:1 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Destroying SIP session with endpoint dtmf_inband [Apr 2 17:29:04] DEBUG[19287] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b40063d8' [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to dtmf_inband [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Destroyed RTP instance '0x7fa6b40063d8' [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0011 .....Session count dec to 2 by Session Module [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf is dissolved, not performing smart bridge operation. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 0 Channel: PJSIP/dtmf_inband-00000006 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1427984939.9 [Apr 2 17:29:04] DEBUG[19287] pjsip: tdta0x7fa6b400 ....Destroying txdata Request msg ACK/cseq=1676 (tdta0x7fa6b4005310) [Apr 2 17:29:04] DEBUG[19287] pjsip: tdta0x7fa6b004 ....Destroying txdata Request msg INVITE/cseq=1676 (tdta0x7fa6b0043010) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0011 .....Session count dec to 1 by mod-invite [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: inv_session 0x7fa6b4003428 has no ast session [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19287] taskprocessor.c: destroying taskprocessor 'f6545ba1-e34e-4a63-9294-12f088b2b215' [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: actually destroying basic bridge, nobody wants it anymore [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 01da7821-9859-4d88-bbde-55efe5bb7aaf BridgeType: basic BridgeTechnology: native_rtp BridgeCreator: BridgeName: BridgeNumChannels: 0 [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling basic bridge destructor [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling native_rtp technology stop [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:29:04] DEBUG[19296][C-00000003] bridge.c: Bridge 01da7821-9859-4d88-bbde-55efe5bb7aaf: calling native_rtp technology destructor [Apr 2 17:29:04] DEBUG[19296][C-00000003] channel.c: Hanging up channel 'PJSIP/dtmf_inband-00000006' [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b000c .Sending Request msg INVITE/cseq=6370 (tdta0x7fa710001cb0) [Apr 2 17:29:04] DEBUG[19296][C-00000003] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ..Sending Request msg INVITE/cseq=6370 (tdta0x7fa710001cb0) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b001e ...Transaction created for Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b001e ..Sending Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) in state Null [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b001e ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Transaction tsx0x7fa6b001e2c8 state changed to Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b001e2c8) [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is INVITE [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=6369 (rdata0x7fa71000f888) [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Delaying sending BYE to dtmf_inband because of outstanding transaction... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/dtmf_inband-00000006 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: dtmf_inband CallerIDName: ConnectedLineNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 ConnectedLineName: Language: en AccountCode: Context: default Exten: Priority: 1 Uniqueid: 1427984939.9 Cause: 16 Cause-txt: Normal Clearing [Apr 2 17:29:04] DEBUG[19199] cdr.c: CDR for PJSIP/dtmf_inband-00000006 is dialed and has no Party B; discarding [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 .Received Request msg INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...Transaction created for Request msg INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Incoming Request msg INVITE/cseq=6369 (rdata0x7fa7100074c8) in state Null [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Null to Trying, event=RX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0014b98 state changed to Trying [Apr 2 17:29:04] DEBUG[19287] pjsip: inv0x7fa6b0033 .....Got SDP offer in Request msg INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Setting payload 8 (0x7fa6a8004108) based on m type on 0x7fa6bf7b5030 [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Copying payload 8 (0x7fa6a8003028) from 0x7fa6bf7b5030 to 0x7fa70c00c3c0 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Media stream 'audio' handled by audio [Apr 2 17:29:04] DEBUG[19287] pjsip: endpoint .....Response msg 200/INVITE/cseq=6369 (tdta0x7fa6b0043010) created [Apr 2 17:29:04] DEBUG[19287] pjsip: inv0x7fa6b0033 .....SDP negotiation done, status=0 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port ''. [Apr 2 17:29:04] DEBUG[19293][C-00000003] channel.c: Hanging up channel 'PJSIP/receiver-00000005' [Apr 2 17:29:04] DEBUG[19293][C-00000003] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 2 17:29:04] DEBUG[19287] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa70c00c1f8' [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Setting payload 8 (0x7fa6a8028a48) based on m type on 0x7fa6bf7b4ae0 [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Copying payload 8 (0x7fa6a8014c28) from 0x7fa6bf7b4ae0 to 0x7fa70c00c3c0 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Apr 2 17:29:04] DEBUG[19287] pjsip: inv0x7fa6b0033 ......Sending Response msg 200/INVITE/cseq=6369 (tdta0x7fa6b0043010) [Apr 2 17:29:04] DEBUG[19288] res_pjsip_session.c: Destroying SIP session with endpoint receiver [Apr 2 17:29:04] DEBUG[19288] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b4014448' [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 .......Sending Response msg 200/INVITE/cseq=6369 (tdta0x7fa6b0043010) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 .......Sending Response msg 200/INVITE/cseq=6369 (tdta0x7fa6b0043010) in state Trying [Apr 2 17:29:04] DEBUG[19288] rtp_engine.c: Destroyed RTP instance '0x7fa6b4014448' [Apr 2 17:29:04] DEBUG[19288] pjsip: dlg0x7fa6b003d .Session count dec to 0 by Session Module [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19287] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19287] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19288] taskprocessor.c: destroying taskprocessor 'b86518b5-8627-4dab-8e2b-f7681620c50f' [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ........State changed from Trying to Completed, event=TX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 .........Transaction tsx0x7fa6b0014b98 state changed to Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Sending response [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fa6b0014b98) [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=6369 (rdata0x7fa710009418) [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Received request [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Method is INVITE [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - receiver [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19197] devicestate.c: Changing state for PJSIP/receiver - state 2 (In use) [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/receiver-00000005 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: dtmf_inband ConnectedLineName: Language: en AccountCode: Context: default Exten: dtmf_inband Priority: 2 Uniqueid: 1427984939.8 Cause: 16 Cause-txt: Normal Clearing [Apr 2 17:29:04] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - dtmf_inband [Apr 2 17:29:04] DEBUG[19197] devicestate.c: Changing state for PJSIP/dtmf_inband - state 1 (Not in use) [Apr 2 17:29:04] DEBUG[19255] app_queue.c: Device 'PJSIP/dtmf_inband' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/dtmf_inband State: NOT_INUSE [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b001e .Incoming Response msg 200/INVITE/cseq=6369 (rdata0x7fa7100074c8) in state Calling [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b001e ..State changed from Calling to Terminated, event=RX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Received Response msg 200/INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ...Transaction tsx0x7fa6b001e2c8 state changed to Terminated [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b000c ....Got SDP answer in Response msg 200/INVITE/cseq=6369 (rdata0x7fa7100074c8) [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b000c ....SDP negotiation done, status=0 [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b000c ....Received Response msg 200/INVITE/cseq=6369 (rdata0x7fa7100074c8), sending ACK [Apr 2 17:29:04] DEBUG[19286] pjsip: tdta0x7fa71000 ....Destroying txdata Request msg ACK/cseq=6368 (tdta0x7fa71000bd40) [Apr 2 17:29:04] DEBUG[19286] pjsip: endpoint ....Request msg ACK/cseq=6369 (tdta0x7fa71000bd40) created. [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c .....Sending Request msg ACK/cseq=6369 (tdta0x7fa71000bd40) [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_resolve.c .....Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b001e2c8 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Received response [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Response is 200 OK [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Queuing delayed request to run for dtmf_inband [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending delayed BYE request to dtmf_inband [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=6369 (rdata0x7fa710009418) [Apr 2 17:29:04] DEBUG[19286] pjsip: endpoint .Request msg BYE/cseq=6371 (tdta0x7fa70c0280b0) created. [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: inv0x7fa6b000c .Sending Request msg BYE/cseq=6371 (tdta0x7fa70c0280b0) [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ..Sending Request msg BYE/cseq=6371 (tdta0x7fa70c0280b0) [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b003b ...Transaction created for Request msg BYE/cseq=6370 (tdta0x7fa70c0280b0) [Apr 2 17:29:04] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=6369 (rdata0x7fa71000f888) [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b001e Timeout timer event [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 .Received Request msg ACK/cseq=6369 (rdata0x7fa71000f888) [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b001e .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ..Request to terminate transaction [Apr 2 17:29:04] DEBUG[19214] pjsip: tdta0x7fa71000 ..Destroying txdata Request msg INVITE/cseq=6369 (tdta0x7fa710001cb0) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b0014 ...State changed from Completed to Terminated, event=USER [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b003b ..Sending Request msg BYE/cseq=6370 (tdta0x7fa70c0280b0) in state Null [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b001e Transaction destroyed! [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0014b98 state changed to Terminated [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is USER [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_resolve.c ...Target '127.0.0.1:5060' type=Unspecified resolved to '127.0.0.1:5060' type=UDP (UDP transport) [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b003b ...State changed from Null to Calling, event=TX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b000c ....Transaction tsx0x7fa6b003bad8 state changed to Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Calling [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending request [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Request msg BYE/cseq=6370 (rdata0x7fa710009008) [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b0014 Timeout timer event [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b0014 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:29:04] DEBUG[19214] pjsip: tdta0x7fa6b004 ..Destroying txdata Response msg 200/INVITE/cseq=6369 (tdta0x7fa6b0043010) [Apr 2 17:29:04] DEBUG[19214] pjsip: tsx0x7fa6b0014 Transaction destroyed! [Apr 2 17:29:04] DEBUG[19286] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg BYE/cseq=6370 (rdata0x7fa710013398) [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 .Received Request msg BYE/cseq=6370 (rdata0x7fa710013398) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0014 ...Transaction created for Request msg BYE/cseq=6370 (rdata0x7fa710013398) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0014 ..Incoming Request msg BYE/cseq=6370 (rdata0x7fa710013398) in state Null [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0014 ...State changed from Null to Trying, event=RX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 ....Transaction tsx0x7fa6b0014b98 state changed to Trying [Apr 2 17:29:04] DEBUG[19286] pjsip: endpoint .....Response msg 200/BYE/cseq=6370 (tdta0x7fa6b0043010) created [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 ......Sending Response msg 200/BYE/cseq=6370 (tdta0x7fa6b0043010) [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0014 ......Sending Response msg 200/BYE/cseq=6370 (tdta0x7fa6b0043010) in state Trying [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] pjsip: tsx0x7fa6b0014 .......State changed from Trying to Completed, event=TX_MSG [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 ........Transaction tsx0x7fa6b0014b98 state changed to Completed [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is TX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is CONFIRMED [Apr 2 17:29:04] DEBUG[19214] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=6370 (rdata0x7fa710009008) [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Sending response [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE, Response is 200 OK [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The state change pertains to the session with receiver [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Received request [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Method is BYE [Apr 2 17:29:04] DEBUG[19214] netsock2.c: Splitting '127.0.0.1:5060' into... [Apr 2 17:29:04] DEBUG[19214] netsock2.c: ...host '127.0.0.1' and port '5060'. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 4 Uniqueid: 1427984939.10 Cause: 16 [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 ......Session count dec to 4 by mod-invite [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: inv_session 0x7fa70c005fc8 has no ast session [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0014b98 [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19287] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=6370 (rdata0x7fa710017638) [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b003b .Incoming Response msg 200/BYE/cseq=6370 (rdata0x7fa710017638) in state Calling [Apr 2 17:29:04] DEBUG[19287] pjsip: tsx0x7fa6b003b ..State changed from Calling to Completed, event=RX_MSG [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b000c ...Received Response msg 200/BYE/cseq=6370 (rdata0x7fa710017638) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b000c ...Transaction tsx0x7fa6b003bad8 state changed to Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The state change pertains to the session with dtmf_inband [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: There is no transaction involved in this state change [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Source of transaction state change is RX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Received response [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Response is 200 OK [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Destroying SIP session with endpoint dtmf_inband [Apr 2 17:29:04] DEBUG[19287] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa6b40154f8' [Apr 2 17:29:04] DEBUG[19294][C-00000004] pbx.c: Extension receiver, priority 4 returned normally even though call was hung up [Apr 2 17:29:04] DEBUG[19294][C-00000004] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/receiver-00000007' [Apr 2 17:29:04] DEBUG[19287] rtp_engine.c: Destroyed RTP instance '0x7fa6b40154f8' [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b000c .....Session count dec to 2 by Session Module [Apr 2 17:29:04] DEBUG[19287] pjsip: tdta0x7fa71000 ....Destroying txdata Request msg ACK/cseq=6369 (tdta0x7fa71000bd40) [Apr 2 17:29:04] DEBUG[19287] pjsip: tdta0x7fa6b401 ....Destroying txdata Request msg INVITE/cseq=6367 (tdta0x7fa6b4017630) [Apr 2 17:29:04] DEBUG[19287] pjsip: dlg0x7fa6b000c .....Session count dec to 1 by mod-invite [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: inv_session 0x7fa6b402ac58 has no ast session [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current transaction state is Completed [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The transaction state change event is RX_MSG [Apr 2 17:29:04] DEBUG[19287] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:04] DEBUG[19287] taskprocessor.c: destroying taskprocessor 'bf7e5afc-c1c0-4ab7-989c-ffc96bd3166d' [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 4 Uniqueid: 1427984939.10 Cause: 16 [Apr 2 17:29:04] DEBUG[19294][C-00000004] pbx_lua.c: Looking up h@default:1 [Apr 2 17:29:04] DEBUG[19294][C-00000004] pbx_lua.c: Looking up h@demo:1 [Apr 2 17:29:04] DEBUG[19294][C-00000004] channel.c: Hanging up channel 'PJSIP/receiver-00000007' [Apr 2 17:29:04] DEBUG[19294][C-00000004] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Apr 2 17:29:04] DEBUG[19286] res_pjsip_session.c: Destroying SIP session with endpoint receiver [Apr 2 17:29:04] DEBUG[19286] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fa70c00c1f8' [Apr 2 17:29:04] DEBUG[19286] rtp_engine.c: Destroyed RTP instance '0x7fa70c00c1f8' [Apr 2 17:29:04] DEBUG[19286] pjsip: dlg0x7fa6b0033 .Session count dec to 0 by Session Module [Apr 2 17:29:04] DEBUG[19199] cdr.c: Finalized CDR for PJSIP/receiver-00000007 - start 1427984939.470757 answer 1427984939.471066 end 1427984944.934231 dispo ANSWERED [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/receiver-00000007 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: b3f6fd9b-c34b-444a-bc05-8403a0a6bb37 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: receiver Priority: 4 Uniqueid: 1427984939.10 Cause: 16 Cause-txt: Normal Clearing [Apr 2 17:29:04] DEBUG[19197] devicestate.c: No provider found, checking channel drivers for PJSIP - receiver [Apr 2 17:29:04] DEBUG[19286] taskprocessor.c: destroying taskprocessor '7e3657f8-06f6-4138-98ae-9e804a6b102b' [Apr 2 17:29:04] DEBUG[19197] devicestate.c: Changing state for PJSIP/receiver - state 0 (Unknown) [Apr 2 17:29:04] DEBUG[19255] app_queue.c: Device 'PJSIP/receiver' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 2 17:29:04] DEBUG[19262] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/receiver State: UNKNOWN [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b0016 Timeout timer event [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b0016 .State changed from Completed to Terminated, event=TIMER [Apr 2 17:29:09] DEBUG[19214] pjsip: dlg0x7fa6b0011 ..Transaction tsx0x7fa6b0016988 state changed to Terminated [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: inv_session 0x7fa6b4003428 has no ast session [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b0016988 [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The transaction state change event is TIMER [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:09] DEBUG[19214] pjsip: dlg0x7fa6b0011 ...Dialog destroyed [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b0016 Timeout timer event [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b0016 .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:29:09] DEBUG[19214] pjsip: tdta0x7fa71001 ..Destroying txdata Request msg BYE/cseq=1677 (tdta0x7fa710012360) [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b0016 Transaction destroyed! [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b003b Timeout timer event [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b003b .State changed from Completed to Terminated, event=TIMER [Apr 2 17:29:09] DEBUG[19214] pjsip: dlg0x7fa6b000c ..Transaction tsx0x7fa6b003bad8 state changed to Terminated [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: inv_session 0x7fa6b402ac58 has no ast session [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The transaction involved in this state change is 0x7fa6b003bad8 [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The current transaction state is Terminated [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The transaction state change event is TIMER [Apr 2 17:29:09] DEBUG[19214] res_pjsip_session.c: The current inv state is DISCONNCTD [Apr 2 17:29:09] DEBUG[19214] pjsip: dlg0x7fa6b000c ...Dialog destroyed [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b003b Timeout timer event [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b003b .State changed from Terminated to Destroyed, event=TIMER [Apr 2 17:29:09] DEBUG[19214] pjsip: tdta0x7fa70c02 ..Destroying txdata Request msg BYE/cseq=6370 (tdta0x7fa70c0280b0) [Apr 2 17:29:09] DEBUG[19214] pjsip: tsx0x7fa6b003b Transaction destroyed! [Apr 2 17:29:19] DEBUG[19295] threadpool.c: Worker thread idle timeout reached. Dying. [Apr 2 17:29:19] DEBUG[19185] threadpool.c: Destroying worker thread 19