[Dec 22 16:54:03] Asterisk SVN-branch-13-r429983 built by root @ newtonr-laptop on a x86_64 running Linux on 2014-12-22 20:00:06 UTC [Dec 22 16:54:03] DEBUG[6113] config.c: Parsing /etc/asterisk/logger.conf [Dec 22 16:54:20] DEBUG[6060] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=20656 (rdata0x1dc3e58) [Dec 22 16:54:20] VERBOSE[6060] res_pjsip_logger.c: <--- Received SIP request (1060 bytes) from UDP:10.24.18.16:5060 ---> INVITE sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjwAsTDb5b.sBrcJWDbMg-bu8yg-HCbP3u Max-Forwards: 70 From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: Contact: "Alice" Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD CSeq: 20656 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_4_2_0_63880 Content-Type: application/sdp Content-Length: 430 v=0 o=- 114660150 114660150 IN IP4 10.24.18.16 s=digphn c=IN IP4 10.24.18.16 t=0 0 a=X-nat:0 m=audio 4036 RTP/AVP 111 18 0 58 118 9 8 58 96 a=rtcp:4037 IN IP4 10.24.18.16 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=20656 (rdata0x7f13bc0045d8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:54:20] DEBUG[6055] pjsip: endpoint .Response msg 401/INVITE/cseq=20656 (tdta0x7f135c006c60) created [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Transmitting SIP response (524 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjwAsTDb5b.sBrcJWDbMg-bu8yg-HCbP3u Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: ;tag=z9hG4bKPjwAsTDb5b.sBrcJWDbMg-bu8yg-HCbP3u CSeq: 20656 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1419288860/6522a9b2946100633197ebe440619676",opaque="00b216db72e5e88a",algorithm=md5,qop="auth" Content-Length: 0 [Dec 22 16:54:20] DEBUG[6055] pjsip: tdta0x7f135c00 .Destroying txdata Response msg 401/INVITE/cseq=20656 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6060] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=20656 (rdata0x7f13bc002678) [Dec 22 16:54:20] VERBOSE[6060] res_pjsip_logger.c: <--- Received SIP request (374 bytes) from UDP:10.24.18.16:5060 ---> ACK sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjwAsTDb5b.sBrcJWDbMg-bu8yg-HCbP3u Max-Forwards: 70 From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: ;tag=z9hG4bKPjwAsTDb5b.sBrcJWDbMg-bu8yg-HCbP3u Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD CSeq: 20656 ACK Content-Length: 0 [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=20656 (rdata0x7f13bc005eb8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:54:20] DEBUG[6060] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=20657 (rdata0x7f13bc002678) [Dec 22 16:54:20] VERBOSE[6060] res_pjsip_logger.c: <--- Received SIP request (1351 bytes) from UDP:10.24.18.16:5060 ---> INVITE sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjU1-g9ERRs5xGATn2TJzUxTO-Y12NgiRD Max-Forwards: 70 From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: Contact: "Alice" Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD CSeq: 20657 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_4_2_0_63880 Authorization: Digest username="6001", realm="asterisk", nonce="1419288860/6522a9b2946100633197ebe440619676", uri="sip:101@10.24.18.124", response="0baf1a118b1898ca250646ecd7fcc8cb", algorithm=md5, cnonce="5XDgdMccAQz8QmyiOk0WjAHB4OQnnwVj", opaque="00b216db72e5e88a", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 430 v=0 o=- 114660150 114660150 IN IP4 10.24.18.16 s=digphn c=IN IP4 10.24.18.16 t=0 0 a=X-nat:0 m=audio 4036 RTP/AVP 111 18 0 58 118 9 8 58 96 a=rtcp:4037 IN IP4 10.24.18.16 a=rtpmap:111 G726-32/8000 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:58 L16/16000 a=rtpmap:118 L16/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:58 L16-256/16000 a=sendrecv a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=20657 (rdata0x7f13bc006a88) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:54:20] DEBUG[6055] pjsip: endpoint .Response msg 401/INVITE/cseq=20657 (tdta0x7f135c006c60) created [Dec 22 16:54:20] DEBUG[6055] res_pjsip_authenticator_digest.c: Calculated nonce 1419288860/6522a9b2946100633197ebe440619676. Actual nonce is 1419288860/6522a9b2946100633197ebe440619676 [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: tdta0x7f135c00 .Destroying txdata Response msg 401/INVITE/cseq=20657 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ..Transaction created for Request msg INVITE/cseq=20657 (rdata0x7f13bc006a88) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c .Incoming Request msg INVITE/cseq=20657 (rdata0x7f13bc006a88) in state Null [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ..State changed from Null to Trying, event=RX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ...Transaction tsx0x7f135c00cfa8 state changed to Trying [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b .UAS dialog created [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b .Module mod-invite added as dialog usage, data=0x7f135c00c7d8 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ..Session count inc to 2 by mod-invite [Dec 22 16:54:20] DEBUG[6055] pjsip: inv0x7f135c00b .UAS invite session created for dialog dlg0x7f135c00bc28 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b .Module Session Module added as dialog usage, data=(nil) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ..Session count inc to 2 by Session Module [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f135c012bb8' [Dec 22 16:54:20] DEBUG[6055] res_rtp_asterisk.c: Allocated port 13944 for RTP instance '0x7f135c012bb8' [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 ICE session created, comp_cnt=2, role is Unknown agent [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:13944, base=10.24.18.124:13944, prio=0x7effffff (2130706431) [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:13944, base=10.24.18.124:13944, prio=0x64ffffff (1694498815) [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: RTP instance '0x7f135c012bb8' is setup and ready to go [Dec 22 16:54:20] DEBUG[6055] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f135c012bb8' [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:13945, base=10.24.18.124:13945, prio=0x7efffffe (2130706430) [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:13945, base=10.24.18.124:13945, prio=0x64fffffe (1694498814) [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Destroying ICE session 0x7f135c016348 [Dec 22 16:54:20] DEBUG[6055] pjsip: stuse0x7f135c0 STUN session 0x7f135c018768 destroy request, ref_cnt=4 [Dec 22 16:54:20] DEBUG[6055] pjsip: stuse0x7f135c0 STUN session 0x7f135c019768 destroy request, ref_cnt=3 [Dec 22 16:54:20] DEBUG[6055] pjsip: ice_session.c ICE session 0x7f135c016348 destroyed [Dec 22 16:54:20] DEBUG[6055] pjsip: stun_session.c STUN session 0x7f135c018768 destroyed [Dec 22 16:54:20] DEBUG[6055] pjsip: stun_session.c STUN session 0x7f135c019768 destroyed [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 111 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 18 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 0 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 58 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 118 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 9 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 8 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 58 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Setting payload 96 (0x7f135c013878) based on m type on 0x7f136d0a0680 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 0 (0x7f135c016378) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 8 (0x7f135c01b138) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 9 (0x7f135c017168) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 18 (0x7f135c00e9c8) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 58 (0x7f135c0163f8) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 96 (0x7f135c017ab8) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 111 (0x7f135c00e838) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Copying payload 118 (0x7f135c01b0b8) from 0x7f136d0a0680 to 0x7f135c012d80 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Media stream 'audio' handled by audio [Dec 22 16:54:20] DEBUG[6055] pjsip: endpoint .Response msg 100/INVITE/cseq=20657 (tdta0x7f135c009bc0) created [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b .Initial answer Response msg 100/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:54:20] DEBUG[6055] pjsip: inv0x7f135c00b .Sending Response msg 100/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ..Sending Response msg 100/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ..Sending Response msg 100/INVITE/cseq=20657 (tdta0x7f135c009bc0) in state Trying [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Transmitting SIP response (325 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjU1-g9ERRs5xGATn2TJzUxTO-Y12NgiRD Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: CSeq: 20657 INVITE Content-Length: 0 [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ...State changed from Trying to Proceeding, event=TX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ....Transaction tsx0x7f135c00cfa8 state changed to Proceeding [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is INCOMING [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Sending response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c00cfa8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is INCOMING [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Sending response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b Module NAT added as dialog usage, data=(nil) [Dec 22 16:54:20] DEBUG[6034] threadpool.c: Increasing threadpool stasis-core's size by 1 [Dec 22 16:54:20] DEBUG[6055] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6001-00000000 [Dec 22 16:54:20] DEBUG[6138][C-00000000] pbx.c: Launching 'Dial' [Dec 22 16:54:20] DEBUG[6055] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a UAC dialog created [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module Outbound Authentica added as dialog usage, data=0x7f135c01d790 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module mod-invite added as dialog usage, data=0x7f135c01dc98 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a .Session count inc to 2 by mod-invite [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module mod-100rel added as dialog usage, data=0x7f135c01de58 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a 100rel module attached [Dec 22 16:54:20] DEBUG[6055] pjsip: inv0x7f135c00a UAC invite session created for dialog dlg0x7f135c00ac78 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a .Session count inc to 2 by Session Module [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module Session Module added as dialog usage, data=(nil) [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f135c011078' [Dec 22 16:54:20] DEBUG[6055] res_rtp_asterisk.c: Allocated port 16936 for RTP instance '0x7f135c011078' [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 ICE session created, comp_cnt=2, role is Unknown agent [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:16936, base=10.24.18.124:16936, prio=0x7effffff (2130706431) [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16936, base=10.24.18.124:16936, prio=0x64ffffff (1694498815) [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: RTP instance '0x7f135c011078' is setup and ready to go [Dec 22 16:54:20] DEBUG[6055] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f135c011078' [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:16937, base=10.24.18.124:16937, prio=0x7efffffe (2130706430) [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '216.207.245.1' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '216.207.245.1' and port ''. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 22 16:54:20] DEBUG[6055] pjsip: icess0x7f135c0 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:18121, base=10.24.18.124:16937, prio=0x64fffffe (1694498814) [Dec 22 16:54:20] DEBUG[6055] sdp_srtp.c: local_key64 kzpoOONl7LoPZ2Us2JkJOfK8izKS8Gpw7waEMVnX len 40 [Dec 22 16:54:20] DEBUG[6055] pjsip: endpoint Request msg INVITE/cseq=4882 (tdta0x7f135c006c60) created. [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module WebSocket Transport Module added as dialog usage, data=(nil) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a Module NAT added as dialog usage, data=(nil) [Dec 22 16:54:20] DEBUG[6055] pjsip: inv0x7f135c00a .Sending Request msg INVITE/cseq=4882 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ..Sending Request msg INVITE/cseq=4882 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 ...Transaction created for Request msg INVITE/cseq=4881 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 ..Sending Request msg INVITE/cseq=4881 (tdta0x7f135c006c60) in state Null [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_resolve.c ...Target '10.24.18.124:45243' type=WS resolved to '10.24.18.124:45243' type=WS ((null)) [Dec 22 16:54:20] DEBUG[6056] pjsip: inv0x7f135c00b .Sending Response msg 180/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6056] pjsip: dlg0x7f135c00b ..Sending Response msg 180/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6056] pjsip: tsx0x7f135c00c ..Sending Response msg 180/INVITE/cseq=20657 (tdta0x7f135c009bc0) in state Proceeding [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6056] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6056] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6056] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Transmitting SIP request (1506 bytes) to WS:10.24.18.124:45243 ---> INVITE sip:dn18f08b@10.24.18.124:45243;transport=ws SIP/2.0 Via: SIP/2.0/WS 10.24.18.124:45243;rport;branch=z9hG4bKPj10d66eb8-53eb-4bef-a617-0ab028c611bf;alias From: "Alice" ;tag=44117ec1-0f48-4e8b-be9f-bd9ebbb93f2b To: Contact: Call-ID: 4184e9e3-dbb9-458f-b145-49aee09858c7 CSeq: 4881 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Content-Type: application/sdp Content-Length: 827 v=0 o=- 1638688404 1638688404 IN IP4 10.24.18.124 s=Asterisk c=IN IP4 10.24.18.124 t=0 0 m=audio 16936 UDP/TLS/RTP/SAVPF 0 101 a=connection:new a=setup:actpass a=fingerprint:SHA-256 D3:4C:64:80:0A:5D:BA:49:A1:CD:56:90:20:D1:5B:B3:B5:BA:CF:41:C1:5F:F6:6A:31:C4:11:36:5F:B8:33:26 a=ice-ufrag:56b6df355fa852f25f4b548b48b703ab a=ice-pwd:1798b94b1954afff51047edc319cf4ef a=candidate:Ha18127c 1 UDP 2130706431 10.24.18.124 16936 typ host a=candidate:Sd8cff501 1 UDP 1694498815 216.207.245.1 16936 typ srflx raddr 10.24.18.124 rport 16936 a=candidate:Ha18127c 2 UDP 2130706430 10.24.18.124 16937 typ host a=candidate:Sd8cff501 2 UDP 1694498814 216.207.245.1 18121 typ srflx raddr 10.24.18.124 rport 16937 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Dec 22 16:54:20] DEBUG[6056] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] VERBOSE[6056] res_pjsip_logger.c: <--- Transmitting SIP response (512 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjU1-g9ERRs5xGATn2TJzUxTO-Y12NgiRD Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: ;tag=2a12fc46-4fd1-4e66-9b4d-51618092110b CSeq: 20657 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Content-Length: 0 [Dec 22 16:54:20] DEBUG[6056] pjsip: tsx0x7f135c00c ...State changed from Proceeding to Proceeding, event=TX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 ...State changed from Null to Calling, event=TX_MSG [Dec 22 16:54:20] DEBUG[6056] pjsip: dlg0x7f135c00b ....Transaction tsx0x7f135c00cfa8 state changed to Proceeding [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ....Transaction tsx0x7f135c033da8 state changed to Calling [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c033da8) [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Sending response [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Sending request [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c00cfa8 [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: The current inv state is EARLY [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Sending response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c033da8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c033da8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Calling [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Sending request [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=4881 (rdata0x7f135c004fa0) [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Received SIP response (344 bytes) from WS:10.24.18.124:45243 ---> SIP/2.0 100 Trying Via: SIP/2.0/WS 10.24.18.124:45243;rport;branch=z9hG4bKPj10d66eb8-53eb-4bef-a617-0ab028c611bf;alias To: From: "Alice" ;tag=44117ec1-0f48-4e8b-be9f-bd9ebbb93f2b Call-ID: 4184e9e3-dbb9-458f-b145-49aee09858c7 CSeq: 4881 INVITE Supported: outbound Content-Length: 0 [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=4881 (rdata0x7f135c03a978) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 .Incoming Response msg 100/INVITE/cseq=4881 (rdata0x7f135c03a978) in state Calling [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 ..State changed from Calling to Proceeding, event=RX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ...Received Response msg 100/INVITE/cseq=4881 (rdata0x7f135c03a978) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ...Transaction tsx0x7f135c033da8 state changed to Proceeding [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c033da8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c033da8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Proceeding [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is CALLING [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Received response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Response is 100 Trying [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Processing incoming message: Response msg 488/INVITE/cseq=4881 (rdata0x7f135c004fa0) [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Received SIP response (372 bytes) from WS:10.24.18.124:45243 ---> SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/WS 10.24.18.124:45243;rport;branch=z9hG4bKPj10d66eb8-53eb-4bef-a617-0ab028c611bf;alias To: ;tag=8qrftrpnet From: "Alice" ;tag=44117ec1-0f48-4e8b-be9f-bd9ebbb93f2b Call-ID: 4184e9e3-dbb9-458f-b145-49aee09858c7 CSeq: 4881 INVITE Supported: outbound Content-Length: 0 [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 488/INVITE/cseq=4881 (rdata0x7f135c03a978) [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 .Incoming Response msg 488/INVITE/cseq=4881 (rdata0x7f135c03a978) in state Proceeding [Dec 22 16:54:20] DEBUG[6055] pjsip: endpoint ..Request msg ACK/cseq=4881 (tdta0x7f135c03c8a0) created. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.124:45243' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.124' and port '45243'. [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Transmitting SIP request (374 bytes) to WS:10.24.18.124:45243 ---> ACK sip:dn18f08b@10.24.18.124:45243;transport=ws SIP/2.0 Via: SIP/2.0/WS 10.24.18.124:45243;rport;branch=z9hG4bKPj10d66eb8-53eb-4bef-a617-0ab028c611bf;alias From: "Alice" ;tag=44117ec1-0f48-4e8b-be9f-bd9ebbb93f2b To: ;tag=8qrftrpnet Call-ID: 4184e9e3-dbb9-458f-b145-49aee09858c7 CSeq: 4881 ACK Content-Length: 0 [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c033 ..State changed from Proceeding to Completed, event=RX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ...Received Response msg 488/INVITE/cseq=4881 (rdata0x7f135c03a978) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a ...Transaction tsx0x7f135c033da8 state changed to Completed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 101 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c033da8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Received response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Response is 488 Not Acceptable Here [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00a .....Session count dec to 2 by mod-invite [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: inv_session 0x7f135c01dc98 has no ast session [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c033da8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c033da8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Completed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6055] pjsip: tdta0x7f135c00 ..Destroying txdata Request msg INVITE/cseq=4881 (tdta0x7f135c006c60) [Dec 22 16:54:20] DEBUG[6138][C-00000000] channel.c: Hanging up channel 'PJSIP/101-00000001' [Dec 22 16:54:20] DEBUG[6048] cdr.c: Finalized CDR for PJSIP/6001-00000000 - start 1419288860.158098 answer 0.000000 end 1419288860.282696 dispo NO ANSWER [Dec 22 16:54:20] DEBUG[6138][C-00000000] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Dec 22 16:54:20] DEBUG[6056] res_pjsip_session.c: Destroying SIP session with endpoint 101 [Dec 22 16:54:20] DEBUG[6056] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f135c011078' [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE, Response is 503 Service Unavailable [Dec 22 16:54:20] DEBUG[6055] pjsip: inv0x7f135c00b .Sending Response msg 503/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ..Sending Response msg 503/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6046] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 22 16:54:20] DEBUG[6056] pjsip: icess0x7f135c0 Destroying ICE session 0x7f135c023ad8 [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ..Sending Response msg 503/INVITE/cseq=20657 (tdta0x7f135c009bc0) in state Proceeding [Dec 22 16:54:20] DEBUG[6056] pjsip: stuse0x7f135c0 STUN session 0x7f135c026108 destroy request, ref_cnt=4 [Dec 22 16:54:20] DEBUG[6056] pjsip: stuse0x7f135c0 STUN session 0x7f135c027108 destroy request, ref_cnt=3 [Dec 22 16:54:20] DEBUG[6056] pjsip: ice_session.c ICE session 0x7f135c023ad8 destroyed [Dec 22 16:54:20] DEBUG[6046] devicestate.c: Changing state for PJSIP/6001 - state 3 (Busy) [Dec 22 16:54:20] DEBUG[6056] pjsip: stun_session.c STUN session 0x7f135c026108 destroyed [Dec 22 16:54:20] DEBUG[6056] pjsip: stun_session.c STUN session 0x7f135c027108 destroyed [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6101] app_queue.c: Device 'PJSIP/6001' changed to state '3' (Busy) but we don't care because they're not a member of any queue. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6055] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6055] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] DEBUG[6056] rtp_engine.c: Destroyed RTP instance '0x7f135c011078' [Dec 22 16:54:20] VERBOSE[6055] res_pjsip_logger.c: <--- Transmitting SIP response (514 bytes) to UDP:10.24.18.16:5060 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 10.24.18.16:5060;rport=5060;received=10.24.18.16;branch=z9hG4bKPjU1-g9ERRs5xGATn2TJzUxTO-Y12NgiRD Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: ;tag=2a12fc46-4fd1-4e66-9b4d-51618092110b CSeq: 20657 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER Reason: Q.850;cause=34 Content-Length: 0 [Dec 22 16:54:20] DEBUG[6056] pjsip: dlg0x7f135c00a .Session count dec to 0 by Session Module [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ...State changed from Proceeding to Completed, event=TX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ....Transaction tsx0x7f135c00cfa8 state changed to Completed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: There is no transaction involved in this state change [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Sending response [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Method is INVITE, Response is 503 Service Unavailable [Dec 22 16:54:20] DEBUG[6048] cdr.c: Finalized CDR for PJSIP/101-00000001 - start 1419288860.160306 answer 0.000000 end 1419288860.283160 dispo NO ANSWER [Dec 22 16:54:20] DEBUG[6034] threadpool.c: Increasing threadpool stasis-core's size by 1 [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ......Session count dec to 3 by mod-invite [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: inv_session 0x7f135c00c7d8 has no ast session [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c00cfa8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Completed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6056] taskprocessor.c: destroying taskprocessor 'a9526e6b-7d65-4609-9279-2f9afee30700' [Dec 22 16:54:20] DEBUG[6046] devicestate.c: No provider found, checking channel drivers for PJSIP - 101 [Dec 22 16:54:20] DEBUG[6046] devicestate.c: Changing state for PJSIP/101 - state 1 (Not in use) [Dec 22 16:54:20] DEBUG[6048] cdr.c: CDR for PJSIP/101-00000001 is dialed and has no Party B; discarding [Dec 22 16:54:20] DEBUG[6138][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/6001-00000000' [Dec 22 16:54:20] DEBUG[6138][C-00000000] channel.c: Hanging up channel 'PJSIP/6001-00000000' [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Destroying SIP session with endpoint 6001 [Dec 22 16:54:20] DEBUG[6055] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f135c012bb8' [Dec 22 16:54:20] DEBUG[6055] rtp_engine.c: Destroyed RTP instance '0x7f135c012bb8' [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b .Session count dec to 0 by Session Module [Dec 22 16:54:20] DEBUG[6046] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 22 16:54:20] DEBUG[6055] taskprocessor.c: destroying taskprocessor '36a63ca9-6771-4cd2-84ab-eb3c53ca5dbd' [Dec 22 16:54:20] DEBUG[6046] devicestate.c: Changing state for PJSIP/6001 - state 1 (Not in use) [Dec 22 16:54:20] DEBUG[6101] app_queue.c: Device 'PJSIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 22 16:54:20] DEBUG[6060] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=20657 (rdata0x7f13bc0021b8) [Dec 22 16:54:20] VERBOSE[6060] res_pjsip_logger.c: <--- Received SIP request (369 bytes) from UDP:10.24.18.16:5060 ---> ACK sip:101@10.24.18.124 SIP/2.0 Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjU1-g9ERRs5xGATn2TJzUxTO-Y12NgiRD Max-Forwards: 70 From: "Alice" ;tag=H4t9ZGvNGVN95Q199C3yGSNQpaC5aQSO To: ;tag=2a12fc46-4fd1-4e66-9b4d-51618092110b Call-ID: NztkFpje1EWJsgi6SycqVj4sD8RqzjLD CSeq: 20657 ACK Content-Length: 0 [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '10.24.18.16:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '10.24.18.16' and port '5060'. [Dec 22 16:54:20] DEBUG[6060] netsock2.c: Splitting '0.0.0.0:5060' into... [Dec 22 16:54:20] DEBUG[6060] netsock2.c: ...host '0.0.0.0' and port '5060'. [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c033 Timeout timer event [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c033 .State changed from Completed to Terminated, event=TIMER [Dec 22 16:54:20] DEBUG[6060] pjsip: dlg0x7f135c00a ..Transaction tsx0x7f135c033da8 state changed to Terminated [Dec 22 16:54:20] DEBUG[6055] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=20657 (rdata0x7f13bc005f78) [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: inv_session 0x7f135c01dc98 has no ast session [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c033da8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The current transaction state is Terminated [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The transaction state change event is TIMER [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6060] pjsip: dlg0x7f135c00a ...Dialog destroyed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c .Incoming Request msg ACK/cseq=20657 (rdata0x7f13bc005f78) in state Completed [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c033 Timeout timer event [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c033 .State changed from Terminated to Destroyed, event=TIMER [Dec 22 16:54:20] DEBUG[6055] pjsip: tsx0x7f135c00c ..State changed from Completed to Confirmed, event=RX_MSG [Dec 22 16:54:20] DEBUG[6055] pjsip: dlg0x7f135c00b ...Transaction tsx0x7f135c00cfa8 state changed to Confirmed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6060] pjsip: tdta0x7f135c03 ..Destroying txdata Request msg ACK/cseq=4881 (tdta0x7f135c03c8a0) [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: inv_session 0x7f135c00c7d8 has no ast session [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f135c00cfa8) [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c033 Transaction destroyed! [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c00cfa8 [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current transaction state is Confirmed [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c00c Timeout timer event [Dec 22 16:54:20] DEBUG[6055] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c00c .State changed from Confirmed to Terminated, event=TIMER [Dec 22 16:54:20] DEBUG[6060] pjsip: dlg0x7f135c00b ..Transaction tsx0x7f135c00cfa8 state changed to Terminated [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: inv_session 0x7f135c00c7d8 has no ast session [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The transaction involved in this state change is 0x7f135c00cfa8 [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The current transaction state is Terminated [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The transaction state change event is TIMER [Dec 22 16:54:20] DEBUG[6060] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 22 16:54:20] DEBUG[6060] pjsip: dlg0x7f135c00b ...Dialog destroyed [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c00c Timeout timer event [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c00c .State changed from Terminated to Destroyed, event=TIMER [Dec 22 16:54:20] DEBUG[6060] pjsip: tdta0x7f135c00 ..Destroying txdata Response msg 503/INVITE/cseq=20657 (tdta0x7f135c009bc0) [Dec 22 16:54:20] DEBUG[6060] pjsip: tsx0x7f135c00c Transaction destroyed! [Dec 22 16:54:25] DEBUG[6058] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:54:25] DEBUG[6057] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:54:25] DEBUG[6059] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 22 16:54:25] DEBUG[6054] threadpool.c: Destroying worker thread 8 [Dec 22 16:54:25] DEBUG[6054] threadpool.c: Destroying worker thread 7 [Dec 22 16:54:25] DEBUG[6054] threadpool.c: Destroying worker thread 9 [Dec 22 16:54:26] DEBUG[6136] cdr.c: CDR Engine termination request received; waiting on messages... [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Dec 22 16:54:26] VERBOSE[6136] asterisk.c: Asterisk cleanly ending (0). [Dec 22 16:54:26] VERBOSE[6136] asterisk.c: Executing last minute cleanups [Dec 22 16:54:26] DEBUG[6136] res_musiconhold.c: Destroying MOH class 'default' [Dec 22 16:54:26] DEBUG[6053] taskprocessor.c: destroying taskprocessor 'a09abf69-36e9-41ea-b2cc-ccd66874de62' [Dec 22 16:54:26] DEBUG[6136] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'CCSS core' [Dec 22 16:54:26] DEBUG[6136] tcptls.c: Stopped server :: AMI server [Dec 22 16:54:26] DEBUG[6136] tcptls.c: Stopped server :: AMI TLS server [Dec 22 16:54:26] DEBUG[6136] channel.c: Unregistering channel type 'Local' [Dec 22 16:54:26] DEBUG[6050] taskprocessor.c: destroying taskprocessor 'fe361cc1-171e-4827-81cc-5bcc0f6379c7' [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'a5e1bd1b-2f17-41f5-b1da-a98601e7ad98' [Dec 22 16:54:26] DEBUG[6048] taskprocessor.c: destroying taskprocessor '3bc531fe-10a7-4bf2-af50-a63d2c0a99d7' [Dec 22 16:54:26] DEBUG[6136] tcptls.c: Stopped server :: http server [Dec 22 16:54:26] DEBUG[6136] bridge.c: Waiting for bridge manager thread to die. [Dec 22 16:54:26] DEBUG[6136] channel.c: Unregistering channel type 'Surrogate' [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'stasis-core-control' [Dec 22 16:54:26] DEBUG[6136] threadpool.c: Destroying worker thread 11 [Dec 22 16:54:26] DEBUG[6136] threadpool.c: Destroying worker thread 12 [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'stasis-core' [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Dec 22 16:54:26] DEBUG[6136] threadpool.c: Destroying worker thread 10 [Dec 22 16:54:26] DEBUG[6136] taskprocessor.c: destroying taskprocessor 'Sorcery' [Dec 22 16:54:26] DEBUG[6136] asterisk.c: Asterisk ending (0).