[Aug 20 20:35:56] Asterisk SVN-branch-12-r421608 built by root @ newtonr-laptop on a x86_64 running Linux on 2014-08-21 00:21:32 UTC [Aug 20 20:35:56] DEBUG[25041] config.c: Parsing /etc/asterisk/logger.conf [Aug 20 20:36:00] DEBUG[24993] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=101 (rdata0x7fab60002ce8) [Aug 20 20:36:00] VERBOSE[24993] res_pjsip_logger.c: <--- Received SIP request (898 bytes) from UDP:192.168.1.245:5060 ---> INVITE sip:2000@192.168.1.187 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.245:5060;branch=z9hG4bK-c26e22ce From: "6001" ;tag=a40fb2a85f0543beo0 To: Call-ID: 51534470-69bd9c96@192.168.1.245 CSeq: 101 INVITE Max-Forwards: 70 Contact: "6001" Expires: 240 User-Agent: Linksys/SPA942-5.2.8 Content-Length: 395 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 25543 25543 IN IP4 192.168.1.245 s=- c=IN IP4 192.168.1.245 t=0 0 m=audio 16472 RTP/AVP 0 8 2 4 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv [Aug 20 20:36:00] DEBUG[24988] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=101 (rdata0x7fab60005c18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Aug 20 20:36:00] DEBUG[24988] pjsip: endpoint .Response msg 401/INVITE/cseq=101 (tdta0x7fab88004c10) created [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.187' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.187' and port ''. [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.245' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.245' and port ''. [Aug 20 20:36:00] VERBOSE[24988] res_pjsip_logger.c: <--- Transmitting SIP response (458 bytes) to UDP:192.168.1.245:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.245:5060;rport;received=192.168.1.245;branch=z9hG4bK-c26e22ce Call-ID: 51534470-69bd9c96@192.168.1.245 From: "6001" ;tag=a40fb2a85f0543beo0 To: ;tag=z9hG4bK-c26e22ce CSeq: 101 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1408584960/90faee0b26bb136c1b152d766e1dfff0",opaque="4c02e53f2096e255",algorithm=md5,qop="auth" Content-Length: 0 [Aug 20 20:36:00] DEBUG[24988] pjsip: tdta0x7fab8800 .Destroying txdata Response msg 401/INVITE/cseq=101 (tdta0x7fab88004c10) [Aug 20 20:36:00] DEBUG[24993] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=101 (rdata0x7fab60001fd8) [Aug 20 20:36:00] VERBOSE[24993] res_pjsip_logger.c: <--- Received SIP request (387 bytes) from UDP:192.168.1.245:5060 ---> ACK sip:2000@192.168.1.187 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.245:5060;branch=z9hG4bK-c26e22ce From: "6001" ;tag=a40fb2a85f0543beo0 To: ;tag=z9hG4bK-c26e22ce Call-ID: 51534470-69bd9c96@192.168.1.245 CSeq: 101 ACK Max-Forwards: 70 Contact: "6001" User-Agent: Linksys/SPA942-5.2.8 Content-Length: 0 [Aug 20 20:36:00] DEBUG[24988] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=101 (rdata0x7fab60004708) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Aug 20 20:36:00] DEBUG[24993] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=102 (rdata0x7fab60001fd8) [Aug 20 20:36:00] VERBOSE[24993] res_pjsip_logger.c: <--- Received SIP request (1158 bytes) from UDP:192.168.1.245:5060 ---> INVITE sip:2000@192.168.1.187 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.245:5060;branch=z9hG4bK-88548e9e From: "6001" ;tag=a40fb2a85f0543beo0 To: Call-ID: 51534470-69bd9c96@192.168.1.245 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="6001",realm="asterisk",nonce="1408584960/90faee0b26bb136c1b152d766e1dfff0",uri="sip:2000@192.168.1.187",algorithm=MD5,response="d06396cd239efcc62fd138e535537899",opaque="4c02e53f2096e255",qop=auth,nc=00000001,cnonce="423221d2" Contact: "6001" Expires: 240 User-Agent: Linksys/SPA942-5.2.8 Content-Length: 395 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 25543 25543 IN IP4 192.168.1.245 s=- c=IN IP4 192.168.1.245 t=0 0 m=audio 16472 RTP/AVP 0 8 2 4 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv [Aug 20 20:36:00] DEBUG[24988] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=102 (rdata0x7fab60005728) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Aug 20 20:36:00] DEBUG[24988] pjsip: endpoint .Response msg 401/INVITE/cseq=102 (tdta0x7fab88004c10) created [Aug 20 20:36:00] DEBUG[24988] res_pjsip_authenticator_digest.c: Calculated nonce 1408584960/90faee0b26bb136c1b152d766e1dfff0. Actual nonce is 1408584960/90faee0b26bb136c1b152d766e1dfff0 [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.187' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.187' and port ''. [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.245' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.245' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: tdta0x7fab8800 .Destroying txdata Response msg 401/INVITE/cseq=102 (tdta0x7fab88004c10) [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ..Transaction created for Request msg INVITE/cseq=102 (rdata0x7fab60005728) [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 .Incoming Request msg INVITE/cseq=102 (rdata0x7fab60005728) in state Null [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ..State changed from Null to Trying, event=RX_MSG [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ...Transaction tsx0x7fab88009d18 state changed to Trying [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 .UAS dialog created [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 .Module mod-invite added as dialog usage, data=0x7fab8800c448 [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ..Session count inc to 2 by mod-invite [Aug 20 20:36:00] DEBUG[24988] pjsip: inv0x7fab88009 .UAS invite session created for dialog dlg0x7fab880092f8 [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 .Module Session Module added as dialog usage, data=(nil) [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ..Session count inc to 2 by Session Module [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.245' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.245' and port ''. [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fab88015d08' [Aug 20 20:36:00] DEBUG[24988] res_rtp_asterisk.c: Allocated port 12654 for RTP instance '0x7fab88015d08' [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 ICE session created, comp_cnt=2, role is Unknown agent [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.187' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.187' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a801bb, addr=192.168.1.187:12654, base=192.168.1.187:12654, prio=0x7effffff (2130706431) [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '10.24.251.42' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '10.24.251.42' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 1 added: comp_id=1, type=host, foundation=Ha18fb2a, addr=10.24.251.42:12654, base=10.24.251.42:12654, prio=0x7effffff (2130706431) [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '173.17.135.67' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '173.17.135.67' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 2 added: comp_id=1, type=srflx, foundation=Sad118743, addr=173.17.135.67:12654, base=192.168.1.187:12654, prio=0x64ffffff (1694498815) [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: RTP instance '0x7fab88015d08' is setup and ready to go [Aug 20 20:36:00] DEBUG[24988] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fab88015d08' [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '192.168.1.187' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '192.168.1.187' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 3 added: comp_id=2, type=host, foundation=Hc0a801bb, addr=192.168.1.187:12655, base=192.168.1.187:12655, prio=0x7efffffe (2130706430) [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '10.24.251.42' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '10.24.251.42' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 4 added: comp_id=2, type=host, foundation=Ha18fb2a, addr=10.24.251.42:12655, base=10.24.251.42:12655, prio=0x7efffffe (2130706430) [Aug 20 20:36:00] DEBUG[24988] netsock2.c: Splitting '173.17.135.67' into... [Aug 20 20:36:00] DEBUG[24988] netsock2.c: ...host '173.17.135.67' and port ''. [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Candidate 5 added: comp_id=2, type=srflx, foundation=Sad118743, addr=173.17.135.67:12655, base=192.168.1.187:12655, prio=0x64fffffe (1694498814) [Aug 20 20:36:00] DEBUG[24988] pjsip: icess0x7fab880 Destroying ICE session 0x7fab8801cea8 [Aug 20 20:36:00] DEBUG[24988] pjsip: stuse0x7fab880 STUN session 0x7fab8800b4c8 destroy request, ref_cnt=4 [Aug 20 20:36:00] DEBUG[24988] pjsip: stuse0x7fab880 STUN session 0x7fab8801eeb8 destroy request, ref_cnt=3 [Aug 20 20:36:00] DEBUG[24988] pjsip: ice_session.c ICE session 0x7fab8801cea8 destroyed [Aug 20 20:36:00] DEBUG[24988] pjsip: stun_session.c STUN session 0x7fab8800b4c8 destroyed [Aug 20 20:36:00] DEBUG[24988] pjsip: stun_session.c STUN session 0x7fab8801eeb8 destroyed [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 0 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 8 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 2 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 4 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 18 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 96 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 97 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 98 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Setting payload 101 based on m type on 0x7fabd8123200 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 0 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 2 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 4 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 8 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 18 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 96 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 97 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 98 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Copying payload 101 from 0x7fabd8123200 to 0x7fab88015e48 [Aug 20 20:36:00] DEBUG[24988] pjsip: endpoint .Response msg 100/INVITE/cseq=102 (tdta0x7fab88003c00) created [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 .Initial answer Response msg 100/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 20 20:36:00] DEBUG[24988] pjsip: inv0x7fab88009 .Sending Response msg 100/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ..Sending Response msg 100/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ..Sending Response msg 100/INVITE/cseq=102 (tdta0x7fab88003c00) in state Trying [Aug 20 20:36:00] VERBOSE[24988] res_pjsip_logger.c: <--- Transmitting SIP response (284 bytes) to UDP:192.168.1.245:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.245:5060;rport;received=192.168.1.245;branch=z9hG4bK-88548e9e Call-ID: 51534470-69bd9c96@192.168.1.245 From: "6001" ;tag=a40fb2a85f0543beo0 To: CSeq: 102 INVITE Content-Length: 0 [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ...State changed from Trying to Proceeding, event=TX_MSG [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ....Transaction tsx0x7fab88009d18 state changed to Proceeding [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The state change pertains to the session with 6001 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fab88009d18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: There is no transaction involved in this state change [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current inv state is INCOMING [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Sending response [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The state change pertains to the session with 6001 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fab88009d18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction involved in this state change is 0x7fab88009d18 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current transaction state is Proceeding [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current inv state is INCOMING [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Method is INVITE [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 Module NAT added as dialog usage, data=(nil) [Aug 20 20:36:00] DEBUG[24988] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6001-00000000 [Aug 20 20:36:00] DEBUG[25043][C-00000000] pbx.c: Launching 'NoOp' [Aug 20 20:36:00] DEBUG[25043][C-00000000] pbx.c: Launching 'Transfer' [Aug 20 20:36:00] DEBUG[25043][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/6001-00000000' [Aug 20 20:36:00] DEBUG[25043][C-00000000] channel.c: Hanging up channel 'PJSIP/6001-00000000' [Aug 20 20:36:00] DEBUG[25043][C-00000000] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Method is INVITE, Response is 603 Decline [Aug 20 20:36:00] DEBUG[24988] pjsip: inv0x7fab88009 .Sending Response msg 603/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ..Sending Response msg 603/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ..Sending Response msg 603/INVITE/cseq=102 (tdta0x7fab88003c00) in state Proceeding [Aug 20 20:36:00] VERBOSE[24988] res_pjsip_logger.c: <--- Transmitting SIP response (349 bytes) to UDP:192.168.1.245:5060 ---> SIP/2.0 603 Decline Via: SIP/2.0/UDP 192.168.1.245:5060;rport;received=192.168.1.245;branch=z9hG4bK-88548e9e Call-ID: 51534470-69bd9c96@192.168.1.245 From: "6001" ;tag=a40fb2a85f0543beo0 To: ;tag=ddd197ab-6e11-4322-a0d4-8c09fdf1d084 CSeq: 102 INVITE Reason: Q.850;cause=0 Content-Length: 0 [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ...State changed from Proceeding to Completed, event=TX_MSG [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ....Transaction tsx0x7fab88009d18 state changed to Completed [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The state change pertains to the session with 6001 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fab88009d18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: There is no transaction involved in this state change [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Sending response [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Method is INVITE, Response is 603 Decline [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ......Session count dec to 3 by mod-invite [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: inv_session 0x7fab8800c448 has no ast session [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fab88009d18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction involved in this state change is 0x7fab88009d18 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current transaction state is Completed [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Destroying SIP session with endpoint 6001 [Aug 20 20:36:00] DEBUG[24988] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fab88015d08' [Aug 20 20:36:00] DEBUG[24988] rtp_engine.c: Destroyed RTP instance '0x7fab88015d08' [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 .Session count dec to 0 by Session Module [Aug 20 20:36:00] DEBUG[24981] cdr.c: Finalized CDR for PJSIP/6001-00000000 - start 1408584960.454951 answer 0.000000 end 1408584960.457230 dispo FAILED [Aug 20 20:36:00] DEBUG[24981] cdr.c: Skipping CDR for PJSIP/6001-00000000 since we weren't answered [Aug 20 20:36:00] DEBUG[24988] taskprocessor.c: destroying taskprocessor 'f663baa6-c098-4546-9dbf-77c3af4d2521' [Aug 20 20:36:00] DEBUG[24979] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Aug 20 20:36:00] DEBUG[24979] devicestate.c: Changing state for PJSIP/6001 - state 1 (Not in use) [Aug 20 20:36:00] DEBUG[24993] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=102 (rdata0x7fab60001968) [Aug 20 20:36:00] VERBOSE[24993] res_pjsip_logger.c: <--- Received SIP request (667 bytes) from UDP:192.168.1.245:5060 ---> ACK sip:2000@192.168.1.187 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.245:5060;branch=z9hG4bK-88548e9e From: "6001" ;tag=a40fb2a85f0543beo0 To: ;tag=ddd197ab-6e11-4322-a0d4-8c09fdf1d084 Call-ID: 51534470-69bd9c96@192.168.1.245 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="6001",realm="asterisk",nonce="1408584960/90faee0b26bb136c1b152d766e1dfff0",uri="sip:2000@192.168.1.187",algorithm=MD5,response="d06396cd239efcc62fd138e535537899",opaque="4c02e53f2096e255",qop=auth,nc=00000001,cnonce="423221d2" Contact: "6001" User-Agent: Linksys/SPA942-5.2.8 Content-Length: 0 [Aug 20 20:36:00] DEBUG[24988] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=102 (rdata0x7fab60005728) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 20 20:36:00] DEBUG[24988] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 .Incoming Request msg ACK/cseq=102 (rdata0x7fab60005728) in state Completed [Aug 20 20:36:00] DEBUG[24988] pjsip: tsx0x7fab88009 ..State changed from Completed to Confirmed, event=RX_MSG [Aug 20 20:36:00] DEBUG[24988] pjsip: dlg0x7fab88009 ...Transaction tsx0x7fab88009d18 state changed to Confirmed [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: inv_session 0x7fab8800c448 has no ast session [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fab88009d18) [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction involved in this state change is 0x7fab88009d18 [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current transaction state is Confirmed [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 20 20:36:00] DEBUG[24988] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 20 20:36:00] DEBUG[24993] pjsip: tsx0x7fab88009 Timeout timer event [Aug 20 20:36:00] DEBUG[24993] pjsip: tsx0x7fab88009 .State changed from Confirmed to Terminated, event=TIMER [Aug 20 20:36:00] DEBUG[24993] pjsip: dlg0x7fab88009 ..Transaction tsx0x7fab88009d18 state changed to Terminated [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: inv_session 0x7fab8800c448 has no ast session [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: The transaction involved in this state change is 0x7fab88009d18 [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: The current transaction state is Terminated [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: The transaction state change event is TIMER [Aug 20 20:36:00] DEBUG[24993] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 20 20:36:00] DEBUG[24993] pjsip: dlg0x7fab88009 ...Dialog destroyed [Aug 20 20:36:00] DEBUG[24993] pjsip: tsx0x7fab88009 Timeout timer event [Aug 20 20:36:00] DEBUG[24993] pjsip: tsx0x7fab88009 .State changed from Terminated to Destroyed, event=TIMER [Aug 20 20:36:00] DEBUG[24993] pjsip: tdta0x7fab8800 ..Destroying txdata Response msg 603/INVITE/cseq=102 (tdta0x7fab88003c00) [Aug 20 20:36:00] DEBUG[24993] pjsip: tsx0x7fab88009 Transaction destroyed! [Aug 20 20:36:04] DEBUG[25041] cdr.c: CDR Engine termination request received; waiting on messages... [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Aug 20 20:36:04] VERBOSE[25041] asterisk.c: Asterisk cleanly ending (0). [Aug 20 20:36:04] VERBOSE[25041] asterisk.c: Executing last minute cleanups [Aug 20 20:36:04] DEBUG[25041] res_musiconhold.c: Destroying MOH class 'default' [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor '176c9387-cba2-4fe2-8ea4-bc7a14adc9cf' [Aug 20 20:36:04] DEBUG[25041] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor 'CCSS core' [Aug 20 20:36:04] DEBUG[25041] tcptls.c: Stopped server :: AMI server [Aug 20 20:36:04] DEBUG[25041] tcptls.c: Stopped server :: AMI TLS server [Aug 20 20:36:04] DEBUG[25041] channel.c: Unregistering channel type 'Local' [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor '7dd67069-e2fa-449f-90d8-96116c4f39c6' [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor '29fd1cbb-71d1-4149-b630-93d407be3e4a' [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor '746a18a2-3ca6-4382-b857-d3f638a14655' [Aug 20 20:36:04] DEBUG[25041] tcptls.c: Stopped server :: http server [Aug 20 20:36:04] DEBUG[25041] bridge.c: Waiting for bridge manager thread to die. [Aug 20 20:36:04] DEBUG[25041] channel.c: Unregistering channel type 'Surrogate' [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Aug 20 20:36:04] DEBUG[25041] threadpool.c: Destroying worker thread 5 [Aug 20 20:36:04] DEBUG[25041] taskprocessor.c: destroying taskprocessor 'Sorcery' [Aug 20 20:36:04] DEBUG[25041] asterisk.c: Asterisk ending (0).