[Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tsx0x7fff94004 Timeout timer event [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tsx0x7fff94004 .State changed from Completed to Terminated, event=TIMER [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : dlg0x7fff94003 ..Transaction tsx0x7fff94004668 state changed to Terminated [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : evsub0x7fff940 ...Subscription destroyed [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : dlg0x7fff94003 ....Session count dec to 1 by mod-evsub [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : dlg0x7fff94003 ...Dialog destroyed [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tsx0x7fff94004 Timeout timer event [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tsx0x7fff94004 .State changed from Terminated to Destroyed, event=TIMER [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tdta0x7fff9400 ..Destroying txdata Response msg 500/SUBSCRIBE/cseq=9164 (tdta0x7fff94000c30) [Oct 18 14:10:49] DEBUG[7391]: pjsip:0 : tsx0x7fff94004 ..Transaction destroyed! [Oct 18 14:10:50] DEBUG[7391]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=20739 (rdata0x7fffd0003998) <--- Received SIP request (1060 bytes) from UDP:10.24.19.143:5060 ---> INVITE sip:5555@10.24.20.81 SIP/2.0 Via: SIP/2.0/UDP 10.24.19.143:5060;rport;branch=z9hG4bKPjxPx0p9Xi9U5Ug5bBrFcI1EoKesOH5ncg Max-Forwards: 70 From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: Contact: "1111" Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf CSeq: 20739 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Digium D40 1_3_2_0_54993 Content-Type: application/sdp Content-Length: 431 v=0 o=- 77494740 77494740 IN IP4 10.24.19.143 s=digphn c=IN IP4 10.24.19.143 t=0 0 a=X-nat:0 m=audio 4012 RTP/AVP 0 8 9 111 18 58 118 58 96 a=rtcp:4013 IN IP4 10.24.19.143 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=20739 (rdata0x7fffd00068c8) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_ip.c:125 ip_identify: No identify sections to match against [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_user.c:104 username_identify: Retrieved endpoint 1111 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : endpoint .Response msg 401/INVITE/cseq=20739 (tdta0x7fffd0000940) created [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port ''. [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.19.143' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.19.143' and port ''. <--- Transmitting SIP response (519 bytes) to UDP:10.24.19.143:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.24.19.143:5060;rport;received=10.24.19.143;branch=z9hG4bKPjxPx0p9Xi9U5Ug5bBrFcI1EoKesOH5ncg Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: ;tag=z9hG4bKPjxPx0p9Xi9U5Ug5bBrFcI1EoKesOH5ncg CSeq: 20739 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1382123450/e5a0299f808f5c8d4156ea18d390015c",opaque="79a94d1232f05947",algorithm=md5,qop="auth" Content-Length: 0 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tdta0x7fffd000 .Destroying txdata Response msg 401/INVITE/cseq=20739 (tdta0x7fffd0000940) [Oct 18 14:10:50] DEBUG[7391]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=20739 (rdata0x7fffd0003278) <--- Received SIP request (373 bytes) from UDP:10.24.19.143:5060 ---> ACK sip:5555@10.24.20.81 SIP/2.0 Via: SIP/2.0/UDP 10.24.19.143:5060;rport;branch=z9hG4bKPjxPx0p9Xi9U5Ug5bBrFcI1EoKesOH5ncg Max-Forwards: 70 From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: ;tag=z9hG4bKPjxPx0p9Xi9U5Ug5bBrFcI1EoKesOH5ncg Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf CSeq: 20739 ACK Content-Length: 0 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=20739 (rdata0x7fffd00059a8) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_ip.c:125 ip_identify: No identify sections to match against [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_user.c:104 username_identify: Retrieved endpoint 1111 [Oct 18 14:10:50] DEBUG[7391]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=20740 (rdata0x7fffd0003278) <--- Received SIP request (1351 bytes) from UDP:10.24.19.143:5060 ---> INVITE sip:5555@10.24.20.81 SIP/2.0 Via: SIP/2.0/UDP 10.24.19.143:5060;rport;branch=z9hG4bKPj.RO1B0sNPitcchAzKG.6odPnDPE4dXk4 Max-Forwards: 70 From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: Contact: "1111" Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf CSeq: 20740 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: Digium D40 1_3_2_0_54993 Authorization: Digest username="1111", realm="asterisk", nonce="1382123450/e5a0299f808f5c8d4156ea18d390015c", uri="sip:5555@10.24.20.81", response="9aefa7dbe2a3bd192f3151154d1de0b6", algorithm=md5, cnonce="9anhZSjpXm16JnHh0WwrOKLQ.IvA1biW", opaque="79a94d1232f05947", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 431 v=0 o=- 77494740 77494740 IN IP4 10.24.19.143 s=digphn c=IN IP4 10.24.19.143 t=0 0 a=X-nat:0 m=audio 4012 RTP/AVP 0 8 9 111 18 58 118 58 96 a=rtcp:4013 IN IP4 10.24.19.143 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=20740 (rdata0x7fffd0006788) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_ip.c:125 ip_identify: No identify sections to match against [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_endpoint_identifier_user.c:104 username_identify: Retrieved endpoint 1111 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : endpoint .Response msg 401/INVITE/cseq=20740 (tdta0x7fffd0000940) created [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_authenticator_digest.c:248 check_nonce: Calculated nonce 1382123450/e5a0299f808f5c8d4156ea18d390015c. Actual nonce is 1382123450/e5a0299f808f5c8d4156ea18d390015c [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port ''. [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.19.143' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.19.143' and port ''. [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tdta0x7fffd000 .Destroying txdata Response msg 401/INVITE/cseq=20740 (tdta0x7fffd0000940) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ..Transaction created for Request msg INVITE/cseq=20740 (rdata0x7fffd0006788) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 .Incoming Request msg INVITE/cseq=20740 (rdata0x7fffd0006788) in state Null [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ..State changed from Null to Trying, event=RX_MSG [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ...Transaction tsx0x7fff94003c48 state changed to Trying [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 .UAS dialog created [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 .Module mod-invite added as dialog usage, data=0x7fff94007c88 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ..Session count inc to 2 by mod-invite [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : inv0x7fff94004 .UAS invite session created for dialog dlg0x7fff94004668 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 .Module Session Module added as dialog usage, data=(nil) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ..Session count inc to 2 by Session Module [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.19.143' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.19.143' and port ''. [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fff9400fef8' [Oct 18 14:10:50] DEBUG[7487]: res_rtp_asterisk.c:1777 ast_rtp_new: Allocated port 17582 for RTP instance '0x7fff9400fef8' [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 ICE session created, comp_cnt=2, role is Unknown agent [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port ''. [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 Candidate 0 added: comp_id=1, type=host, foundation=Ha181451, addr=10.24.20.81:17582, base=10.24.20.81:17582, prio=0x7effffff (2130706431) [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.67.59' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.67.59' and port ''. [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 Candidate 1 added: comp_id=1, type=host, foundation=Ha18433b, addr=10.24.67.59:17582, base=10.24.67.59:17582, prio=0x7effffff (2130706431) [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x7fff9400fef8' is setup and ready to go [Oct 18 14:10:50] DEBUG[7487]: res_rtp_asterisk.c:3967 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fff9400fef8' [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port ''. [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 Candidate 2 added: comp_id=2, type=host, foundation=Ha181451, addr=10.24.20.81:17583, base=10.24.20.81:17583, prio=0x7efffffe (2130706430) [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.67.59' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.67.59' and port ''. [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 Candidate 3 added: comp_id=2, type=host, foundation=Ha18433b, addr=10.24.67.59:17583, base=10.24.67.59:17583, prio=0x7efffffe (2130706430) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : icess0x7fff940 Destroying ICE session 0x7fff940182b8 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : stuse0x7fff940 STUN session 0x7fff9401a6d8 destroy request, ref_cnt=4 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : stuse0x7fff940 STUN session 0x7fff9401b6d8 destroy request, ref_cnt=3 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : ice_session.c ICE session 0x7fff940182b8 destroyed [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : stun_session.c STUN session 0x7fff9401a6d8 destroyed [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : stun_session.c STUN session 0x7fff9401b6d8 destroyed [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 111 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 58 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 118 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 58 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 96 based on m type on 0x7fffa083b460 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 58 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 96 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 111 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 118 from 0x7fffa083b460 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : endpoint .Response msg 100/INVITE/cseq=20740 (tdta0x7fff94000c30) created [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 .Initial answer Response msg 100/INVITE/cseq=20740 (tdta0x7fff94000c30) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1768 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : inv0x7fff94004 .Sending Response msg 100/INVITE/cseq=20740 (tdta0x7fff94000c30) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ..Sending Response msg 100/INVITE/cseq=20740 (tdta0x7fff94000c30) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ..Sending Response msg 100/INVITE/cseq=20740 (tdta0x7fff94000c30) in state Trying <--- Transmitting SIP response (320 bytes) to UDP:10.24.19.143:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.24.19.143:5060;rport;received=10.24.19.143;branch=z9hG4bKPj.RO1B0sNPitcchAzKG.6odPnDPE4dXk4 Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: CSeq: 20740 INVITE Content-Length: 0 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ...State changed from Trying to Proceeding, event=TX_MSG [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ....Transaction tsx0x7fff94003c48 state changed to Proceeding [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1697 __print_debug_details: There is no transaction involved in this state change [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is INCOMING[New Thread 0x7fff4b13c700 (LWP 7499)] [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1829 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1780 handle_outgoing: Sending response [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1768 handle_outgoing_response: Method is INVITE, Response is 100 Trying [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1693 __print_debug_details: The transaction involved in this state change is 0x7fff94003c48 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1694 __print_debug_details: The current transaction state is Proceeding [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1695 __print_debug_details: The transaction state change event is TX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is INCOMING [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1709 handle_incoming_request: Method is INVITE [Oct 18 14:10:50] DEBUG[7448]: res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 3 instead [Oct 18 14:10:50] DEBUG[7487]: chan_pjsip.c:2008 pbx_start_incoming_request: Started PBX on new PJSIP channel PJSIP/1111-00000000 [Oct 18 14:10:50] DEBUG[7499]: logger.c:1316 ast_create_callid: CALL_ID [C-00000000] created by thread. [Oct 18 14:10:50] DEBUG[7499][C-00000000]: logger.c:1378 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread. [Oct 18 14:10:50] DEBUG[7499][C-00000000]: pbx.c:4688 pbx_extension_helper: Launching 'Answer' -- Executing [5555@custext:1] Answer("PJSIP/1111-00000000", "") in new stack [Oct 18 14:10:50] DEBUG[7380]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for PJSIP - 1111 [Oct 18 14:10:50] DEBUG[7380]: devicestate.c:425 do_state_change: Changing state for PJSIP/1111 - state 2 (In use) [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'In use' for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'In use' for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:662 devstate_change_collector_cb: Aggregate state for device 'PJSIP/1111' has changed to 'In use' [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : inv0x7fff94004 .SDP negotiation done, status=0 [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.19.143' into... [Oct 18 14:10:50] DEBUG[7487]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.19.143' and port ''. [Oct 18 14:10:50] DEBUG[7487]: res_rtp_asterisk.c:4014 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fff9400fef8' [Oct 18 14:10:50] DEBUG[7463]: app_queue.c:2312 device_state_cb: Device 'PJSIP/1111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7fffa083aed0 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 96 based on m type on 0x7fffa083aed0 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7fffa083aed0 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 96 from 0x7fffa083aed0 to 0x7fff94010038 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1768 handle_outgoing_response: Method is INVITE, Response is 200 OK [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : inv0x7fff94004 .Sending Response msg 200/INVITE/cseq=20740 (tdta0x7fff94000c30) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ..Sending Response msg 200/INVITE/cseq=20740 (tdta0x7fff94000c30) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ..Sending Response msg 200/INVITE/cseq=20740 (tdta0x7fff94000c30) in state Proceeding <--- Transmitting SIP response (829 bytes) to UDP:10.24.19.143:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.24.19.143:5060;rport;received=10.24.19.143;branch=z9hG4bKPj.RO1B0sNPitcchAzKG.6odPnDPE4dXk4 Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: ;tag=b488a916-3ccd-4724-bedc-8d257bcc201e CSeq: 20740 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, REGISTER, MESSAGE Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 246 v=0 o=- 77494740 77494742 IN IP4 veighln s=Asterisk c=IN IP4 10.24.20.81 t=0 0 m=audio 17582 RTP/AVP 0 96 c=IN IP4 10.24.20.81 a=rtpmap:0 PCMU/8000 a=ptime:20 a=maxptime:150 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ...State changed from Proceeding to Completed, event=TX_MSG [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ....Transaction tsx0x7fff94003c48 state changed to Completed [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1697 __print_debug_details: There is no transaction involved in this state change [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is CONNECTING [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1829 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1780 handle_outgoing: Sending response [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1768 handle_outgoing_response: Method is INVITE, Response is 200 OK [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1693 __print_debug_details: The transaction involved in this state change is 0x7fff94003c48 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1694 __print_debug_details: The current transaction state is Completed [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1695 __print_debug_details: The transaction state change event is TX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is CONNECTING [Oct 18 14:10:50] DEBUG[7499][C-00000000]: res_rtp_asterisk.c:3610 ast_rtp_read: 0x7fff94015740 -- Probation learning mode pass with source address 10.24.19.143:4012 > 0x7fff94015740 -- Probation passed - setting RTP source address to 10.24.19.143:4012 [Oct 18 14:10:50] DEBUG[7499][C-00000000]: pbx.c:4688 pbx_extension_helper: Launching 'Stasis' -- Executing [5555@custext:2] Stasis("PJSIP/1111-00000000", "test") in new stack [Oct 18 14:10:50] ERROR[7499][C-00000000]: res_stasis.c:604 stasis_app_exec: Stasis app 'test' not registered [Oct 18 14:10:50] DEBUG[7499][C-00000000]: pbx.c:6181 __ast_pbx_run: Spawn extension (custext,5555,2) exited non-zero on 'PJSIP/1111-00000000' == Spawn extension (custext, 5555, 2) exited non-zero on 'PJSIP/1111-00000000' [Oct 18 14:10:50] DEBUG[7499][C-00000000]: channel.c:2577 ast_softhangup_nolock: Soft-Hanging up channel 'PJSIP/1111-00000000' [Oct 18 14:10:50] DEBUG[7499][C-00000000]: channel.c:2748 ast_hangup: Hanging up channel 'PJSIP/1111-00000000' [Oct 18 14:10:50] DEBUG[7499][C-00000000]: chan_pjsip.c:1593 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : endpoint .Request msg BYE/cseq=15766 (tdta0x7fffd0000940) created. [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1753 handle_outgoing_request: Method is BYE [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : inv0x7fff94004 .Sending Request msg BYE/cseq=15766 (tdta0x7fffd0000940) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ..Sending Request msg BYE/cseq=15766 (tdta0x7fffd0000940) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff9400e ...Transaction created for Request msg BYE/cseq=15765 (tdta0x7fffd0000940) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff9400e ..Sending Request msg BYE/cseq=15765 (tdta0x7fffd0000940) in state Null [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : sip_resolve.c ...Target '10.24.19.143:5060' type=Unspecified resolved to '10.24.19.143:5060' type=UDP (UDP transport) <--- Transmitting SIP request (385 bytes) to UDP:10.24.19.143:5060 ---> BYE sip:1111@10.24.19.143:5060;ob SIP/2.0 Via: SIP/2.0/UDP 10.24.67.59:5060;rport;branch=z9hG4bKPj4c82aae8-3df0-4f3d-9b7d-b877d3ba643f From: ;tag=b488a916-3ccd-4724-bedc-8d257bcc201e To: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf CSeq: 15765 BYE Reason: Q.850;cause=0 Content-Length: 0 [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff9400e ...State changed from Null to Calling, event=TX_MSG [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ....Transaction tsx0x7fff9400ef78 state changed to Calling [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1693 __print_debug_details: The transaction involved in this state change is 0x7fff9400ef78 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1694 __print_debug_details: The current transaction state is Calling [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1695 __print_debug_details: The transaction state change event is TX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is CONNECTING [Oct 18 14:10:50] DEBUG[7380]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for PJSIP - 1111 [Oct 18 14:10:50] DEBUG[7379]: cdr.c:1267 cdr_object_finalize: Finalized CDR for PJSIP/1111-00000000 - start 1382123450.472154 answer 1382123450.522178 end 1382123450.720280 dispo ANSWERED [Oct 18 14:10:50] DEBUG[7380]: devicestate.c:425 do_state_change: Changing state for PJSIP/1111 - state 1 (Not in use) [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '2013-10-18 14:10:50' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '"1111" <1111>' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'custext' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'PJSIP/1111-00000000' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'Stasis' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'test' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '0' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '0' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '1382123450.0' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 18 14:10:50] DEBUG[7379]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 18 14:10:50] DEBUG[7379]: cdr_sqlite3_custom.c:262 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2013-10-18 14:10:50','"1111" <1111>','custext','PJSIP/1111-00000000','','Stasis','test','0','0','ANSWERED','DOCUMENTATION','','1382123450.0','','') [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'Not in use' for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'Not in use' for 'PJSIP/1111' [Oct 18 14:10:50] DEBUG[7374]: devicestate.c:662 devstate_change_collector_cb: Aggregate state for device 'PJSIP/1111' has changed to 'Not in use' [Oct 18 14:10:50] DEBUG[7463]: app_queue.c:2312 device_state_cb: Device 'PJSIP/1111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 18 14:10:50] DEBUG[7379]: cdr_radius.c:214 radius_log: Unable to create RADIUS record. CDR not recorded! [Thread 0x7fff4b13c700 (LWP 7499) exited] [New Thread 0x7fff4aeaa700 (LWP 7500)] [Oct 18 14:10:50] DEBUG[7391]: pjsip:0 : sip_endpoint.c Processing incoming message: Request msg ACK/cseq=20740 (rdata0x7fffd0002e88) <--- Received SIP request (368 bytes) from UDP:10.24.19.143:5060 ---> ACK sip:10.24.20.81:5060 SIP/2.0 Via: SIP/2.0/UDP 10.24.19.143:5060;rport;branch=z9hG4bKPj-J3rAm9E3ijz11srEyafFLfDXQorz34S Max-Forwards: 70 From: "1111" ;tag=mWiu1fMAhB6gBnyipBggCqMyeGDLZwxg To: ;tag=b488a916-3ccd-4724-bedc-8d257bcc201e Call-ID: TLKZLtxBrvtpyPqcYHy93nq.8G11e6Wf CSeq: 20740 ACK Content-Length: 0 FRACK!, Failed assertion 0 (0) at line 191 in __ao2_lock of astobj2.c [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=20740 (rdata0x7fffd00067b8) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 .Received Request msg ACK/cseq=20740 (rdata0x7fffd00067b8) [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ..Request to terminate transaction [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : tsx0x7fff94003 ...State changed from Completed to Terminated, event=USER [Oct 18 14:10:50] DEBUG[7487]: pjsip:0 : dlg0x7fff94004 ....Transaction tsx0x7fff94003c48 state changed to Terminated [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1688 __print_debug_details: The inv session still has an invite_tsx (0x7fff94003c48) [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1693 __print_debug_details: The transaction involved in this state change is 0x7fff94003c48 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1694 __print_debug_details: The current transaction state is Terminated [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1695 __print_debug_details: The transaction state change event is USER [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is CONNECTING [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1674 __print_debug_details: Function session_inv_on_state_changed called on event RX_MSG [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1685 __print_debug_details: The state change pertains to the session with 1111 [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1690 __print_debug_details: The inv session does NOT have an invite_tsx [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1697 __print_debug_details: There is no transaction involved in this state change [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1699 __print_debug_details: The current inv state is CONFIRMED [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1737 handle_incoming: Received request [Oct 18 14:10:50] DEBUG[7487]: res_pjsip_session.c:1709 handle_incoming_request: Method is ACK [Oct 18 14:10:50] ERROR[7487]: astobj2.c:156 INTERNAL_OBJ: user_data is NULL [Oct 18 14:10:50] ERROR[7487]: astobj2.c:191 __ao2_lock: FRACK!, Failed assertion 0 (0) Program received signal SIGSEGV, Segmentation fault.