[Dec 20 10:41:38] Asterisk SVN-branch-12-r404375M built by root @ newtonr-laptop on a x86_64 running Linux on 2013-12-20 15:51:06 UTC [Dec 20 10:41:38] DEBUG[18287] config.c: Parsing /etc/asterisk/logger.conf [Dec 20 10:41:38] VERBOSE[18287] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Dec 20 10:41:38] VERBOSE[18287] logger.c: Asterisk Queue Logger restarted [Dec 20 10:41:48] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1343 (rdata0x7ff4380036d8) [Dec 20 10:41:48] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP request (877 bytes) from UDP:10.24.18.16:5060 ---> ˙INVITE sip:6002@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjASZxkN9sglZWl8AuF3RwXroQn59hcBc7 ˙Max-Forwards: 70 ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ˙Contact: "RustyONE" ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙CSeq: 1343 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: 240 ˙ ˙v=0 ˙o=- 82928999 82928999 IN IP4 10.24.18.16 ˙s=digphn ˙c=IN IP4 10.24.18.16 ˙t=0 0 ˙a=X-nat:0 ˙m=audio 4010 RTP/AVP 0 96 ˙a=rtcp:4011 IN IP4 10.24.18.16 ˙a=rtpmap:0 PCMU/8000 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-15 ˙ [Dec 20 10:41:48] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1343 (rdata0x7ff438006a08) [Dec 20 10:41:48] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:48] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:48] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: Source address 10.24.18.16:5060 does not match identify 'mytrunk_identify' [Dec 20 10:41:48] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: '10.24.18.16:5060' did not match any identify section rules [Dec 20 10:41:48] DEBUG[18235] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 20 10:41:48] DEBUG[18235] pjsip: endpoint .Response msg 401/INVITE/cseq=1343 (tdta0x7ff468008280) created [Dec 20 10:41:48] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:48] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:48] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:48] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:48] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:48] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:48] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (522 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjASZxkN9sglZWl8AuF3RwXroQn59hcBc7 ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=z9hG4bKPjASZxkN9sglZWl8AuF3RwXroQn59hcBc7 ˙CSeq: 1343 INVITE ˙WWW-Authenticate: Digest realm="asterisk",nonce="1387557708/b9a9fb6c7d25b12c741b0816bd73e8e3",opaque="71538615316d7263",algorithm=md5,qop="auth" ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:48] DEBUG[18235] pjsip: tdta0x7ff46800 .Destroying txdata Response msg 401/INVITE/cseq=1343 (tdta0x7ff468008280) [Dec 20 10:41:49] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1343 (rdata0x7ff4380036d8) [Dec 20 10:41:49] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP request (378 bytes) from UDP:10.24.18.16:5060 ---> ˙ACK sip:6002@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjASZxkN9sglZWl8AuF3RwXroQn59hcBc7 ˙Max-Forwards: 70 ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=z9hG4bKPjASZxkN9sglZWl8AuF3RwXroQn59hcBc7 ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙CSeq: 1343 ACK ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1343 (rdata0x7ff438005a28) [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: Source address 10.24.18.16:5060 does not match identify 'mytrunk_identify' [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: '10.24.18.16:5060' did not match any identify section rules [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 20 10:41:49] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1344 (rdata0x7ff4380036d8) [Dec 20 10:41:49] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP request (1169 bytes) from UDP:10.24.18.16:5060 ---> ˙INVITE sip:6002@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Max-Forwards: 70 ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ˙Contact: "RustyONE" ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙CSeq: 1344 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="6001", realm="asterisk", nonce="1387557708/b9a9fb6c7d25b12c741b0816bd73e8e3", uri="sip:6002@10.24.18.124", response="6ddcd30df27073066495317cc493c72a", algorithm=md5, cnonce="VdFBO6sOoerakjVhWfmg99MITUUlSNYz", opaque="71538615316d7263", qop=auth, nc=00000001 ˙Content-Type: application/sdp ˙Content-Length: 240 ˙ ˙v=0 ˙o=- 82928999 82928999 IN IP4 10.24.18.16 ˙s=digphn ˙c=IN IP4 10.24.18.16 ˙t=0 0 ˙a=X-nat:0 ˙m=audio 4010 RTP/AVP 0 96 ˙a=rtcp:4011 IN IP4 10.24.18.16 ˙a=rtpmap:0 PCMU/8000 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-15 ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1344 (rdata0x7ff438007228) [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: Source address 10.24.18.16:5060 does not match identify 'mytrunk_identify' [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: '10.24.18.16:5060' did not match any identify section rules [Dec 20 10:41:49] DEBUG[18235] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6001 [Dec 20 10:41:49] DEBUG[18235] pjsip: endpoint .Response msg 401/INVITE/cseq=1344 (tdta0x7ff468008280) created [Dec 20 10:41:49] DEBUG[18235] res_pjsip_authenticator_digest.c: Calculated nonce 1387557708/b9a9fb6c7d25b12c741b0816bd73e8e3. Actual nonce is 1387557708/b9a9fb6c7d25b12c741b0816bd73e8e3 [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] DEBUG[18235] pjsip: tdta0x7ff46800 .Destroying txdata Response msg 401/INVITE/cseq=1344 (tdta0x7ff468008280) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ..Transaction created for Request msg INVITE/cseq=1344 (rdata0x7ff438007228) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b .Incoming Request msg INVITE/cseq=1344 (rdata0x7ff438007228) in state Null [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ..State changed from Null to Trying, event=RX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ...Transaction tsx0x7ff46803bb38 state changed to Trying [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 .UAS dialog created [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 .Module mod-invite added as dialog usage, data=0x7ff468011fb8 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ..Session count inc to 2 by mod-invite [Dec 20 10:41:49] DEBUG[18235] pjsip: inv0x7ff468004 .UAS invite session created for dialog dlg0x7ff468004558 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 .Module Session Module added as dialog usage, data=(nil) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ..Session count inc to 2 by Session Module [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff46803e138' [Dec 20 10:41:49] DEBUG[18235] res_rtp_asterisk.c: Allocated port 17796 for RTP instance '0x7ff46803e138' [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 ICE session created, comp_cnt=2, role is Unknown agent [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:17796, base=10.24.18.124:17796, prio=0x7effffff (2130706431) [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: RTP instance '0x7ff46803e138' is setup and ready to go [Dec 20 10:41:49] DEBUG[18235] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff46803e138' [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:17797, base=10.24.18.124:17797, prio=0x7efffffe (2130706430) [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Destroying ICE session 0x7ff4680224a8 [Dec 20 10:41:49] DEBUG[18235] pjsip: stuse0x7ff4680 STUN session 0x7ff46802d5f8 destroy request, ref_cnt=4 [Dec 20 10:41:49] DEBUG[18235] pjsip: stuse0x7ff4680 STUN session 0x7ff46804fe78 destroy request, ref_cnt=3 [Dec 20 10:41:49] DEBUG[18235] pjsip: ice_session.c ICE session 0x7ff4680224a8 destroyed [Dec 20 10:41:49] DEBUG[18235] pjsip: stun_session.c STUN session 0x7ff46802d5f8 destroyed [Dec 20 10:41:49] DEBUG[18235] pjsip: stun_session.c STUN session 0x7ff46804fe78 destroyed [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Setting payload 0 based on m type on 0x7ff4a0090210 [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Setting payload 96 based on m type on 0x7ff4a0090210 [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Copying payload 0 from 0x7ff4a0090210 to 0x7ff46803e278 [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Copying payload 96 from 0x7ff4a0090210 to 0x7ff46803e278 [Dec 20 10:41:49] DEBUG[18235] pjsip: endpoint .Response msg 100/INVITE/cseq=1344 (tdta0x7ff468015680) created [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 .Initial answer Response msg 100/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 20 10:41:49] DEBUG[18235] pjsip: inv0x7ff468004 .Sending Response msg 100/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ..Sending Response msg 100/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ..Sending Response msg 100/INVITE/cseq=1344 (tdta0x7ff468015680) in state Trying [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (323 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ˙CSeq: 1344 INVITE ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ...State changed from Trying to Proceeding, event=TX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ....Transaction tsx0x7ff46803bb38 state changed to Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is INCOMING [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Sending response [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current transaction state is Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is INCOMING [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 Module NAT added as dialog usage, data=(nil) [Dec 20 10:41:49] DEBUG[18235] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/6001-0000000c [Dec 20 10:41:49] DEBUG[18525][C-00000006] pbx.c: Result of 'EXTEN' is '6002' [Dec 20 10:41:49] DEBUG[18525][C-00000006] pbx.c: Launching 'Dial' [Dec 20 10:41:49] VERBOSE[18525][C-00000006] pbx.c: -- Executing [6002@from-internal:1] Dial("PJSIP/6001-0000000c", "PJSIP/6002,15") in new stack [Dec 20 10:41:49] DEBUG[18235] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 UAC dialog created [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 Module Outbound Authentica added as dialog usage, data=0x7ff46800ede0 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 Module mod-invite added as dialog usage, data=0x7ff46802b308 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 .Session count inc to 2 by mod-invite [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 Module mod-100rel added as dialog usage, data=0x7ff46802b4b8 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 100rel module attached [Dec 20 10:41:49] DEBUG[18235] pjsip: inv0x7ff468016 UAC invite session created for dialog dlg0x7ff468016d68 [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 .Session count inc to 2 by Session Module [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 Module Session Module added as dialog usage, data=(nil) [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff468035a08' [Dec 20 10:41:49] DEBUG[18235] res_rtp_asterisk.c: Allocated port 17544 for RTP instance '0x7ff468035a08' [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 ICE session created, comp_cnt=2, role is Unknown agent [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:17544, base=10.24.18.124:17544, prio=0x7effffff (2130706431) [Dec 20 10:41:49] DEBUG[18235] rtp_engine.c: RTP instance '0x7ff468035a08' is setup and ready to go [Dec 20 10:41:49] DEBUG[18235] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff468035a08' [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Candidate 1 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:17545, base=10.24.18.124:17545, prio=0x7efffffe (2130706430) [Dec 20 10:41:49] DEBUG[18235] pjsip: icess0x7ff4680 Destroying ICE session 0x7ff4680224a8 [Dec 20 10:41:49] DEBUG[18235] pjsip: stuse0x7ff4680 STUN session 0x7ff46802e5d8 destroy request, ref_cnt=4 [Dec 20 10:41:49] DEBUG[18235] pjsip: stuse0x7ff4680 STUN session 0x7ff46800c238 destroy request, ref_cnt=3 [Dec 20 10:41:49] DEBUG[18235] pjsip: ice_session.c ICE session 0x7ff4680224a8 destroyed [Dec 20 10:41:49] DEBUG[18235] pjsip: stun_session.c STUN session 0x7ff46802e5d8 destroyed [Dec 20 10:41:49] DEBUG[18235] pjsip: stun_session.c STUN session 0x7ff46800c238 destroyed [Dec 20 10:41:49] VERBOSE[18525][C-00000006] app_dial.c: -- Called PJSIP/6002 [Dec 20 10:41:49] DEBUG[18235] pjsip: endpoint Request msg INVITE/cseq=30704 (tdta0x7ff468008280) created. [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 Module NAT added as dialog usage, data=(nil) [Dec 20 10:41:49] DEBUG[18235] pjsip: inv0x7ff468016 .Sending Request msg INVITE/cseq=30704 (tdta0x7ff468008280) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ..Sending Request msg INVITE/cseq=30704 (tdta0x7ff468008280) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 ...Transaction created for Request msg INVITE/cseq=30703 (tdta0x7ff468008280) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 ..Sending Request msg INVITE/cseq=30703 (tdta0x7ff468008280) in state Null [Dec 20 10:41:49] DEBUG[18235] pjsip: sip_resolve.c ...Target '10.24.18.138:5060' type=Unspecified resolved to '10.24.18.138:5060' type=UDP (UDP transport) [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.138' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.138' and port ''. [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:49] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP request (906 bytes) to UDP:10.24.18.138:5060 ---> ˙INVITE sip:6002@10.24.18.138:5060;ob SIP/2.0 ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport;branch=z9hG4bKPj55e7fffe-4f76-4729-a8e2-bf9cb5d01fe1 ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ˙Contact: ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙CSeq: 30703 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: 260 ˙ ˙v=0 ˙o=- 320130341 320130341 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17544 RTP/AVP 0 101 ˙c=IN IP4 10.24.18.124 ˙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 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 ...State changed from Null to Calling, event=TX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ....Transaction tsx0x7ff468010bf8 state changed to Calling [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is CALLING [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Sending request [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current transaction state is Calling [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is CALLING [Dec 20 10:41:49] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=30703 (rdata0x7ff4380032b8) [Dec 20 10:41:49] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP response (347 bytes) from UDP:10.24.18.138:5060 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;received=10.24.18.124;branch=z9hG4bKPj55e7fffe-4f76-4729-a8e2-bf9cb5d01fe1 ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ˙CSeq: 30703 INVITE ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=30703 (rdata0x7ff438006248) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 .Incoming Response msg 100/INVITE/cseq=30703 (rdata0x7ff438006248) in state Calling [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 ..State changed from Calling to Proceeding, event=RX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ...Received Response msg 100/INVITE/cseq=30703 (rdata0x7ff438006248) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ...Transaction tsx0x7ff468010bf8 state changed to Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current transaction state is Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is CALLING [Dec 20 10:41:49] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=30703 (rdata0x7ff4380032b8) [Dec 20 10:41:49] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP response (568 bytes) from UDP:10.24.18.138:5060 ---> ˙SIP/2.0 180 ringing ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;received=10.24.18.124;branch=z9hG4bKPj55e7fffe-4f76-4729-a8e2-bf9cb5d01fe1 ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ;tag=D-vMJD.0B2bMWiRcGCkNdaQyu5vmumJw ˙CSeq: 30703 INVITE ˙Contact: "RustyTWO" ˙Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS ˙User-Agent: Digium D40 1_3_2_0_54993 ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=30703 (rdata0x7ff438006248) [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 .Incoming Response msg 180/INVITE/cseq=30703 (rdata0x7ff438006248) in state Proceeding [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff468010 ..State changed from Proceeding to Proceeding, event=RX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ...Received Response msg 180/INVITE/cseq=30703 (rdata0x7ff438006248) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ....Route-set updated [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468016 ...Transaction tsx0x7ff468010bf8 state changed to Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is EARLY [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Received response [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Response is 180 ringing [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current transaction state is Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is EARLY [Dec 20 10:41:49] VERBOSE[18525][C-00000006] app_dial.c: -- PJSIP/6002-0000000d is ringing [Dec 20 10:41:49] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6002 [Dec 20 10:41:49] DEBUG[18224] devicestate.c: Changing state for PJSIP/6002 - state 6 (Ringing) [Dec 20 10:41:49] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 20 10:41:49] DEBUG[18224] devicestate.c: Changing state for PJSIP/6001 - state 2 (In use) [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6002' [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Adding per-server state of 'Ringing' for 'PJSIP/6002' [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Aggregate devstate result is 'Ringing' for 'PJSIP/6002' [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6002' has changed to 'Ringing' [Dec 20 10:41:49] DEBUG[18235] pjsip: inv0x7ff468004 .Sending Response msg 180/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ..Sending Response msg 180/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6001' [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ..Sending Response msg 180/INVITE/cseq=1344 (tdta0x7ff468015680) in state Proceeding [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/6001' [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/6001' [Dec 20 10:41:49] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6001' has changed to 'In use' [Dec 20 10:41:49] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:49] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:49] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (511 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 180 Ringing ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Contact: ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:49] DEBUG[18235] pjsip: tsx0x7ff46803b ...State changed from Proceeding to Proceeding, event=TX_MSG [Dec 20 10:41:49] DEBUG[18235] pjsip: dlg0x7ff468004 ....Transaction tsx0x7ff46803bb38 state changed to Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is EARLY [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Sending response [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current transaction state is Proceeding [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:41:49] DEBUG[18235] res_pjsip_session.c: The current inv state is EARLY [Dec 20 10:41:49] DEBUG[18284] app_queue.c: Device 'PJSIP/6002' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 20 10:41:49] DEBUG[18284] app_queue.c: Device 'PJSIP/6001' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 20 10:41:51] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=30703 (rdata0x7ff4380032b8) [Dec 20 10:41:51] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP response (963 bytes) from UDP:10.24.18.138:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;received=10.24.18.124;branch=z9hG4bKPj55e7fffe-4f76-4729-a8e2-bf9cb5d01fe1 ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ;tag=D-vMJD.0B2bMWiRcGCkNdaQyu5vmumJw ˙CSeq: 30703 INVITE ˙Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS ˙User-Agent: Digium D40 1_3_2_0_54993 ˙Contact: "RustyTWO" ˙Supported: replaces, 100rel, timer, norefersub ˙Session-Expires: 1800;refresher=uac ˙User-Agent: Digium D40 1_3_2_0_54993 ˙Content-Type: application/sdp ˙Content-Length: 243 ˙ ˙v=0 ˙o=- 82928999 82929000 IN IP4 10.24.18.138 ˙s=digphn ˙c=IN IP4 10.24.18.138 ˙t=0 0 ˙a=X-nat:0 ˙m=audio 4028 RTP/AVP 0 96 ˙a=rtcp:4029 IN IP4 10.24.18.138 ˙a=rtpmap:0 PCMU/8000 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-15 ˙ [Dec 20 10:41:51] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=30703 (rdata0x7ff438007228) [Dec 20 10:41:51] DEBUG[18235] pjsip: tsx0x7ff468010 .Incoming Response msg 200/INVITE/cseq=30703 (rdata0x7ff438007228) in state Proceeding [Dec 20 10:41:51] DEBUG[18235] pjsip: tsx0x7ff468010 ..State changed from Proceeding to Terminated, event=RX_MSG [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468016 ...Received Response msg 200/INVITE/cseq=30703 (rdata0x7ff438007228) [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468016 ....Route-set updated [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468016 ....Route-set frozen [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468016 ...Transaction tsx0x7ff468010bf8 state changed to Terminated [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current inv state is CONNECTING [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Received response [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Response is 200 OK [Dec 20 10:41:51] DEBUG[18235] pjsip: inv0x7ff468016 ....Got SDP answer in Response msg 200/INVITE/cseq=30703 (rdata0x7ff438007228) [Dec 20 10:41:51] DEBUG[18235] pjsip: inv0x7ff468016 ....SDP negotiation done, status=0 [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.138' into... [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.138' and port ''. [Dec 20 10:41:51] DEBUG[18235] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff468035a08' [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Setting payload 0 based on m type on 0x7ff4a008f910 [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Setting payload 101 based on m type on 0x7ff4a008f910 [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Copying payload 0 from 0x7ff4a008f910 to 0x7ff468035b48 [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Copying payload 101 from 0x7ff4a008f910 to 0x7ff468035b48 [Dec 20 10:41:51] VERBOSE[18525][C-00000006] app_dial.c: -- PJSIP/6002-0000000d answered PJSIP/6001-0000000c [Dec 20 10:41:51] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6002 [Dec 20 10:41:51] DEBUG[18224] devicestate.c: Changing state for PJSIP/6002 - state 2 (In use) [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6002' [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/6002' [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/6002' [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6002' has changed to 'In use' [Dec 20 10:41:51] DEBUG[18284] app_queue.c: Device 'PJSIP/6002' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 20 10:41:51] DEBUG[18235] pjsip: inv0x7ff468016 ....Received Response msg 200/INVITE/cseq=30703 (rdata0x7ff438007228), sending ACK [Dec 20 10:41:51] DEBUG[18235] pjsip: endpoint ....Request msg ACK/cseq=30703 (tdta0x7ff46804ea30) created. [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468016 .....Sending Request msg ACK/cseq=30703 (tdta0x7ff46804ea30) [Dec 20 10:41:51] DEBUG[18235] pjsip: sip_resolve.c .....Target '10.24.18.138:5060' type=Unspecified resolved to '10.24.18.138:5060' type=UDP (UDP transport) [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.138' into... [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.138' and port ''. [Dec 20 10:41:51] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP request (377 bytes) to UDP:10.24.18.138:5060 ---> ˙ACK sip:6002@10.24.18.138:5060;ob SIP/2.0 ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport;branch=z9hG4bKPj28baa190-409c-454d-b568-e5bfd4f461bc ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ;tag=D-vMJD.0B2bMWiRcGCkNdaQyu5vmumJw ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙CSeq: 30703 ACK ˙Content-Length: 0 ˙ ˙ [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current inv state is CONFIRMED [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Sending request [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Method is ACK [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff468010bf8) [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current transaction state is Terminated [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current inv state is CONFIRMED [Dec 20 10:41:51] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 20 10:41:51] DEBUG[18525][C-00000006] features.c: Removing dialed interfaces datastore on PJSIP/6002-0000000d since we're bridging [Dec 20 10:41:51] DEBUG[18224] devicestate.c: Changing state for PJSIP/6001 - state 2 (In use) [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6001' [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge_native_rtp.c: Bridge '5552714e-4d81-4ffe-b90d-1601e37e4541' can not use native RTP bridge as two channels are required [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/6001' [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/6001' [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Chose bridge technology simple_bridge [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling simple_bridge technology constructor [Dec 20 10:41:51] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6001' has not changed from 'In use' [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling simple_bridge technology start [Dec 20 10:41:51] DEBUG[18235] pjsip: inv0x7ff468004 .SDP negotiation done, status=0 [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:51] DEBUG[18235] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff46803e138' [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Setting payload 0 based on m type on 0x7ff4a008fb20 [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Setting payload 96 based on m type on 0x7ff4a008fb20 [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b7d8(PJSIP/6001-0000000c) is joining [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Copying payload 0 from 0x7ff4a008fb20 to 0x7ff46803e278 [Dec 20 10:41:51] DEBUG[18235] rtp_engine.c: Copying payload 96 from 0x7ff4a008fb20 to 0x7ff46803e278 [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b488(PJSIP/6002-0000000d) is joining [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: pushing 0x7ff46000b7d8(PJSIP/6001-0000000c) [Dec 20 10:41:51] VERBOSE[18525][C-00000006] bridge_channel.c: -- Channel PJSIP/6001-0000000c joined 'simple_bridge' basic-bridge <5552714e-4d81-4ffe-b90d-1601e37e4541> [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Dec 20 10:41:51] DEBUG[18235] pjsip: inv0x7ff468004 .Sending Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468004 ..Sending Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:41:51] DEBUG[18235] pjsip: tsx0x7ff46803b ..Sending Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680) in state Proceeding [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge_native_rtp.c: Bridge '5552714e-4d81-4ffe-b90d-1601e37e4541' can not use native RTP bridge as two channels are required [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Chose bridge technology simple_bridge [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is already using the new technology. [Dec 20 10:41:51] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:41:51] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6001-0000000c already has read format ulaw [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6001-0000000c already has write format ulaw [Dec 20 10:41:51] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b7d8(PJSIP/6001-0000000c) is joining simple_bridge technology [Dec 20 10:41:51] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:41:51] DEBUG[18235] pjsip: tsx0x7ff46803b ...State changed from Proceeding to Completed, event=TX_MSG [Dec 20 10:41:51] DEBUG[18235] pjsip: dlg0x7ff468004 ....Transaction tsx0x7ff46803bb38 state changed to Completed [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current inv state is CONNECTING [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is TX_MSG [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Sending response [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current transaction state is Completed [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:41:51] DEBUG[18235] res_pjsip_session.c: The current inv state is CONNECTING [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: pushing 0x7ff46000b488(PJSIP/6002-0000000d) [Dec 20 10:41:51] VERBOSE[18526][C-00000006] bridge_channel.c: -- Channel PJSIP/6002-0000000d joined 'simple_bridge' basic-bridge <5552714e-4d81-4ffe-b90d-1601e37e4541> [Dec 20 10:41:51] DEBUG[18223] cdr.c: Finalized CDR for PJSIP/6002-0000000d - start 1387557709.020117 answer 1387557711.280917 end 1387557711.283047 dispo ANSWERED [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge technology softmix does not have any capabilities we want. [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Chose bridge technology native_rtp [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling native_rtp technology constructor [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling simple_bridge technology stop [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b7d8(PJSIP/6001-0000000c) is leaving simple_bridge technology (dummy) [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6001-0000000c already has read format ulaw [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6001-0000000c already has write format ulaw [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b7d8(PJSIP/6001-0000000c) is joining native_rtp technology [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/6001-0000000c' and 'PJSIP/6002-0000000d' in stack [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6002-0000000d already has read format ulaw [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is happy that channel PJSIP/6002-0000000d already has write format ulaw [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b488(PJSIP/6002-0000000d) is joining native_rtp technology [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/6001-0000000c' and 'PJSIP/6002-0000000d' in stack [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling native_rtp technology start [Dec 20 10:41:51] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling simple_bridge technology destructor [Dec 20 10:41:51] DEBUG[18526][C-00000006] res_rtp_asterisk.c: 0x7ff468052100 -- Probation learning mode pass with source address 10.24.18.138:4028 [Dec 20 10:41:51] DEBUG[18234] pjsip: tsx0x7ff468010 Timeout timer event [Dec 20 10:41:51] DEBUG[18234] pjsip: tsx0x7ff468010 .State changed from Terminated to Destroyed, event=TIMER [Dec 20 10:41:51] DEBUG[18234] pjsip: tsx0x7ff468010 Transaction destroyed! [Dec 20 10:41:51] DEBUG[18525][C-00000006] res_rtp_asterisk.c: 0x7ff468012780 -- Probation learning mode pass with source address 10.24.18.16:4010 [Dec 20 10:41:51] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:41:51] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=0, restart?=1 [Dec 20 10:41:51] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:51] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:51] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:41:52] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:41:52] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=1, restart?=1 [Dec 20 10:41:52] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:52] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:52] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:41:53] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:41:54] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:41:54] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:41:54] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=2, restart?=1 [Dec 20 10:41:54] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:54] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:54] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:41:58] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:41:58] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=3, restart?=1 [Dec 20 10:41:58] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:41:58] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:41:58] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:41:58] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:41:59] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:02] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:02] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=4, restart?=1 [Dec 20 10:42:02] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:02] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:02] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:03] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:04] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:06] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:06] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=5, restart?=1 [Dec 20 10:42:06] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:06] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:06] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:08] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:09] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:10] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:10] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=6, restart?=1 [Dec 20 10:42:10] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:10] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:10] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:13] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:14] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:14] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:14] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=7, restart?=1 [Dec 20 10:42:14] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:14] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:14] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:18] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:18] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=8, restart?=1 [Dec 20 10:42:18] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:18] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:18] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:18] DEBUG[18526][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:19] DEBUG[18525][C-00000006] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 20 10:42:22] DEBUG[18234] pjsip: tsx0x7ff46803b Retransmit timer event [Dec 20 10:42:22] DEBUG[18234] pjsip: tsx0x7ff46803b .Retransmiting Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680), count=9, restart?=1 [Dec 20 10:42:22] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:22] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:22] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP response (843 bytes) to UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.16:5060;rport;received=10.24.18.16;branch=z9hG4bKPjzmhp3OGW.gQwt47bR4MUdpBIt9zPWmEb ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙To: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙CSeq: 1344 INVITE ˙Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER, REGISTER ˙Contact: ˙Supported: 100rel, timer, replaces, norefersub ˙Content-Type: application/sdp ˙Content-Length: 255 ˙ ˙v=0 ˙o=- 82928999 82929001 IN IP4 newtonr-laptop ˙s=Asterisk ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 17796 RTP/AVP 0 96 ˙c=IN IP4 10.24.18.124 ˙a=rtpmap:0 PCMU/8000 ˙a=ptime:20 ˙a=maxptime:150 ˙a=sendrecv ˙a=rtpmap:96 telephone-event/8000 ˙a=fmtp:96 0-16 ˙ [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff46803b Timeout timer event [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff46803b .State changed from Completed to Terminated, event=TIMER [Dec 20 10:42:23] DEBUG[18234] pjsip: dlg0x7ff468004 ..Transaction tsx0x7ff46803bb38 state changed to Terminated [Dec 20 10:42:23] DEBUG[18234] pjsip: endpoint ...Request msg BYE/cseq=21747 (tdta0x7ff438000e30) created. [Dec 20 10:42:23] DEBUG[18234] pjsip: inv0x7ff468004 ....Sending Request msg BYE/cseq=21747 (tdta0x7ff438000e30) [Dec 20 10:42:23] DEBUG[18234] pjsip: dlg0x7ff468004 .....Sending Request msg BYE/cseq=21747 (tdta0x7ff438000e30) [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff468010 ......Transaction created for Request msg BYE/cseq=21746 (tdta0x7ff438000e30) [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff468010 .....Sending Request msg BYE/cseq=21746 (tdta0x7ff438000e30) in state Null [Dec 20 10:42:23] DEBUG[18234] pjsip: sip_resolve.c ......Target '10.24.18.16:5060' type=Unspecified resolved to '10.24.18.16:5060' type=UDP (UDP transport) [Dec 20 10:42:23] DEBUG[18234] netsock2.c: Splitting '10.24.18.16' into... [Dec 20 10:42:23] DEBUG[18234] netsock2.c: ...host '10.24.18.16' and port ''. [Dec 20 10:42:23] VERBOSE[18234] res_pjsip_logger.c: <--- Transmitting SIP request (369 bytes) to UDP:10.24.18.16:5060 ---> ˙BYE sip:6001@10.24.18.16:5060;ob SIP/2.0 ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport;branch=z9hG4bKPjeb31bd8b-a981-4a73-a8a9-75c8c769882e ˙From: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙To: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙CSeq: 21746 BYE ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff468010 ......State changed from Null to Calling, event=TX_MSG [Dec 20 10:42:23] DEBUG[18234] pjsip: dlg0x7ff468004 .......Transaction tsx0x7ff468010bf8 state changed to Calling [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The current transaction state is Calling [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The current inv state is CONNECTING [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff46803bb38) [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The current transaction state is Terminated [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The transaction state change event is TIMER [Dec 20 10:42:23] DEBUG[18234] res_pjsip_session.c: The current inv state is CONNECTING [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff46803b Timeout timer event [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff46803b .State changed from Terminated to Destroyed, event=TIMER [Dec 20 10:42:23] DEBUG[18234] pjsip: tdta0x7ff46801 ..Destroying txdata Response msg 200/INVITE/cseq=1344 (tdta0x7ff468015680) [Dec 20 10:42:23] DEBUG[18234] pjsip: tsx0x7ff46803b Transaction destroyed! [Dec 20 10:42:23] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=21746 (rdata0x7ff4380032b8) [Dec 20 10:42:23] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP response (370 bytes) from UDP:10.24.18.16:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;received=10.24.18.124;branch=z9hG4bKPjeb31bd8b-a981-4a73-a8a9-75c8c769882e ˙Call-ID: 9Jth2UebTmyrQIHZJSRy3DuL45jfpw7Z ˙From: ;tag=2495162e-79aa-40cd-a5ef-232fda6a3e9d ˙To: "RustyONE" ;tag=eGZ7xdHNUhvbeUMGdtSXvmsnqJAYdemn ˙CSeq: 21746 BYE ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:23] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=21746 (rdata0x7ff438008958) [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff468010 .Incoming Response msg 200/BYE/cseq=21746 (rdata0x7ff438008958) in state Calling [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff468010 ..State changed from Calling to Completed, event=RX_MSG [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468004 ...Received Response msg 200/BYE/cseq=21746 (rdata0x7ff438008958) [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468004 ...Transaction tsx0x7ff468010bf8 state changed to Completed [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6001 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Received response [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Response is 200 OK [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468004 .....Session count dec to 2 by mod-invite [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: inv_session 0x7ff468011fb8 has no ast session [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge_channel.c: Setting 0x7ff46000b7d8(PJSIP/6001-0000000c) state from:0 to:1 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current transaction state is Completed [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: pulling 0x7ff46000b7d8(PJSIP/6001-0000000c) [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:23] VERBOSE[18525][C-00000006] bridge_channel.c: -- Channel PJSIP/6001-0000000c left 'native_rtp' basic-bridge <5552714e-4d81-4ffe-b90d-1601e37e4541> [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b7d8(PJSIP/6001-0000000c) is leaving native_rtp technology [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/6001-0000000c' and 'PJSIP/6002-0000000d' - media will flow through Asterisk core [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: dissolving bridge with cause 16(Normal Clearing) [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge_channel.c: Setting 0x7ff46000b488(PJSIP/6002-0000000d) state from:0 to:2 [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: queueing action type:13 sub:1001 [Dec 20 10:42:23] DEBUG[18223] cdr.c: Finalized CDR for PJSIP/6001-0000000c - start 1387557709.018399 answer 1387557711.281759 end 1387557743.286908 dispo ANSWERED [Dec 20 10:42:23] DEBUG[18525][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is dissolved, not performing smart bridge operation. [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: pulling 0x7ff46000b488(PJSIP/6002-0000000d) [Dec 20 10:42:23] VERBOSE[18526][C-00000006] bridge_channel.c: -- Channel PJSIP/6002-0000000d left 'native_rtp' basic-bridge <5552714e-4d81-4ffe-b90d-1601e37e4541> [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge_channel.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: 0x7ff46000b488(PJSIP/6002-0000000d) is leaving native_rtp technology [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541 is dissolved, not performing smart bridge operation. [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: actually destroying basic bridge, nobody wants it anymore [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling basic bridge destructor [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling native_rtp technology stop [Dec 20 10:42:23] DEBUG[18526][C-00000006] bridge.c: Bridge 5552714e-4d81-4ffe-b90d-1601e37e4541: calling native_rtp technology destructor [Dec 20 10:42:23] DEBUG[18526][C-00000006] channel.c: Hanging up channel 'PJSIP/6002-0000000d' [Dec 20 10:42:23] DEBUG[18525][C-00000006] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Dec 20 10:42:23] DEBUG[18526][C-00000006] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Dec 20 10:42:23] DEBUG[18525][C-00000006] pbx.c: Spawn extension (from-internal,6002,1) exited non-zero on 'PJSIP/6001-0000000c' [Dec 20 10:42:23] VERBOSE[18525][C-00000006] pbx.c: == Spawn extension (from-internal, 6002, 1) exited non-zero on 'PJSIP/6001-0000000c' [Dec 20 10:42:23] DEBUG[18525][C-00000006] channel.c: Soft-Hanging up channel 'PJSIP/6001-0000000c' [Dec 20 10:42:23] DEBUG[18235] pjsip: endpoint .Request msg BYE/cseq=30705 (tdta0x7ff468015680) created. [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Method is BYE [Dec 20 10:42:23] DEBUG[18235] pjsip: inv0x7ff468016 .Sending Request msg BYE/cseq=30705 (tdta0x7ff468015680) [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 ..Sending Request msg BYE/cseq=30705 (tdta0x7ff468015680) [Dec 20 10:42:23] DEBUG[18525][C-00000006] channel.c: Hanging up channel 'PJSIP/6001-0000000c' [Dec 20 10:42:23] DEBUG[18525][C-00000006] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Dec 20 10:42:23] DEBUG[18236] res_pjsip_session.c: Destroying SIP session with endpoint 6001 [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff46803b ...Transaction created for Request msg BYE/cseq=30704 (tdta0x7ff468015680) [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff46803b ..Sending Request msg BYE/cseq=30704 (tdta0x7ff468015680) in state Null [Dec 20 10:42:23] DEBUG[18236] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff46803e138' [Dec 20 10:42:23] DEBUG[18235] pjsip: sip_resolve.c ...Target '10.24.18.138:5060' type=Unspecified resolved to '10.24.18.138:5060' type=UDP (UDP transport) [Dec 20 10:42:23] DEBUG[18236] rtp_engine.c: Destroyed RTP instance '0x7ff46803e138' [Dec 20 10:42:23] DEBUG[18235] netsock2.c: Splitting '10.24.18.138' into... [Dec 20 10:42:23] DEBUG[18235] netsock2.c: ...host '10.24.18.138' and port ''. [Dec 20 10:42:23] DEBUG[18236] pjsip: dlg0x7ff468004 .Session count dec to 0 by Session Module [Dec 20 10:42:23] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP request (401 bytes) to UDP:10.24.18.138:5060 ---> ˙BYE sip:6002@10.24.18.138:5060;ob SIP/2.0 ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport;branch=z9hG4bKPj0b5fda2a-23fc-4dda-960c-5b5e3535a9ef ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ;tag=D-vMJD.0B2bMWiRcGCkNdaQyu5vmumJw ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙CSeq: 30704 BYE ˙Reason: Q.850;cause=16 ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff46803b ...State changed from Null to Calling, event=TX_MSG [Dec 20 10:42:23] DEBUG[18236] taskprocessor.c: destroying taskprocessor '15cf43cc-8172-4a88-8a19-a0d9860743b0' [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 ....Transaction tsx0x7ff46803bb38 state changed to Calling [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current transaction state is Calling [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction state change event is TX_MSG [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current inv state is CONFIRMED [Dec 20 10:42:23] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6001 [Dec 20 10:42:23] DEBUG[18224] devicestate.c: Changing state for PJSIP/6001 - state 1 (Not in use) [Dec 20 10:42:23] DEBUG[18224] devicestate.c: No provider found, checking channel drivers for PJSIP - 6002 [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6001' [Dec 20 10:42:23] DEBUG[18224] devicestate.c: Changing state for PJSIP/6002 - state 1 (Not in use) [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Adding per-server state of 'Not in use' for 'PJSIP/6001' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Aggregate devstate result is 'Not in use' for 'PJSIP/6001' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6001' has changed to 'Not in use' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Processing device state change for 'PJSIP/6002' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Adding per-server state of 'Not in use' for 'PJSIP/6002' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Aggregate devstate result is 'Not in use' for 'PJSIP/6002' [Dec 20 10:42:23] DEBUG[18219] devicestate.c: Aggregate state for device 'PJSIP/6002' has changed to 'Not in use' [Dec 20 10:42:23] DEBUG[18284] 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 20 10:42:23] DEBUG[18284] app_queue.c: Device 'PJSIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 20 10:42:23] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=30704 (rdata0x7ff4380032b8) [Dec 20 10:42:23] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP response (377 bytes) from UDP:10.24.18.138:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 173.17.135.67:5060;rport=5060;received=10.24.18.124;branch=z9hG4bKPj0b5fda2a-23fc-4dda-960c-5b5e3535a9ef ˙Call-ID: afefba4a-d606-487b-9ab1-8e4f0fd1474c ˙From: "RustyONE" ;tag=d4dce353-8340-4357-93ed-08493fe69bd2 ˙To: ;tag=D-vMJD.0B2bMWiRcGCkNdaQyu5vmumJw ˙CSeq: 30704 BYE ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:23] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=30704 (rdata0x7ff438008958) [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff46803b .Incoming Response msg 200/BYE/cseq=30704 (rdata0x7ff438008958) in state Calling [Dec 20 10:42:23] DEBUG[18235] pjsip: tsx0x7ff46803b ..State changed from Calling to Completed, event=RX_MSG [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 ...Received Response msg 200/BYE/cseq=30704 (rdata0x7ff438008958) [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 ...Transaction tsx0x7ff46803bb38 state changed to Completed [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The state change pertains to the session with 6002 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: There is no transaction involved in this state change [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Source of transaction state change is RX_MSG [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Received response [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Response is 200 OK [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Destroying SIP session with endpoint 6002 [Dec 20 10:42:23] DEBUG[18235] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff468035a08' [Dec 20 10:42:23] DEBUG[18235] rtp_engine.c: Destroyed RTP instance '0x7ff468035a08' [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 .....Session count dec to 2 by Session Module [Dec 20 10:42:23] DEBUG[18235] pjsip: tdta0x7ff46804 ....Destroying txdata Request msg ACK/cseq=30703 (tdta0x7ff46804ea30) [Dec 20 10:42:23] DEBUG[18235] pjsip: tdta0x7ff46800 ....Destroying txdata Request msg INVITE/cseq=30703 (tdta0x7ff468008280) [Dec 20 10:42:23] DEBUG[18235] pjsip: dlg0x7ff468016 .....Session count dec to 1 by mod-invite [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: inv_session 0x7ff46802b308 has no ast session [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current transaction state is Completed [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The transaction state change event is RX_MSG [Dec 20 10:42:23] DEBUG[18235] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:23] DEBUG[18235] taskprocessor.c: destroying taskprocessor '9a0ac03f-f874-4830-bc26-e8df8d9beb12' [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff468010 Timeout timer event [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff468010 .State changed from Completed to Terminated, event=TIMER [Dec 20 10:42:28] DEBUG[18234] pjsip: dlg0x7ff468004 ..Transaction tsx0x7ff468010bf8 state changed to Terminated [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: inv_session 0x7ff468011fb8 has no ast session [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The transaction involved in this state change is 0x7ff468010bf8 [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The current transaction state is Terminated [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The transaction state change event is TIMER [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:28] DEBUG[18234] pjsip: dlg0x7ff468004 ...Dialog destroyed [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff468010 Timeout timer event [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff468010 .State changed from Terminated to Destroyed, event=TIMER [Dec 20 10:42:28] DEBUG[18234] pjsip: tdta0x7ff43800 ..Destroying txdata Request msg BYE/cseq=21746 (tdta0x7ff438000e30) [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff468010 Transaction destroyed! [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff46803b Timeout timer event [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff46803b .State changed from Completed to Terminated, event=TIMER [Dec 20 10:42:28] DEBUG[18234] pjsip: dlg0x7ff468016 ..Transaction tsx0x7ff46803bb38 state changed to Terminated [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: inv_session 0x7ff46802b308 has no ast session [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The transaction involved in this state change is 0x7ff46803bb38 [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The current transaction state is Terminated [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The transaction state change event is TIMER [Dec 20 10:42:28] DEBUG[18234] res_pjsip_session.c: The current inv state is DISCONNCTD [Dec 20 10:42:28] DEBUG[18234] pjsip: dlg0x7ff468016 ...Dialog destroyed [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff46803b Timeout timer event [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff46803b .State changed from Terminated to Destroyed, event=TIMER [Dec 20 10:42:28] DEBUG[18234] pjsip: tdta0x7ff46801 ..Destroying txdata Request msg BYE/cseq=30704 (tdta0x7ff468015680) [Dec 20 10:42:28] DEBUG[18234] pjsip: tsx0x7ff46803b Transaction destroyed! [Dec 20 10:42:28] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=41 (rdata0x7ff4380032b8) [Dec 20 10:42:28] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP request (412 bytes) from UDP:10.24.18.166:5060 ---> ˙REGISTER sip:10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/UDP 10.24.18.166:5060;branch=z9hG4bK2006363921386127052;rport ˙From: 6004 ;tag=90986116 ˙To: 6004 ˙Call-ID: 28096309906454-24342940423932@10.24.18.166 ˙CSeq: 41 REGISTER ˙Contact: ˙Max-Forwards: 70 ˙Expires: 60 ˙Supported: path ˙User-Agent: Voip Phone 1.0 ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:28] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=41 (rdata0x7ff438006248) [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: Source address 10.24.18.166:5060 does not match identify 'mytrunk_identify' [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: '10.24.18.166:5060' did not match any identify section rules [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6004 [Dec 20 10:42:28] DEBUG[18235] pjsip: endpoint .Response msg 401/REGISTER/cseq=41 (tdta0x7ff438000e30) created [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (483 bytes) to UDP:10.24.18.166:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/UDP 10.24.18.166:5060;rport;received=10.24.18.166;branch=z9hG4bK2006363921386127052 ˙Call-ID: 28096309906454-24342940423932@10.24.18.166 ˙From: "6004" ;tag=90986116 ˙To: "6004" ;tag=z9hG4bK2006363921386127052 ˙CSeq: 41 REGISTER ˙WWW-Authenticate: Digest realm="asterisk",nonce="1387557748/0948604d9af893bad36bfb5713bd6d7d",opaque="411a71011b71ed36",algorithm=md5,qop="auth" ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:28] DEBUG[18235] pjsip: tdta0x7ff43800 .Destroying txdata Response msg 401/REGISTER/cseq=41 (tdta0x7ff438000e30) [Dec 20 10:42:28] DEBUG[18234] pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=42 (rdata0x7ff4380032b8) [Dec 20 10:42:28] VERBOSE[18234] res_pjsip_logger.c: <--- Received SIP request (675 bytes) from UDP:10.24.18.166:5060 ---> ˙REGISTER sip:10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/UDP 10.24.18.166:5060;branch=z9hG4bK1082312116332710133;rport ˙From: 6004 ;tag=90986116 ˙To: 6004 ˙Call-ID: 28096309906454-24342940423932@10.24.18.166 ˙CSeq: 42 REGISTER ˙Contact: ˙Authorization: Digest username="6004", realm="asterisk", nonce="1387557748/0948604d9af893bad36bfb5713bd6d7d", uri="sip:10.24.18.124", response="6b04967bc7bad16befefc1a40851abd0", algorithm=MD5, cnonce="ebcb82d2", opaque="411a71011b71ed36", qop=auth, nc=00000001 ˙Max-Forwards: 70 ˙Expires: 60 ˙Supported: path ˙User-Agent: Voip Phone 1.0 ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:28] DEBUG[18235] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=42 (rdata0x7ff438007228) [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: Source address 10.24.18.166:5060 does not match identify 'mytrunk_identify' [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_ip.c: '10.24.18.166:5060' did not match any identify section rules [Dec 20 10:42:28] DEBUG[18235] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 6004 [Dec 20 10:42:28] DEBUG[18235] pjsip: endpoint .Response msg 401/REGISTER/cseq=42 (tdta0x7ff438000e30) created [Dec 20 10:42:28] DEBUG[18235] res_pjsip_authenticator_digest.c: Calculated nonce 1387557748/0948604d9af893bad36bfb5713bd6d7d. Actual nonce is 1387557748/0948604d9af893bad36bfb5713bd6d7d [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.124' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.124' and port ''. [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] DEBUG[18235] pjsip: tdta0x7ff43800 .Destroying txdata Response msg 401/REGISTER/cseq=42 (tdta0x7ff438000e30) [Dec 20 10:42:28] DEBUG[18235] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 20 10:42:28] DEBUG[18235] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 20 10:42:28] DEBUG[18235] res_pjsip_registrar.c: Refreshed contact 'sip:6004@10.24.18.166:5060' on AOR '6004' with new expiration of 60 seconds [Dec 20 10:42:28] DEBUG[18235] config.c: extract int from [0] in [0, 86400] gives [0](0) [Dec 20 10:42:28] DEBUG[18235] pjsip: endpoint Response msg 200/REGISTER/cseq=42 (tdta0x7ff468015680) created [Dec 20 10:42:28] DEBUG[18235] netsock2.c: Splitting '10.24.18.166' into... [Dec 20 10:42:28] DEBUG[18235] netsock2.c: ...host '10.24.18.166' and port ''. [Dec 20 10:42:28] VERBOSE[18235] res_pjsip_logger.c: <--- Transmitting SIP response (414 bytes) to UDP:10.24.18.166:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/UDP 10.24.18.166:5060;rport;received=10.24.18.166;branch=z9hG4bK1082312116332710133 ˙Call-ID: 28096309906454-24342940423932@10.24.18.166 ˙From: "6004" ;tag=90986116 ˙To: "6004" ;tag=z9hG4bK1082312116332710133 ˙CSeq: 42 REGISTER ˙Date: Fri, 20 Dec 2013 16:42:28 GMT ˙Contact: ;expires=59 ˙Content-Length: 0 ˙ ˙ [Dec 20 10:42:28] DEBUG[18235] pjsip: tdta0x7ff46801 Destroying txdata Response msg 200/REGISTER/cseq=42 (tdta0x7ff468015680) [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Dec 20 10:42:35] VERBOSE[18287] asterisk.c: Asterisk cleanly ending (0). [Dec 20 10:42:35] VERBOSE[18287] asterisk.c: Executing last minute cleanups [Dec 20 10:42:35] VERBOSE[18287] res_musiconhold.c: == Destroying musiconhold processes [Dec 20 10:42:35] DEBUG[18287] res_musiconhold.c: Destroying MOH class 'default' [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'caf96c47-221b-4662-844f-e3f108a8e435' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'CallCompletionCancel' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'CallCompletionRequest' [Dec 20 10:42:35] DEBUG[18287] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'CCSS core' [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'a09feb39-f1ea-4df7-b178-fb56a3018829' [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeList [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeInfo [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeDestroy [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeKick [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Ping [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Events [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Logoff [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Login [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Challenge [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Hangup [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Status [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Setvar [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Getvar [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action GetConfig [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action GetConfigJSON [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action UpdateConfig [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action CreateConfig [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ListCategories [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Redirect [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Atxfer [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Originate [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Command [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ExtensionState [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action PresenceState [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action AbsoluteTimeout [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action MailboxStatus [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action MailboxCount [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ListCommands [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action SendText [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action UserEvent [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action WaitEvent [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action CoreSettings [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action CoreStatus [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Reload [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action CoreShowChannels [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ModuleLoad [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ModuleCheck [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action AOCMessage [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Filter [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BlindTransfer [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function AMI_CLIENT [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'c676e9c0-14e1-4681-bdf3-8d25723c20bf' [Dec 20 10:42:35] DEBUG[18287] tcptls.c: Stopped server :: AMI server [Dec 20 10:42:35] DEBUG[18287] tcptls.c: Stopped server :: AMI TLS server [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action LocalOptimizeAway [Dec 20 10:42:35] DEBUG[18287] channel.c: Unregistering channel type 'Local' [Dec 20 10:42:35] VERBOSE[18287] channel.c: == Unregistered channel type 'Local' [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor '28f3c7e1-cce8-4a4e-ab7c-482ed996003e' [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor '4b9307ca-bc3d-4a20-a9c0-2d39d1225ab6' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Answer' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'BackGround' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Busy' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Congestion' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'ExecIfTime' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Goto' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'GotoIf' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'GotoIfTime' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'ImportVar' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Hangup' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Incomplete' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'NoOp' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Proceeding' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Progress' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'RaiseException' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Ringing' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SayAlpha' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SayAlphaCase' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SayDigits' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SayNumber' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SayPhonetic' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Set' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'MSet' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'SetAMAFlags' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Wait' [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'WaitExten' [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action ShowDialPlan [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function EXCEPTION [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function TESTTIME [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeTechnologyList [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeTechnologySuspend [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action BridgeTechnologyUnsuspend [Dec 20 10:42:35] DEBUG[18287] bridge.c: Waiting for bridge manager thread to die. [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function FEATUREMAP [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function FEATURE [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action Bridge [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'Bridge' [Dec 20 10:42:35] DEBUG[18287] tcptls.c: Stopped server :: http server [Dec 20 10:42:35] DEBUG[18287] channel.c: Unregistering channel type 'Surrogate' [Dec 20 10:42:35] VERBOSE[18287] channel.c: == Unregistered channel type 'Surrogate' [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action DataGet [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function MESSAGE [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered custom function MESSAGE_DATA [Dec 20 10:42:35] VERBOSE[18287] pbx.c: == Unregistered application 'MessageSend' [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action MessageSend [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action DBGet [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action DBPut [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action DBDel [Dec 20 10:42:35] VERBOSE[18287] manager.c: == Manager unregistered action DBDelTree [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Dec 20 10:42:35] DEBUG[18287] threadpool.c: Destroying worker thread 5 [Dec 20 10:42:35] DEBUG[18287] taskprocessor.c: destroying taskprocessor 'Sorcery' [Dec 20 10:42:35] DEBUG[18287] asterisk.c: Asterisk ending (0).