*CLI> channel originate sip/bob/test application echo [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:29649 sip_request_call: Asked to create a SIP channel with formats: (slin) [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8936 sip_alloc: Allocating new SIP dialog for 2bb83ced4bd828470745aa3f34a9ee06@127.0.1.1:5060 - INVITE (No RTP) [Oct 1 11:52:24] DEBUG[24518]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x2f0d7c8' [Oct 1 11:52:24] DEBUG[24518]: res_rtp_asterisk.c:1771 ast_rtp_new: Allocated port 12678 for RTP instance '0x2f0d7c8' [Oct 1 11:52:24] DEBUG[24518]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x2f0d7c8' is setup and ready to go [Oct 1 11:52:24] DEBUG[24518]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x2f03578' [Oct 1 11:52:24] DEBUG[24518]: res_rtp_asterisk.c:1771 ast_rtp_new: Allocated port 16930 for RTP instance '0x2f03578' [Oct 1 11:52:24] DEBUG[24518]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x2f03578' is setup and ready to go [Oct 1 11:52:24] DEBUG[24518]: res_rtp_asterisk.c:3961 ast_rtp_prop_set: Setup RTCP on RTP instance '0x2f03578' == Using SIP VIDEO CoS mark 6 [Oct 1 11:52:24] DEBUG[24518]: res_rtp_asterisk.c:3961 ast_rtp_prop_set: Setup RTCP on RTP instance '0x2f0d7c8' == Using SIP RTP CoS mark 5 [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:5854 do_setnat: Setting NAT on RTP to Off [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:5858 do_setnat: Setting NAT on VRTP to Off [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:3734 obproxy_get: OBPROXY: Not applying OBproxy to this call [Oct 1 11:52:24] DEBUG[24518]: acl.c:979 ast_ouraddrfor: For destination '10.24.20.81', our source address is '10.24.20.65'. [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:4124 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:5854 do_setnat: Setting NAT on RTP to Off [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:5858 do_setnat: Setting NAT on VRTP to Off [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8731 change_callid_pvt: SIP call-id changed from '2bb83ced4bd828470745aa3f34a9ee06@127.0.1.1:5060' to '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' [Oct 1 11:52:24] DEBUG[24518]: format_pref.c:339 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8124 sip_new: *** Our native formats are (ulaw|h263) [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8125 sip_new: *** Joint capabilities are (nothing) [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8126 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8127 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8129 sip_new: *** Our preferred formats from the incoming channel are (slin) [Oct 1 11:52:24] DEBUG[24518]: chan_sip.c:8153 sip_new: This channel can handle video! HOLLYWOOD next! *CLI> [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:6490 sip_call: Outgoing Call for test [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:6811 update_call_counter: Updating call counter for outgoing call [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:13210 add_sdp: This call needs video offers! [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:13260 add_sdp: ** Our capability: (gsm|ulaw|alaw|h263|testlaw) Video flag: False Text flag: False [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:13261 add_sdp: ** Our prefcodec: (slin) Audio is at 12678 Video is at 10.24.20.65:16930 Adding codec 100002 (gsm) to SDP Adding codec 100003 (ulaw) to SDP Adding codec 100004 (alaw) to SDP Adding codec 100017 (testlaw) to SDP Adding video codec 200002 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:13405 add_sdp: -- Done with adding codecs to SDP [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:13607 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|alaw|h263|testlaw) [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:3610 initialize_initreq: Initializing initreq for method INVITE - callid 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 0 [ 40]: INVITE sip:test@10.24.20.81:5062 SIP/2.0 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 1 [ 56]: Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK59c78874 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 4 [ 31]: To: [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 5 [ 35]: Contact: [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 6 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 8 [ 46]: User-Agent: Asterisk PBX SVN-branch-12-r400217 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 9 [ 35]: Date: Tue, 01 Oct 2013 16:52:24 GMT [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 11 [ 26]: Supported: replaces, timer [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:9798 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (no NAT) to 10.24.20.81:5062: INVITE sip:test@10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK59c78874 Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: Contact: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-12-r400217 Date: Tue, 01 Oct 2013 16:52:24 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 414 v=0 o=root 1540045244 1540045244 IN IP4 10.24.20.65 s=Asterisk PBX SVN-branch-12-r400217 c=IN IP4 10.24.20.65 b=CT:384 t=0 0 m=audio 12678 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 16930 RTP/AVP 34 a=rtpmap:34 H263/90000 a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 a=sendrecv --- [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:4427 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #56 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:3967 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.24.20.81:5062 -- Called bob/test <--- SIP read from UDP:10.24.20.81:5062 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK59c78874 Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 From: "Anonymous" ;tag=as00109e7a To: ;tag=z9hG4bK59c78874 CSeq: 102 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1380646344/b45f2febba67bf86487285faa5e85753",opaque="75909b8a6450269d",algorithm=md5,qop="auth" Content-Length: 0 <-------------> [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 1 [ 83]: Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK59c78874 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 2 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 4 [ 46]: To: ;tag=z9hG4bK59c78874 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 6 [144]: WWW-Authenticate: Digest realm="asterisk",nonce="1380646344/b45f2febba67bf86487285faa5e85753",opaque="75909b8a6450269d",algorithm=md5,qop="auth" [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9348 find_call: = Looking for Call ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 (Checking To) --From tag as00109e7a --To-tag z9hG4bK59c78874 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4621 __sip_ack: Acked pending invite 102 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4626 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #56 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4659 __sip_ack: Stopping retransmission on '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' of Request 102: Match Found [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:23033 handle_response_invite: SIP response 401 to standard invite Transmitting (no NAT) to 10.24.20.81:5062: ACK sip:test@10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK59c78874 Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: ;tag=z9hG4bK59c78874 Contact: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-branch-12-r400217 Content-Length: 0 --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:3967 __sip_xmit: Trying to put 'ACK sip:tes' onto UDP socket destined for 10.24.20.81:5062 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:22149 do_proxy_auth: Auth attempt 1 on INVITE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:13210 add_sdp: This call needs video offers! [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:13260 add_sdp: ** Our capability: (gsm|ulaw|alaw|h263|testlaw) Video flag: False Text flag: False [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:13261 add_sdp: ** Our prefcodec: (slin) Audio is at 12678 Video is at 10.24.20.65:16930 Adding codec 100002 (gsm) to SDP Adding codec 100003 (ulaw) to SDP Adding codec 100004 (alaw) to SDP Adding codec 100017 (testlaw) to SDP Adding video codec 200002 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:13405 add_sdp: -- Done with adding codecs to SDP [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:13607 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw|alaw|h263|testlaw) Reliably Transmitting (no NAT) to 10.24.20.81:5062: INVITE sip:test@10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK4c80e456 Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: Contact: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-branch-12-r400217 Authorization: Digest username="bob", realm="asterisk", algorithm=MD5, uri="sip:test@10.24.20.81:5062", nonce="1380646344/b45f2febba67bf86487285faa5e85753", response="fe96ef18ea0cb015ce8a0ce5e21f6b72", opaque="75909b8a6450269d", qop=auth, cnonce="200a76ee", nc=00000001 Date: Tue, 01 Oct 2013 16:52:24 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 414 v=0 o=root 1540045244 1540045245 IN IP4 10.24.20.65 s=Asterisk PBX SVN-branch-12-r400217 c=IN IP4 10.24.20.65 b=CT:384 t=0 0 m=audio 12678 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv m=video 16930 RTP/AVP 34 a=rtpmap:34 H263/90000 a=fmtp:34 F=0;I=0;J=0;T=0;K=0;N=0;BPP=0;HRD=0 a=sendrecv --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4427 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #58 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:3967 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.24.20.81:5062 <--- SIP read from UDP:10.24.20.81:5062 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK4c80e456 Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 From: "Anonymous" ;tag=as00109e7a To: CSeq: 103 INVITE Content-Length: 0 <-------------> [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 1 [ 83]: Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK4c80e456 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 2 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 4 [ 26]: To: [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 6 [ 17]: Content-Length: 0 --- (7 headers 0 lines) --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9348 find_call: = Looking for Call ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 (Checking To) --From tag as00109e7a --To-tag [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4693 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #58 - INVITE (got response) [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4700 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' Request 103: Found [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:23033 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP:10.24.20.81:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK4c80e456 Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d CSeq: 103 INVITE Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, REGISTER, MESSAGE Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 157 v=0 o=- 1540045244 1540045247 IN IP4 veighln s=Asterisk t=0 0 m=audio 0 RTP/AVP 3 0 8 101 c=IN IP4 127.0.0.1 m=video 0 RTP/AVP 34 c=IN IP4 127.0.0.1 <-------------> [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 1 [ 83]: Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK4c80e456 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 2 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 4 [ 67]: To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 6 [ 31]: Contact: [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 7 [109]: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, REGISTER, MESSAGE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 8 [ 46]: Supported: 100rel, timer, replaces, norefersub [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 10 [ 19]: Content-Length: 157 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 11 [ 0]: [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 0 [ 3]: v=0 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 1 [ 40]: o=- 1540045244 1540045247 IN IP4 veighln [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 2 [ 10]: s=Asterisk [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 3 [ 5]: t=0 0 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 4 [ 27]: m=audio 0 RTP/AVP 3 0 8 101 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 5 [ 18]: c=IN IP4 127.0.0.1 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Body 6 [ 20]: m=video 0 RTP/AVP 34 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9835 parse_request: Body 7 [ 18]: c=IN IP4 127.0.0.1 --- (11 headers 8 lines) --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9348 find_call: = Looking for Call ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 (Checking To) --From tag as00109e7a --To-tag eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4621 __sip_ack: Acked pending invite 103 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4659 __sip_ack: Stopping retransmission on '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' of Request 103: Match Found [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:23033 handle_response_invite: SIP response 200 to standard invite [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10165 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10165 process_sdp: Processing session-level SDP o=- 1540045244 1540045247 IN IP4 veighln... OK. [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10165 process_sdp: Processing session-level SDP s=Asterisk... UNSUPPORTED OR FAILED. [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10165 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10214 process_sdp: Ignoring audio media offer because port number is zero [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:10297 process_sdp: Ignoring video stream offer because port number is zero [Oct 1 11:52:24] WARNING[24574]: chan_sip.c:10588 process_sdp: Insufficient information in SDP (c=)... [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:6811 update_call_counter: Updating call counter for outgoing call [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:16433 build_route: build_route: Contact hop: list_route: route/path hop: [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81:5062' into... [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port '5062'. [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:12005 reqprep: Strict routing enforced for session 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 set_destination: Parsing for address/port to send to [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81:5062' into... [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port '5062'. set_destination: set destination to 10.24.20.81:5062 Transmitting (no NAT) to 10.24.20.81:5062: ACK sip:10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK3beeece8 Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d Contact: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 103 ACK User-Agent: Asterisk PBX SVN-branch-12-r400217 Content-Length: 0 --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:3967 __sip_xmit: Trying to put 'ACK sip:10.' onto UDP socket destined for 10.24.20.81:5062 [Oct 1 11:52:24] DEBUG[24574]: channel.c:2574 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/bob-00000004' [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:12005 reqprep: Strict routing enforced for session 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 set_destination: Parsing for address/port to send to [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81:5062' into... [Oct 1 11:52:24] DEBUG[24574]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port '5062'. set_destination: set destination to 10.24.20.81:5062 Reliably Transmitting (no NAT) to 10.24.20.81:5062: BYE sip:10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK2da96ac6 Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 104 BYE User-Agent: Asterisk PBX SVN-branch-12-r400217 Authorization: Digest username="bob", realm="asterisk", algorithm=MD5, uri="sip:10.24.20.81:5062", nonce="1380646344/b45f2febba67bf86487285faa5e85753", response="fd5d2a25175a52c041d65c622d880a71", opaque="75909b8a6450269d", qop=auth, cnonce="4bea3e72", nc=00000002 X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode: 0 Content-Length: 0 --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4427 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #59 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:3967 __sip_xmit: Trying to put 'BYE sip:10.' onto UDP socket destined for 10.24.20.81:5062 Scheduling destruction of SIP dialog '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' in 32000 ms (Method: INVITE) <--- SIP read from UDP:10.24.20.81:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK2da96ac6 Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d CSeq: 104 BYE Content-Length: 0 <-------------> [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 1 [ 83]: Via: SIP/2.0/UDP 10.24.20.65:5060;rport;received=10.24.20.65;branch=z9hG4bK2da96ac6 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 2 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 4 [ 67]: To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 5 [ 13]: CSeq: 104 BYE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 6 [ 17]: Content-Length: 0 --- (7 headers 0 lines) --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9348 find_call: = Looking for Call ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 (Checking To) --From tag as00109e7a --To-tag eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4626 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #59 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4659 __sip_ack: Stopping retransmission on '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' of Request 104: Match Found [Oct 1 11:52:24] DEBUG[24528]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for SIP - bob [Oct 1 11:52:24] DEBUG[24528]: chan_sip.c:29544 sip_devicestate: Checking device state for peer bob [Oct 1 11:52:24] DEBUG[24528]: devicestate.c:425 do_state_change: Changing state for SIP/bob - state 1 (Not in use) [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'Not in use' for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'Not in use' for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:656 devstate_change_collector_cb: Aggregate state for device 'SIP/bob' has not changed from 'Not in use' -- SIP/bob-00000004 answered > Launching echo((null)) on SIP/bob-00000004 [Oct 1 11:52:24] DEBUG[24597]: channel.c:2745 ast_hangup: Hanging up channel 'SIP/bob-00000004' [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:7191 sip_hangup: Hangup call SIP/bob-00000004, SIP callid 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24597]: res_rtp_asterisk.c:4008 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2f0d7c8' [Oct 1 11:52:24] DEBUG[24597]: res_rtp_asterisk.c:4008 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x2f03578' Scheduling destruction of SIP dialog '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' in 32000 ms (Method: INVITE) [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:12005 reqprep: Strict routing enforced for session 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 set_destination: Parsing for address/port to send to [Oct 1 11:52:24] DEBUG[24597]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.24.20.81:5062' into... [Oct 1 11:52:24] DEBUG[24597]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.24.20.81' and port '5062'. set_destination: set destination to 10.24.20.81:5062 Reliably Transmitting (no NAT) to 10.24.20.81:5062: BYE sip:10.24.20.81:5062 SIP/2.0 Via: SIP/2.0/UDP 10.24.20.65:5060;branch=z9hG4bK0424850a Max-Forwards: 70 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 CSeq: 105 BYE User-Agent: Asterisk PBX SVN-branch-12-r400217 Authorization: Digest username="bob", realm="asterisk", algorithm=MD5, uri="sip:10.24.20.81:5062", nonce="1380646344/b45f2febba67bf86487285faa5e85753", response="7afd41b708eb413699bd86d5c13fca38", opaque="75909b8a6450269d", qop=auth, cnonce="7d8ce866", nc=00000003 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:4427 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #62 [Oct 1 11:52:24] DEBUG[24597]: chan_sip.c:3967 __sip_xmit: Trying to put 'BYE sip:10.' onto UDP socket destined for 10.24.20.81:5062 [Oct 1 11:52:24] DEBUG[24527]: cdr.c:1266 cdr_object_finalize: Finalized CDR for SIP/bob-00000004 - start 1380646344.578903 answer 1380646344.598098 end 1380646344.603965 dispo ANSWERED [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '2013-10-01 11:52:24' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '"" <>' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'local' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'SIP/bob-00000004' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'Echo' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '1380646344.10' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 11:52:24] DEBUG[24527]: pbx.c:4517 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 11:52:24] DEBUG[24527]: cdr_sqlite3_custom.c:262 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2013-10-01 11:52:24','"" <>','local','SIP/bob-00000004','','Echo','','0','0','ANSWERED','DOCUMENTATION','','1380646344.10','','') <--- SIP read from UDP:10.24.20.81:5062 ---> SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/UDP 10.24.20.65:5060;received=10.24.20.65;branch=z9hG4bK0424850a Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 From: "Anonymous" ;tag=as00109e7a To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d CSeq: 105 BYE Content-Length: 0 <-------------> [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 0 [ 43]: SIP/2.0 481 Call/Transaction Does Not Exist [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 1 [ 77]: Via: SIP/2.0/UDP 10.24.20.65:5060;received=10.24.20.65;branch=z9hG4bK0424850a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 2 [ 58]: Call-ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 3 [ 60]: From: "Anonymous" ;tag=as00109e7a [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 4 [ 67]: To: ;tag=eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 5 [ 13]: CSeq: 105 BYE [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9798 parse_request: Header 6 [ 17]: Content-Length: 0 --- (7 headers 0 lines) --- [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:9348 find_call: = Looking for Call ID: 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 (Checking To) --From tag as00109e7a --To-tag eb2d8f0b-5ad5-461c-9d1e-260946892e5d [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4626 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62 [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:4659 __sip_ack: Stopping retransmission on '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' of Request 105: Match Found [Oct 1 11:52:24] DEBUG[24574]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060 Really destroying SIP dialog '7d037ee979a818cd6f9e747e74e8123e@10.24.20.65:5060' Method: INVITE [Oct 1 11:52:24] DEBUG[24574]: rtp_engine.c:338 instance_destructor: Destroyed RTP instance '0x2f0d7c8' [Oct 1 11:52:24] DEBUG[24574]: rtp_engine.c:338 instance_destructor: Destroyed RTP instance '0x2f03578' [Oct 1 11:52:24] DEBUG[24528]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for SIP - bob [Oct 1 11:52:24] DEBUG[24528]: chan_sip.c:29544 sip_devicestate: Checking device state for peer bob [Oct 1 11:52:24] DEBUG[24528]: devicestate.c:425 do_state_change: Changing state for SIP/bob - state 1 (Not in use) [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'Not in use' for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'Not in use' for 'SIP/bob' [Oct 1 11:52:24] DEBUG[24522]: devicestate.c:656 devstate_change_collector_cb: Aggregate state for device 'SIP/bob' has not changed from 'Not in use'