<--- SIP read from UDP:89.209.99.97:5060 ---> INVITE sip:6000444@vm.intersog.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 From: ;tag=1082013176 To: Call-ID: 1852355859 CSeq: 20 INVITE Contact: Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Subject: Phone call Content-Length: 581 v=0 o=6000333 3649 1924 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 a=ice-pwd:7bc004f15af80a5f610c0aaa a=ice-ufrag:0e1e6122 m=audio 7076 RTP/AVP 9 101 c=IN IP4 89.209.99.97 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 <-------------> [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 42]: INVITE sip:6000444@vm.intersog.com SIP/2.0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 33]: To: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 15]: CSeq: 20 INVITE [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 16]: Max-Forwards: 70 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 11 [ 19]: Subject: Phone call [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 12 [ 19]: Content-Length: 581 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 13 [ 0]: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1924 IN IP4 192.168.2.144 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 34]: a=ice-pwd:7bc004f15af80a5f610c0aaa [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=ice-ufrag:0e1e6122 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 9 [ 21]: c=IN IP4 89.209.99.97 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 10 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 12 [ 15]: a=fmtp:101 0-11 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 13 [ 58]: a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 14 [ 58]: a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 15 [ 89]: a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 16 [ 89]: a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 --- (13 headers 17 lines) --- [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag [May 7 16:04:35] DEBUG[1815]: logger.c:1302 ast_create_callid: CALL_ID [C-00000294] created by thread. [May 7 16:04:35] DEBUG[1815]: acl.c:979 ast_ouraddrfor: For destination '89.209.99.97', our source address is '209.239.114.51'. [May 7 16:04:35] DEBUG[1815]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 209.239.114.51:5060 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:8731 sip_alloc: Allocating new SIP dialog for 1852355859 - INVITE (No RTP) [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144:5060' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port '5060'. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:17908 check_via: NAT detected for 192.168.2.144:5060 / 89.209.99.97:5060 Sending to 89.209.99.97:5060 (NAT) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:25071 handle_request_invite: Initializing initreq for method INVITE - callid 1852355859 Using INVITE request as basis request - 1852355859 [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. Found peer '6000333' for '6000333' from 89.209.99.97:5060 <--- Reliably Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK59672018;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as4c84353e Call-ID: 1852355859 CSeq: 20 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="vm.intersog.com", nonce="0fd4b31a" Content-Length: 0 <------------> [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42559 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 89.209.99.97:5060 Scheduling destruction of SIP dialog '1852355859' in 11392 ms (Method: INVITE) [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:35] DEBUG[1815]: chan_sip.c:4113 retrans_pkt: SIP TIMER: Rescheduling retransmission #42559 (1) SIP/2.0 - 1 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:4133 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 356 ms (t1 178 ms (Retrans id #42559)) Retransmitting #1 (NAT) to 89.209.99.97:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK59672018;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as4c84353e Call-ID: 1852355859 CSeq: 20 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="vm.intersog.com", nonce="0fd4b31a" Content-Length: 0 --- [May 7 16:04:35] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 89.209.99.97:5060 <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@vm.intersog.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 From: ;tag=1082013176 To: ;tag=as4c84353e Call-ID: 1852355859 CSeq: 20 ACK Content-Length: 0 <-------------> [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 39]: ACK sip:6000444@vm.intersog.com SIP/2.0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as4c84353e [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 20 ACK [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 17]: Content-Length: 0 --- (7 headers 0 lines) --- [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as4c84353e [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:4528 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42559 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Response 20: Match Found [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from UDP:89.209.99.97:5060 ---> INVITE sip:6000444@vm.intersog.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK968372617 From: ;tag=1082013176 To: Call-ID: 1852355859 CSeq: 21 INVITE Contact: Authorization: Digest username="6000333", realm="vm.intersog.com", nonce="0fd4b31a", uri="sip:6000444@vm.intersog.com", response="a9701efe1e7229c2ba1c75d02c494041", algorithm=MD5 Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Subject: Phone call Content-Length: 581 v=0 o=6000333 3649 1924 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 a=ice-pwd:7bc004f15af80a5f610c0aaa a=ice-ufrag:0e1e6122 m=audio 7076 RTP/AVP 9 101 c=IN IP4 89.209.99.97 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 <-------------> [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 42]: INVITE sip:6000444@vm.intersog.com SIP/2.0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK968372617 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 33]: To: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 15]: CSeq: 21 INVITE [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [178]: Authorization: Digest username="6000333", realm="vm.intersog.com", nonce="0fd4b31a", uri="sip:6000444@vm.intersog.com", response="a9701efe1e7229c2ba1c75d02c494041", algorithm=MD5 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 29]: Content-Type: application/sdp [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 16]: Max-Forwards: 70 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 11 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 12 [ 19]: Subject: Phone call [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 13 [ 19]: Content-Length: 581 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 14 [ 0]: [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1924 IN IP4 192.168.2.144 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 34]: a=ice-pwd:7bc004f15af80a5f610c0aaa [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=ice-ufrag:0e1e6122 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 9 [ 21]: c=IN IP4 89.209.99.97 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 10 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 12 [ 15]: a=fmtp:101 0-11 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 13 [ 58]: a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 14 [ 58]: a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 15 [ 89]: a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 16 [ 89]: a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 --- (14 headers 17 lines) --- [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag [May 7 16:04:35] DEBUG[1815]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. [May 7 16:04:35] DEBUG[1815]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144:5060' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port '5060'. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:17908 check_via: NAT detected for 192.168.2.144:5060 / 89.209.99.97:5060 Sending to 89.209.99.97:5060 (NAT) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:25071 handle_request_invite: Initializing initreq for method INVITE - callid 1852355859 Using INVITE request as basis request - 1852355859 [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. Found peer '6000333' for '6000333' from 89.209.99.97:5060 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdb9426cab8' [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 16500 for RTP instance '0x7fdb9426cab8' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdb9426cab8' is setup and ready to go [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdb94289518' [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 13174 for RTP instance '0x7fdb94289518' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdb94289518' is setup and ready to go [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb94289518' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. == Using SIP VIDEO CoS mark 6 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdb942ea4a8' [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 8604 for RTP instance '0x7fdb942ea4a8' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdb942ea4a8' is setup and ready to go [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb942ea4a8' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb9426cab8' [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. == Using SIP RTP CoS mark 5 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:5730 do_setnat: Setting NAT on RTP to On [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:5734 do_setnat: Setting NAT on VRTP to On [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:5742 do_setnat: Setting NAT on TRTP to On [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000333 3649 1924 IN IP4 192.168.2.144... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.144... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP a=ice-pwd:7bc004f15af80a5f610c0aaa... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP a=ice-ufrag:0e1e6122... OK. Found RTP audio format 9 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba6c0e630 Found RTP audio format 101 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba6c0e630 [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP c=IN IP4 89.209.99.97... OK. Found audio description format G722 for ID 9 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076... OK. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077... OK. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb9426cab8' Peer audio RTP is at port 89.209.99.97:7076 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba6c0e630 to 0x7fdb9426cc80 [May 7 16:04:35] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba6c0e630 to 0x7fdb9426cc80 [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3816 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fdb9426cab8' [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb94289518' Peer doesn't provide video [May 7 16:04:35] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb942ea4a8' Peer doesn't provide T.140 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:25204 handle_request_invite: Checking SIP call limits for device 6000333 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for incoming call [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:35] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. Looking for 6000444 in webrtc (domain vm.intersog.com) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:7911 sip_new: *** Our native formats are (g722) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:7912 sip_new: *** Joint capabilities are (g722) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:7913 sip_new: *** Our capabilities are (ulaw|g729|g722|h263|h264) [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:7914 sip_new: *** AST_CODEC_CHOOSE formats are g722 [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:7940 sip_new: This channel can handle video! HOLLYWOOD next! [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:16162 build_route: build_route: Contact hop: list_route: hop: [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:25514 handle_request_invite: SIP/6000333-00000093: New call is still down.... Trying... <--- Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK968372617;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: Call-ID: 1852355859 CSeq: 21 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [May 7 16:04:35] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:35] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000333 [May 7 16:04:35] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000333 [May 7 16:04:35] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000333 - state 1 (Not in use) [May 7 16:04:35] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000333' state '1' [May 7 16:04:35] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:35] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000333' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 7 16:04:35] DEBUG[9780][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@vm.intersog.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 From: ;tag=1082013176 To: ;tag=as4c84353e Call-ID: 1852355859 CSeq: 20 ACK Content-Length: 0 <-------------> [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 39]: ACK sip:6000444@vm.intersog.com SIP/2.0 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK59672018 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as4c84353e [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 20 ACK [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 17]: Content-Length: 0 --- (7 headers 0 lines) --- [May 7 16:04:35] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as4c84353e [May 7 16:04:35] DEBUG[1815]: chan_sip.c:28204 handle_request_do: Invalid SIP message - rejected , no callid, len 256 [May 7 16:04:35] DEBUG[9780][C-00000294]: pbx.c:3642 ast_str_retrieve_variable: Result of 'EXTEN' is '6000444' [May 7 16:04:35] DEBUG[9780][C-00000294]: pbx.c:4633 pbx_extension_helper: Launching 'NoOp' -- Executing [6000444@webrtc:1] NoOp("SIP/6000333-00000093", "Call Start to: 6000444") in new stack [May 7 16:04:35] DEBUG[9780][C-00000294]: pbx.c:3642 ast_str_retrieve_variable: Result of 'EXTEN' is '6000444' [May 7 16:04:35] DEBUG[9780][C-00000294]: pbx.c:4633 pbx_extension_helper: Launching 'Dial' -- Executing [6000444@webrtc:2] Dial("SIP/6000333-00000093", "SIP/6000444,20,S(600)") in new stack -- Setting call duration limit to 600.000 seconds. [May 7 16:04:35] DEBUG[9780][C-00000294]: chan_sip.c:29470 sip_request_call: Asked to create a SIP channel with formats: (g722) [May 7 16:04:35] DEBUG[9780][C-00000294]: chan_sip.c:8731 sip_alloc: Allocating new SIP dialog for 31f5fb1825c77ed51ff3383108a5db1e@209.239.114.51:5060 - INVITE (No RTP) [May 7 16:04:35] DEBUG[9780][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdbd800ef48' [May 7 16:04:35] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 10336 for RTP instance '0x7fdbd800ef48' [May 7 16:04:35] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:35] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdbd800ef48' is setup and ready to go [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdbd801bf68' [May 7 16:04:36] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 7372 for RTP instance '0x7fdbd801bf68' [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdbd801bf68' is setup and ready to go [May 7 16:04:36] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdbd801bf68' [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. == Using SIP VIDEO CoS mark 6 [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:283 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7fdbd80285c8' [May 7 16:04:36] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1731 ast_rtp_new: Allocated port 13126 for RTP instance '0x7fdbd80285c8' [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. <--- SIP read from UDP:89.209.99.97:5060 ---> INVITE sip:6000444@vm.intersog.com SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK968372617 From: ;tag=1082013176 To: Call-ID: 1852355859 CSeq: 21 INVITE Contact: Authorization: Digest username="6000333", realm="vm.intersog.com", nonce="0fd4b31a", uri="sip:6000444@vm.intersog.com", response="a9701efe1e7229c2ba1c75d02c494041", algorithm=MD5 Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Subject: Phone call Content-Length: 581 v=0 o=6000333 3649 1924 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 a=ice-pwd:7bc004f15af80a5f610c0aaa a=ice-ufrag:0e1e6122 m=audio 7076 RTP/AVP 9 101 c=IN IP4 89.209.99.97 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 <-------------> [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 42]: INVITE sip:6000444@vm.intersog.com SIP/2.0 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK968372617 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 33]: To: [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 15]: CSeq: 21 INVITE [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [178]: Authorization: Digest username="6000333", realm="vm.intersog.com", nonce="0fd4b31a", uri="sip:6000444@vm.intersog.com", response="a9701efe1e7229c2ba1c75d02c494041", algorithm=MD5 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 29]: Content-Type: application/sdp [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 16]: Max-Forwards: 70 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 11 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 12 [ 19]: Subject: Phone call [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 13 [ 19]: Content-Length: 581 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 14 [ 0]: [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1924 IN IP4 192.168.2.144 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 34]: a=ice-pwd:7bc004f15af80a5f610c0aaa [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=ice-ufrag:0e1e6122 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 9 [ 21]: c=IN IP4 89.209.99.97 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 10 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 12 [ 15]: a=fmtp:101 0-11 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 13 [ 58]: a=candidate:1 1 UDP 2130706431 192.168.2.144 7076 typ host [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 14 [ 58]: a=candidate:1 2 UDP 2130706430 192.168.2.144 7077 typ host [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 15 [ 89]: a=candidate:2 1 UDP 1694498815 89.209.99.97 7076 typ srflx raddr 192.168.2.144 rport 7076 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 16 [ 89]: a=candidate:2 2 UDP 1694498814 89.209.99.97 7077 typ srflx raddr 192.168.2.144 rport 7077 --- (14 headers 17 lines) --- [May 7 16:04:36] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag [May 7 16:04:36] DEBUG[1815]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:36] DEBUG[1815]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. [May 7 16:04:36] DEBUG[1815]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'vm.intersog.com' into... [May 7 16:04:36] DEBUG[1815]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'vm.intersog.com' and port ''. [May 7 16:04:36] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:36] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 7 16:04:36] DEBUG[1815][C-00000294]: chan_sip.c:27953 handle_incoming: Ignoring SIP message because of retransmit (INVITE Seqno 21, ours 21) Ignoring this INVITE request [May 7 16:04:36] DEBUG[1815][C-00000294]: chan_sip.c:25304 handle_request_invite: Got a SIP re-transmit of INVITE for call 1852355859 <--- Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK968372617;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: Call-ID: 1852355859 CSeq: 21 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [May 7 16:04:36] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:36] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance '0x7fdbd80285c8' is setup and ready to go [May 7 16:04:36] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdbd80285c8' [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdbd800ef48' [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:36] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. == Using SIP RTP CoS mark 5 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:5730 do_setnat: Setting NAT on RTP to On [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:5734 do_setnat: Setting NAT on VRTP to On [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:5742 do_setnat: Setting NAT on TRTP to On [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:3636 obproxy_get: OBPROXY: Not applying OBproxy to this call [May 7 16:04:36] DEBUG[9780][C-00000294]: acl.c:979 ast_ouraddrfor: For destination '89.209.99.97', our source address is '209.239.114.51'. [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_TCP with address 209.239.114.51:5060 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:8525 change_callid_pvt: SIP call-id changed from '31f5fb1825c77ed51ff3383108a5db1e@209.239.114.51:5060' to '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7911 sip_new: *** Our native formats are (g722) [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7912 sip_new: *** Joint capabilities are (g722) [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7913 sip_new: *** Our capabilities are (ulaw|g729|g722|h263|h264) [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7914 sip_new: *** AST_CODEC_CHOOSE formats are g722 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7916 sip_new: *** Our preferred formats from the incoming channel are (g722) [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:7940 sip_new: This channel can handle video! HOLLYWOOD next! [May 7 16:04:36] DEBUG[9780][C-00000294]: channel_internal_api.c:882 ast_channel_callid_set: Channel Call ID changing from [C-00000294] to [C-00000294] [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:1698 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'SIP/6000444-00000094' with that of 'SIP/6000333-00000093' [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 7 16:04:36] DEBUG[9780][C-00000294]: channel.c:6507 ast_channel_inherit_variables: Not copying variable SIPURI. [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:6350 sip_call: Outgoing Call for 6000444 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for outgoing call [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:13034 add_sdp: This call needs video offers! [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (ulaw|g729|g722|h263|h264) Video flag: False Text flag: False [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (g722) Audio is at 10336 Video is at 209.239.114.51:7372 Adding codec 100012 (g722) to SDP Adding codec 100003 (ulaw) to SDP Adding codec 100008 (g729) to SDP Adding video codec 200004 (h264) to SDP Adding video codec 200002 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (ulaw|g729|g722|h263|h264) [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:3512 initialize_initreq: Initializing initreq for method INVITE - callid 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 80]: INVITE sip:6000444@89.209.99.97:54787;transport=tcp;line=c6eea3073c3bb64 SIP/2.0 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 71]: To: [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 56]: Contact: [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 35]: Date: Tue, 07 May 2013 16:04:36 GMT [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 26]: Supported: replaces, timer [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:54787: INVITE sip:6000444@89.209.99.97:54787;transport=tcp;line=c6eea3073c3bb64 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 INVITE User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 1316 v=0 o=root 1528145059 1528145059 IN IP4 209.239.114.51 s=Asterisk PBX 11.3.0 c=IN IP4 209.239.114.51 b=CT:384 t=0 0 m=audio 10336 RTP/AVP 9 0 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=ice-ufrag:6e205c7811fa296f532f539a314eb76d a=ice-pwd:1e4ada0f4a6a39155a81778318f50030 a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 10336 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 10336 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 10337 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 10336 typ srflx a=sendrecv m=video 7372 RTP/AVP 99 34 a=ice-ufrag:09f56dcb212e56253f08e1d119c63659 a=ice-pwd:072cf84800ebadea1ed2b9f606cfe61c a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 7372 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 7372 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 7373 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 7372 typ srflx a=rtpmap:99 H264/90000 a=fmtp:99 redundant-pic-cap=0;parameter-add=0;packetization-mode=0;level-asymmetry-allowed=0 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 --- [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 89.209.99.97:54787 -- Called SIP/6000444 [May 7 16:04:36] DEBUG[1815]: chan_sip.c:4417 __sip_autodestruct: Auto destroying SIP dialog '159463716' [May 7 16:04:36] DEBUG[1815]: chan_sip.c:6822 sip_destroy: Destroying SIP dialog 159463716 Really destroying SIP dialog '159463716' Method: REGISTER <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 100 Trying Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 From: "Doctor" ;tag=as573d8290 To: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 71]: To: [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:36] DEBUG[9776][C-00000294]: chan_sip.c:22418 handle_response_invite: SIP response 100 to standard invite [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 101 Dialog Establishement Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 INVITE Contact: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 33]: SIP/2.0 101 Dialog Establishement [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 56]: Contact: [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 17]: Content-Length: 0 --- (9 headers 0 lines) --- [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:36] DEBUG[9776][C-00000294]: chan_sip.c:22418 handle_response_invite: SIP response 101 to standard invite [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 180 Ringing Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 INVITE Contact: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 56]: Contact: [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 17]: Content-Length: 0 --- (9 headers 0 lines) --- [May 7 16:04:36] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:36] DEBUG[9776][C-00000294]: chan_sip.c:22418 handle_response_invite: SIP response 180 to standard invite [May 7 16:04:36] DEBUG[9776][C-00000294]: chan_sip.c:16162 build_route: build_route: Contact hop: list_route: hop: [May 7 16:04:36] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:36] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000444 [May 7 16:04:36] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000444 [May 7 16:04:36] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000444 - state 1 (Not in use) [May 7 16:04:36] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000444' state '1' [May 7 16:04:36] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000444' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- SIP/6000444-00000094 is ringing [May 7 16:04:36] DEBUG[9780][C-00000294]: rtp_engine.c:1805 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/6000333-00000093' with that of 'SIP/6000444-00000094' <--- Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK968372617;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 21 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [May 7 16:04:36] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 89.209.99.97:5060 <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 231 v=0 o=6000444 2744 3274 IN IP4 192.168.2.225 s=Talk c=IN IP4 192.168.2.225 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 m=video 0 RTP/AVP 0 a=inactive <-------------> [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK79788735;rport=5060 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 50]: Contact: [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 231 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000444 2744 3274 IN IP4 192.168.2.225 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.225 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 10 [ 19]: m=video 0 RTP/AVP 0 [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9615 parse_request: Body 11 [ 10]: a=inactive --- (10 headers 12 lines) --- [May 7 16:04:38] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:38] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:22418 handle_response_invite: SIP response 200 to standard invite [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000444 2744 3274 IN IP4 192.168.2.225... OK. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:38] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225' into... [May 7 16:04:38] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port ''. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.225... OK. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:38] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba590fad0 Found RTP audio format 101 [May 7 16:04:38] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba590fad0 Found audio description format G722 for ID 9 [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. [May 7 16:04:38] WARNING[9776][C-00000294]: chan_sip.c:10141 process_sdp: Ignoring video stream offer because port number is zero Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [May 7 16:04:38] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd800ef48' Peer audio RTP is at port 192.168.2.225:7076 [May 7 16:04:38] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:38] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:38] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3816 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fdbd800ef48' [May 7 16:04:38] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd801bf68' Peer doesn't provide video [May 7 16:04:38] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' Peer doesn't provide T.140 [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g722) [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for outgoing call [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:16162 build_route: build_route: Contact hop: list_route: hop: [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:38] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:38] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 Transmitting (NAT) to 89.209.99.97:54787: ACK sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK6da7a130;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 102 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:38] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:lin' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:38] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:38] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000444 -- SIP/6000444-00000094 answered SIP/6000333-00000093 [May 7 16:04:38] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000444 [May 7 16:04:38] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000444 - state 1 (Not in use) [May 7 16:04:38] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000444' state '1' [May 7 16:04:38] DEBUG[9780][C-00000294]: rtp_engine.c:1805 ast_rtp_instance_early_bridge: Setting early bridge SDP of 'SIP/6000333-00000093' with that of 'SIP/6000444-00000094' [May 7 16:04:38] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000444' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:7261 sip_answer: SIP answering channel: SIP/6000333-00000093 [May 7 16:04:38] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:2084 ast_rtp_update_source: Setting the marker bit due to a source update [May 7 16:04:38] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000333 [May 7 16:04:38] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000333 [May 7 16:04:38] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000333 - state 1 (Not in use) [May 7 16:04:38] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000333' state '1' [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13534 transmit_response_with_sdp: Setting framing from config on incoming call [May 7 16:04:38] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000333' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722) Video flag: True Text flag: True [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (nothing) Audio is at 16500 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) <--- Reliably Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK968372617;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 21 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 636 v=0 o=root 379716584 379716584 IN IP4 209.239.114.51 s=Asterisk PBX 11.3.0 c=IN IP4 209.239.114.51 t=0 0 m=audio 16500 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=ice-ufrag:78154d5622241dca7692083e7561fd64 a=ice-pwd:29f912b0324cefdc0470a3d43a125b9b a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 16500 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 16500 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 16501 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 16500 typ srflx a=sendrecv <------------> [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42565 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:38] DEBUG[9780][C-00000294]: features.c:4410 ast_bridge_call: bridge answer set, chan answer set [May 7 16:04:38] DEBUG[9780][C-00000294]: features.c:4234 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/6000444-00000094 since we're bridging [May 7 16:04:38] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:2084 ast_rtp_update_source: Setting the marker bit due to a source update [May 7 16:04:38] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:2084 ast_rtp_update_source: Setting the marker bit due to a source update -- Remotely bridging SIP/6000333-00000093 and SIP/6000444-00000094 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:32503 sip_set_rtp_peer: Deferring reinvite on SIP '1852355859' - It's audio will be redirected to IP 192.168.2.225:7076 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:32500 sip_set_rtp_peer: Sending reinvite on SIP '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' - It's audio soon redirected to IP 89.209.99.97:7076 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:38] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:38] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722) Video flag: True Text flag: True [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (g722) [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13089 add_sdp: ** Our native-bridge filtered capablity: (g722) Audio is at 10336 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:3510 initialize_initreq: Initializing already initialized SIP dialog 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (presumably reinvite) [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 54]: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 86]: To: ;tag=2128546057 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 56]: Contact: [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 103 INVITE [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 26]: Supported: replaces, timer [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:54787: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 103 INVITE User-Agent: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 261 v=0 o=root 1528145059 1528145060 IN IP4 89.209.99.97 s=Asterisk PBX 11.3.0 c=IN IP4 89.209.99.97 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 7 16:04:38] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:38] DEBUG[9780][C-00000294]: rtp_engine.c:1278 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' changed end address to 89.209.99.97:7076 (format (g722)) [May 7 16:04:38] DEBUG[9780][C-00000294]: rtp_engine.c:1281 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' was 89.209.99.97:7076/(format (g722)) [May 7 16:04:38] WARNING[9780][C-00000294]: res_rtp_asterisk.c:1450 __rtp_recvfrom: PJ ICE Rx error status code: 370400 'Bad Request'. [May 7 16:04:38] DEBUG[1815]: chan_sip.c:4113 retrans_pkt: SIP TIMER: Rescheduling retransmission #42565 (1) SIP/2.0 - 1 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:4133 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 356 ms (t1 178 ms (Retrans id #42565)) Retransmitting #1 (NAT) to 89.209.99.97:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK968372617;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 21 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 636 v=0 o=root 379716584 379716584 IN IP4 209.239.114.51 s=Asterisk PBX 11.3.0 c=IN IP4 209.239.114.51 t=0 0 m=audio 16500 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=ice-ufrag:78154d5622241dca7692083e7561fd64 a=ice-pwd:29f912b0324cefdc0470a3d43a125b9b a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 16500 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 16500 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 16501 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 16500 typ srflx a=sendrecv --- [May 7 16:04:38] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 89.209.99.97:5060 <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@209.239.114.51:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK8485795 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 21 ACK Contact: Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 43]: ACK sip:6000444@209.239.114.51:5060 SIP/2.0 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK8485795 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as08ba5b0e [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 21 ACK [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 16]: Max-Forwards: 70 [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 7 16:04:38] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as08ba5b0e [May 7 16:04:38] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:4528 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42565 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Response 21: Match Found [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:22219 check_pendings: Sending pending reinvite on '1852355859' [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 1852355859 set_destination: Parsing for address/port to send to [May 7 16:04:38] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:38] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. set_destination: set destination to 89.209.99.97:5060 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722) Video flag: True Text flag: True [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (nothing) [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:13089 add_sdp: ** Our native-bridge filtered capablity: (g722) Audio is at 16500 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:3510 initialize_initreq: Initializing already initialized SIP dialog 1852355859 (presumably reinvite) [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 39]: INVITE sip:6000333@89.209.99.97 SIP/2.0 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 48]: To: ;tag=1082013176 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 42]: Contact: [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 19]: Call-ID: 1852355859 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 26]: Supported: replaces, timer [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:5060: INVITE sip:6000333@89.209.99.97 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport Max-Forwards: 70 From: ;tag=as08ba5b0e To: ;tag=1082013176 Contact: Call-ID: 1852355859 CSeq: 102 INVITE User-Agent: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 261 v=0 o=root 379716584 379716585 IN IP4 192.168.2.225 s=Asterisk PBX 11.3.0 c=IN IP4 192.168.2.225 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42566 [May 7 16:04:38] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:38] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:38] WARNING[9780][C-00000294]: res_rtp_asterisk.c:1450 __rtp_recvfrom: PJ ICE Rx error status code: 370400 'Bad Request'. [May 7 16:04:38] WARNING[9780][C-00000294]: res_rtp_asterisk.c:1450 __rtp_recvfrom: PJ ICE Rx error status code: 370400 'Bad Request'. [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3501 ast_rtp_read: 0x7fdb944a33f0 -- start learning mode pass with addr = 89.209.99.97:7076 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1604 rtp_learning_rtp_seq_update: 0x7fdb944a33f0 -- probation = 4, seq = 0 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3507 ast_rtp_read: 0x7fdb944a33f0 -- Condition for learning hasn't exited, so reject the frame. [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3501 ast_rtp_read: 0x7fdb944a33f0 -- start learning mode pass with addr = 89.209.99.97:7076 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1604 rtp_learning_rtp_seq_update: 0x7fdb944a33f0 -- probation = 3, seq = 1 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3507 ast_rtp_read: 0x7fdb944a33f0 -- Condition for learning hasn't exited, so reject the frame. [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3501 ast_rtp_read: 0x7fdb944a33f0 -- start learning mode pass with addr = 89.209.99.97:7076 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1604 rtp_learning_rtp_seq_update: 0x7fdb944a33f0 -- probation = 2, seq = 2 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3507 ast_rtp_read: 0x7fdb944a33f0 -- Condition for learning hasn't exited, so reject the frame. <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@209.239.114.51:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK8485795 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 21 ACK Contact: Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 43]: ACK sip:6000444@209.239.114.51:5060 SIP/2.0 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK8485795 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as08ba5b0e [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 21 ACK [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 16]: Max-Forwards: 70 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as08ba5b0e [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3501 ast_rtp_read: 0x7fdb944a33f0 -- start learning mode pass with addr = 89.209.99.97:7076 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:1604 rtp_learning_rtp_seq_update: 0x7fdb944a33f0 -- probation = 1, seq = 3 [May 7 16:04:39] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3511 ast_rtp_read: 0x7fdb944a33f0 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 89.209.99.97:7076 Sent RTP P2P packet to 192.168.2.225:7076 (type 09, len 000160) Sent RTP P2P packet to 192.168.2.225:7076 (type 09, len 000160) Sent RTP P2P packet to 192.168.2.225:7076 (type 09, len 000160) <--- SIP read from UDP:89.209.99.97:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport=5060 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 102 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport=5060 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=1082013176 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking To) --From tag as08ba5b0e --To-tag 1082013176 [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:4595 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #42566 - INVITE (got response) [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:4602 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1852355859' Request 102: Found [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 100 to RE-invite on outgoing call 1852355859 [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 100 Trying Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 103 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport=5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 100 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from UDP:89.209.99.97:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport=5060 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 102 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 198 v=0 o=6000333 3649 1925 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK7c4036dd;rport=5060 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=1082013176 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 198 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1925 IN IP4 192.168.2.144 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 --- (10 headers 10 lines) --- [May 7 16:04:39] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking To) --From tag as08ba5b0e --To-tag 1082013176 [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:4523 __sip_ack: Acked pending invite 102 [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Request 102: Match Found [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1852355859 [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000333 3649 1925 IN IP4 192.168.2.144... OK. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.144... OK. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:39] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba6c0dad0 Found RTP audio format 101 [May 7 16:04:39] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba6c0dad0 Found audio description format G722 for ID 9 [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.2.144:7076 [May 7 16:04:39] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba6c0dad0 to 0x7fdb9426cc80 [May 7 16:04:39] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba6c0dad0 to 0x7fdb9426cc80 [May 7 16:04:39] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb9426cab8' [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. Peer doesn't provide video [May 7 16:04:39] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb942ea4a8' Peer doesn't provide T.140 [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g722) [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for incoming call [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 1852355859 set_destination: Parsing for address/port to send to [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:39] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. set_destination: set destination to 89.209.99.97:5060 Transmitting (NAT) to 89.209.99.97:5060: ACK sip:6000333@89.209.99.97 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK1a40a74f;rport Max-Forwards: 70 From: ;tag=as08ba5b0e To: ;tag=1082013176 Contact: Call-ID: 1852355859 CSeq: 102 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:39] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:600' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:39] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:39] DEBUG[9780][C-00000294]: rtp_engine.c:1278 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' changed end address to 192.168.2.144:7076 (format (g722)) [May 7 16:04:39] DEBUG[9780][C-00000294]: rtp_engine.c:1281 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' was 89.209.99.97:7076/(format (g722)) [May 7 16:04:39] DEBUG[9780][C-00000294]: chan_sip.c:32503 sip_set_rtp_peer: Deferring reinvite on SIP '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' - It's audio will be redirected to IP 192.168.2.144:7076 <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 103 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 198 v=0 o=6000444 2744 3275 IN IP4 192.168.2.225 s=Talk c=IN IP4 192.168.2.225 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4195309f;rport=5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 50]: Contact: [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 198 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000444 2744 3275 IN IP4 192.168.2.225 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.225 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9615 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 --- (10 headers 10 lines) --- [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 200 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000444 2744 3275 IN IP4 192.168.2.225... OK. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225' into... [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port ''. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.225... OK. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:39] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba590fad0 Found RTP audio format 101 [May 7 16:04:39] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba590fad0 Found audio description format G722 for ID 9 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.2.225:7076 [May 7 16:04:39] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:39] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:39] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdbd800ef48' [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. Peer doesn't provide video [May 7 16:04:39] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' Peer doesn't provide T.140 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g722) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for outgoing call [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 Transmitting (NAT) to 89.209.99.97:54787: ACK sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK610888a1;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 103 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:lin' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:22219 check_pendings: Sending pending reinvite on '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:39] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722) Video flag: True Text flag: True [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (g722) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:13089 add_sdp: ** Our native-bridge filtered capablity: (g722) Audio is at 10336 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:3510 initialize_initreq: Initializing already initialized SIP dialog 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (presumably reinvite) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 54]: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 86]: To: ;tag=2128546057 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 56]: Contact: [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 104 INVITE [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 26]: Supported: replaces, timer [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:54787: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 104 INVITE User-Agent: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 263 v=0 o=root 1528145059 1528145061 IN IP4 192.168.2.144 s=Asterisk PBX 11.3.0 c=IN IP4 192.168.2.144 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 100 Trying Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 104 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport=5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 104 INVITE [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:39] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:39] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 100 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:39] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:39] WARNING[9780][C-00000294]: res_rtp_asterisk.c:1450 __rtp_recvfrom: PJ ICE Rx error status code: 370400 'Bad Request'. [May 7 16:04:40] DEBUG[1815]: chan_sip.c:8731 sip_alloc: Allocating new SIP dialog for 7a7075f06b7d79900e943e944792d6b2@209.239.114.51:5060 - OPTIONS (No RTP) [May 7 16:04:40] DEBUG[1815]: acl.c:979 ast_ouraddrfor: For destination '89.209.99.97', our source address is '209.239.114.51'. [May 7 16:04:40] DEBUG[1815]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 209.239.114.51:5060 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:8525 change_callid_pvt: SIP call-id changed from '7a7075f06b7d79900e943e944792d6b2@209.239.114.51:5060' to '7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060' [May 7 16:04:40] DEBUG[1815]: chan_sip.c:3512 initialize_initreq: Initializing initreq for method OPTIONS - callid 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 70]: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as6b06b1c4 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 60]: To: [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 43]: Contact: [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 61]: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 35]: Date: Tue, 07 May 2013 16:04:40 GMT [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:40] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 89.209.99.97:55584: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport Max-Forwards: 70 From: "asterisk" ;tag=as6b06b1c4 To: Contact: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 CSeq: 102 OPTIONS User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [May 7 16:04:40] DEBUG[1815]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42567 [May 7 16:04:40] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 89.209.99.97:55584 <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 104 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 198 v=0 o=6000444 2744 3276 IN IP4 192.168.2.225 s=Talk c=IN IP4 192.168.2.225 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK01bf3ecb;rport=5060 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 104 INVITE [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 50]: Contact: [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 198 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000444 2744 3276 IN IP4 192.168.2.225 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.225 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9615 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 --- (10 headers 10 lines) --- [May 7 16:04:40] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:40] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 200 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000444 2744 3276 IN IP4 192.168.2.225... OK. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:40] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225' into... [May 7 16:04:40] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port ''. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.225... OK. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:40] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba590fad0 Found RTP audio format 101 [May 7 16:04:40] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba590fad0 Found audio description format G722 for ID 9 [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [May 7 16:04:40] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd800ef48' Peer audio RTP is at port 192.168.2.225:7076 [May 7 16:04:40] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:40] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:40] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3816 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fdbd800ef48' Peer doesn't provide video [May 7 16:04:40] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' Peer doesn't provide T.140 [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g722) [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for outgoing call [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:40] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:40] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 Transmitting (NAT) to 89.209.99.97:54787: ACK sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK1a356f03;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 104 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:40] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:lin' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:40] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:41] DEBUG[1815]: chan_sip.c:4103 retrans_pkt: SIP TIMER: Not rescheduling id #42567:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (NAT) to 89.209.99.97:55584: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport Max-Forwards: 70 From: "asterisk" ;tag=as6b06b1c4 To: Contact: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 CSeq: 102 OPTIONS User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [May 7 16:04:41] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 89.209.99.97:55584 [May 7 16:04:42] DEBUG[1815]: chan_sip.c:4103 retrans_pkt: SIP TIMER: Not rescheduling id #42567:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (NAT) to 89.209.99.97:55584: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport Max-Forwards: 70 From: "asterisk" ;tag=as6b06b1c4 To: Contact: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 CSeq: 102 OPTIONS User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [May 7 16:04:42] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 89.209.99.97:55584 [May 7 16:04:43] DEBUG[1815]: chan_sip.c:4103 retrans_pkt: SIP TIMER: Not rescheduling id #42567:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (NAT) to 89.209.99.97:55584: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport Max-Forwards: 70 From: "asterisk" ;tag=as6b06b1c4 To: Contact: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 CSeq: 102 OPTIONS User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [May 7 16:04:43] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 89.209.99.97:55584 [May 7 16:04:44] DEBUG[1815]: chan_sip.c:4103 retrans_pkt: SIP TIMER: Not rescheduling id #42567:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (NAT) to 89.209.99.97:55584: OPTIONS sip:7000000241@89.209.99.97:55584;line=96c156cf2853f01 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK0ce28384;rport Max-Forwards: 70 From: "asterisk" ;tag=as6b06b1c4 To: Contact: Call-ID: 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 CSeq: 102 OPTIONS User-Agent: Video Medicine PBX Date: Tue, 07 May 2013 16:04:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [May 7 16:04:44] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 89.209.99.97:55584 [May 7 16:04:44] DEBUG[1815]: chan_sip.c:6822 sip_destroy: Destroying SIP dialog 7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060 Really destroying SIP dialog '7d4c22117d8959297b3fb0c141f7f417@209.239.114.51:5060' Method: OPTIONS <--- SIP read from UDP:89.209.99.97:5060 ---> INVITE sip:6000444@209.239.114.51:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1157469319 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 INVITE Contact: Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Subject: Media change Content-Length: 285 v=0 o=6000333 3649 1926 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 m=video 9078 RTP/AVP 102 a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014 <-------------> [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 46]: INVITE sip:6000444@209.239.114.51:5060 SIP/2.0 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1157469319 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as08ba5b0e [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 15]: CSeq: 22 INVITE [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 16]: Max-Forwards: 70 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 11 [ 21]: Subject: Media change [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 12 [ 19]: Content-Length: 285 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 13 [ 0]: [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1926 IN IP4 192.168.2.144 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 10 [ 24]: m=video 9078 RTP/AVP 102 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 11 [ 23]: a=rtpmap:102 H264/90000 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 12 [ 34]: a=fmtp:102 profile-level-id=428014 --- (13 headers 13 lines) --- [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as08ba5b0e [May 7 16:04:45] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144:5060' into... [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port '5060'. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:17908 check_via: NAT detected for 192.168.2.144:5060 / 89.209.99.97:5060 Sending to 89.209.99.97:5060 (NAT) [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:25071 handle_request_invite: Initializing initreq for method INVITE - callid 1852355859 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000333 3649 1926 IN IP4 192.168.2.144... OK. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.144... OK. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba6c0e630 Found RTP audio format 101 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba6c0e630 Found audio description format G722 for ID 9 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Found RTP video format 102 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 102 based on m type on 0x7fdba6c12980 Found video description format H264 for ID 102 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (video) SDP a=rtpmap:102 H264/90000... OK. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (video) SDP a=fmtp:102 profile-level-id=428014... OK. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(h264)/text=(nothing), combined - (g722|h264) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.2.144:7076 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba6c0e630 to 0x7fdb9426cc80 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba6c0e630 to 0x7fdb9426cc80 [May 7 16:04:45] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb9426cab8' [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:45] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. Peer video RTP is at port 192.168.2.144:9078 [May 7 16:04:45] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 102 from 0x7fdba6c12980 to 0x7fdb942896e0 [May 7 16:04:45] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb942ea4a8' Peer doesn't provide T.140 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722|h264) [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722|h264), old nativeformats (g722) [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:25302 handle_request_invite: Got a SIP re-invite for call 1852355859 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:25578 handle_request_invite: SIP/6000333-00000093: This call is UP.... <--- Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK1157469319;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13534 transmit_response_with_sdp: Setting framing from config on incoming call [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13031 add_sdp: This call needs video offers, but caller probably did not offer it! [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722|h264) Video flag: False Text flag: True [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (nothing) [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13089 add_sdp: ** Our native-bridge filtered capablity: (g722) Audio is at 16500 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) <--- Reliably Transmitting (NAT) to 89.209.99.97:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK1157469319;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 284 v=0 o=root 379716584 379716586 IN IP4 192.168.2.225 s=Asterisk PBX 11.3.0 c=IN IP4 192.168.2.225 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 0 RTP/AVP 102 <------------> [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42570 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:45] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:45] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:2084 ast_rtp_update_source: Setting the marker bit due to a source update [May 7 16:04:45] DEBUG[9780][C-00000294]: rtp_engine.c:1278 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' changed end address to 192.168.2.144:7076 (format (g722|h264)) [May 7 16:04:45] DEBUG[9780][C-00000294]: rtp_engine.c:1281 remote_bridge_loop: Oooh, 'SIP/6000333-00000093' was 192.168.2.144:7076/(format (g722|h264)) [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:32500 sip_set_rtp_peer: Sending reinvite on SIP '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' - It's audio soon redirected to IP 192.168.2.144:7076 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:45] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:45] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722) Video flag: True Text flag: True [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (g722) [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:13089 add_sdp: ** Our native-bridge filtered capablity: (g722) Audio is at 10336 Adding codec 100012 (g722) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722) [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:3510 initialize_initreq: Initializing already initialized SIP dialog 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (presumably reinvite) [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 54]: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 86]: To: ;tag=2128546057 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 56]: Contact: [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 105 INVITE [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 26]: Supported: replaces, timer [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:54787: INVITE sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 105 INVITE User-Agent: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 263 v=0 o=root 1528145059 1528145062 IN IP4 192.168.2.144 s=Asterisk PBX 11.3.0 c=IN IP4 192.168.2.144 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [May 7 16:04:45] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto TCP socket destined for 89.209.99.97:54787 <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 100 Trying Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 105 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport=5060 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 105 INVITE [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:45] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 100 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:45] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:45] DEBUG[1815]: chan_sip.c:4113 retrans_pkt: SIP TIMER: Rescheduling retransmission #42570 (1) SIP/2.0 - 1 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:4133 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 356 ms (t1 178 ms (Retrans id #42570)) Retransmitting #1 (NAT) to 89.209.99.97:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.144:5060;branch=z9hG4bK1157469319;received=89.209.99.97;rport=5060 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 INVITE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 284 v=0 o=root 379716584 379716586 IN IP4 192.168.2.225 s=Asterisk PBX 11.3.0 c=IN IP4 192.168.2.225 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 0 RTP/AVP 102 --- [May 7 16:04:45] DEBUG[1815]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 89.209.99.97:5060 <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@209.239.114.51:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1564077610 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 ACK Contact: Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 43]: ACK sip:6000444@209.239.114.51:5060 SIP/2.0 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1564077610 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as08ba5b0e [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 22 ACK [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 16]: Max-Forwards: 70 [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 7 16:04:45] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as08ba5b0e [May 7 16:04:45] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:4528 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42570 [May 7 16:04:45] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Response 22: Match Found [May 7 16:04:45] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport=5060 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 105 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 198 v=0 o=6000444 2744 3277 IN IP4 192.168.2.225 s=Talk c=IN IP4 192.168.2.225 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 <-------------> [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK4052dfc4;rport=5060 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 58]: From: "Doctor" ;tag=as573d8290 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 86]: To: ;tag=2128546057 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 105 INVITE [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 50]: Contact: [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 198 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000444 2744 3277 IN IP4 192.168.2.225 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.225 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9615 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 --- (10 headers 10 lines) --- [May 7 16:04:45] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking To) --From tag as573d8290 --To-tag 2128546057 [May 7 16:04:45] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 200 to RE-invite on outgoing call 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000444 2744 3277 IN IP4 192.168.2.225... OK. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225' into... [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port ''. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.225... OK. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:45] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba590fad0 Found RTP audio format 101 [May 7 16:04:45] DEBUG[9776][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba590fad0 Found audio description format G722 for ID 9 [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:45] DEBUG[9776][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(nothing)/text=(nothing), combined - (g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.2.225:7076 [May 7 16:04:45] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:45] DEBUG[9776][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba590fad0 to 0x7fdbd800f110 [May 7 16:04:45] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdbd800ef48' [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:45] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. Peer doesn't provide video [May 7 16:04:46] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' Peer doesn't provide T.140 [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722) [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:10694 process_sdp: We have an owner, now see if we need to change this call [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:10700 process_sdp: Setting native formats after processing SDP. peer joint formats (g722), old nativeformats (g722) [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for outgoing call [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 set_destination: Parsing for address/port to send to [May 7 16:04:46] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:46] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. set_destination: set destination to 192.168.2.225:51166 Transmitting (NAT) to 89.209.99.97:54787: ACK sip:linphone.iphone@192.168.2.225:51166 SIP/2.0 Via: SIP/2.0/TCP 209.239.114.51:5060;branch=z9hG4bK02e34368;rport Max-Forwards: 70 From: "Doctor" ;tag=as573d8290 To: ;tag=2128546057 Contact: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 105 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:46] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:lin' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:46] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from UDP:89.209.99.97:5060 ---> ACK sip:6000444@209.239.114.51:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1564077610 From: ;tag=1082013176 To: ;tag=as08ba5b0e Call-ID: 1852355859 CSeq: 22 ACK Contact: Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 43]: ACK sip:6000444@209.239.114.51:5060 SIP/2.0 [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.2.144:5060;rport;branch=z9hG4bK1564077610 [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=1082013176 [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=as08ba5b0e [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 12]: CSeq: 22 ACK [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 16]: Max-Forwards: 70 [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 7 16:04:46] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking From) --From tag 1082013176 --To-tag as08ba5b0e [May 7 16:04:46] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:46] DEBUG[1815][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 7 16:04:46] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from TCP:89.209.99.97:54787 ---> BYE sip:6000333@209.239.114.51:5060;transport=TCP SIP/2.0 Via: SIP/2.0/TCP 192.168.2.225:51166;rport;branch=z9hG4bK728276598 From: ;tag=2128546057 To: "Doctor" ;tag=as573d8290 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 2 BYE Contact: Max-Forwards: 70 User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 0 [ 57]: BYE sip:6000333@209.239.114.51:5060;transport=TCP SIP/2.0 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 1 [ 66]: Via: SIP/2.0/TCP 192.168.2.225:51166;rport;branch=z9hG4bK728276598 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 2 [ 88]: From: ;tag=2128546057 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 3 [ 56]: To: "Doctor" ;tag=as573d8290 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 4 [ 61]: Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 5 [ 11]: CSeq: 2 BYE [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 6 [ 56]: Contact: [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 7 [ 16]: Max-Forwards: 70 [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9578 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 7 16:04:50] DEBUG[9776]: chan_sip.c:9128 find_call: = Looking for Call ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 (Checking From) --From tag 2128546057 --To-tag as573d8290 [May 7 16:04:50] DEBUG[9776][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:27928 handle_incoming: **** Received BYE (8) - Command in SIP BYE [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:26463 handle_request_bye: Initializing initreq for method BYE - callid 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:50] DEBUG[9776][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.225:51166' into... [May 7 16:04:50] DEBUG[9776][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.225' and port '51166'. [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:17908 check_via: NAT detected for 192.168.2.225:51166 / 89.209.99.97:54787 Sending to 89.209.99.97:54787 (NAT) [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:3525 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:50] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd800ef48' [May 7 16:04:50] DEBUG[9776][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' Scheduling destruction of SIP dialog '4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060' in 15040 ms (Method: BYE) [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:26565 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 89.209.99.97:54787 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.2.225:51166;branch=z9hG4bK728276598;received=89.209.99.97;rport=54787 From: ;tag=2128546057 To: "Doctor" ;tag=as573d8290 Call-ID: 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 CSeq: 2 BYE Server: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [May 7 16:04:50] DEBUG[9776][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto TCP socket destined for 89.209.99.97:54787 [May 7 16:04:50] DEBUG[9776][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:50] DEBUG[9780][C-00000294]: rtp_engine.c:1315 remote_bridge_loop: Oooh, got a hangup [May 7 16:04:50] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3850 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7fdb9426cab8' [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '209.239.114.51' into... [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '209.239.114.51' and port ''. [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:32500 sip_set_rtp_peer: Sending reinvite on SIP '1852355859' - It's audio soon redirected to IP 209.239.114.51:5060 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 1852355859 set_destination: Parsing for address/port to send to [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:50] DEBUG[9780][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. set_destination: set destination to 89.209.99.97:5060 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:13034 add_sdp: This call needs video offers! [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:13084 add_sdp: ** Our capability: (g722|h264) Video flag: False Text flag: True [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:13085 add_sdp: ** Our prefcodec: (nothing) Audio is at 16500 Video is at 209.239.114.51:13174 Adding codec 100012 (g722) to SDP Adding video codec 200004 (h264) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:13222 add_sdp: -- Done with adding codecs to SDP [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:13420 add_sdp: Done building SDP. Settling with this capability: (g722|h264) [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:3510 initialize_initreq: Initializing already initialized SIP dialog 1852355859 (presumably reinvite) [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 0 [ 39]: INVITE sip:6000333@89.209.99.97 SIP/2.0 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 3 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 4 [ 48]: To: ;tag=1082013176 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 5 [ 42]: Contact: [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 6 [ 19]: Call-ID: 1852355859 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 7 [ 16]: CSeq: 103 INVITE [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 8 [ 30]: User-Agent: Video Medicine PBX [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 9 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 10 [ 26]: Supported: replaces, timer [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:9578 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 89.209.99.97:5060: INVITE sip:6000333@89.209.99.97 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport Max-Forwards: 70 From: ;tag=as08ba5b0e To: ;tag=1082013176 Contact: Call-ID: 1852355859 CSeq: 103 INVITE User-Agent: Video Medicine PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 1118 v=0 o=root 379716584 379716587 IN IP4 209.239.114.51 s=Asterisk PBX 11.3.0 c=IN IP4 209.239.114.51 b=CT:384 t=0 0 m=audio 16500 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=ice-ufrag:78154d5622241dca7692083e7561fd64 a=ice-pwd:29f912b0324cefdc0470a3d43a125b9b a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 16500 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 16500 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 16501 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 16500 typ srflx a=sendrecv m=video 13174 RTP/AVP 102 a=ice-ufrag:0198525a2e8521b519453f21005ac06f a=ice-pwd:49fef0b25eb6a5670c265c4f3587b6f7 a=candidate:Hd1ef7233 1 UDP 2130706431 209.239.114.51 13174 typ host a=candidate:Sd1ef7233 1 UDP 1694498815 209.239.114.51 13174 typ srflx a=candidate:Hd1ef7233 2 UDP 2130706430 209.239.114.51 13175 typ host a=candidate:Sd1ef7233 2 UDP 1694498814 209.239.114.51 13174 typ srflx a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014 a=sendrecv --- [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42572 [May 7 16:04:50] DEBUG[9780][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:50] DEBUG[9780][C-00000294]: channel.c:7967 ast_channel_bridge: Returning from native bridge, channels: SIP/6000333-00000093, SIP/6000444-00000094 [May 7 16:04:50] DEBUG[9780][C-00000294]: cdr_mysql.c:336 mysql_log: Inserting a CDR record. [May 7 16:04:50] DEBUG[9780][C-00000294]: cdr_mysql.c:339 mysql_log: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`channel`,`dstchannel`,`amaflags`,`uniqueid`,`answer`,`end`) VALUES ('2013-05-07 16:04:35','\"Doctor\" <6000333>','6000333','6000444','webrtc','Dial','SIP/6000444,20,S(600)','14.987222','12.277037','ANSWERED','SIP/6000333-00000093','SIP/6000444-00000094','DOCUMENTATION','1367942675.148','2013-05-07 16:04:38','2013-05-07 16:04:50') [May 7 16:04:51] DEBUG[9780][C-00000294]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/6000444-00000094' [May 7 16:04:51] DEBUG[9780][C-00000294]: chan_sip.c:7054 sip_hangup: Hangup call SIP/6000444-00000094, SIP callid 4e5c2ca475627ed636e28a854fc7a3dd@209.239.114.51:5060 [May 7 16:04:51] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd800ef48' [May 7 16:04:51] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdbd80285c8' [May 7 16:04:51] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000444 [May 7 16:04:51] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000444 [May 7 16:04:51] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000444 - state 1 (Not in use) [May 7 16:04:51] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000444' state '1' [May 7 16:04:51] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000444' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 7 16:04:51] DEBUG[9780][C-00000294]: app_dial.c:3100 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [May 7 16:04:51] DEBUG[9780][C-00000294]: pbx.c:6316 __ast_pbx_run: Spawn extension (webrtc,6000444,2) exited non-zero on 'SIP/6000333-00000093' == Spawn extension (webrtc, 6000444, 2) exited non-zero on 'SIP/6000333-00000093' [May 7 16:04:51] DEBUG[9780][C-00000294]: channel.c:2661 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/6000333-00000093' [May 7 16:04:51] DEBUG[9780][C-00000294]: channel.c:2840 ast_hangup: Hanging up channel 'SIP/6000333-00000093' [May 7 16:04:51] DEBUG[9780][C-00000294]: chan_sip.c:7054 sip_hangup: Hangup call SIP/6000333-00000093, SIP callid 1852355859 [May 7 16:04:51] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb9426cab8' [May 7 16:04:51] DEBUG[9780][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb942ea4a8' Scheduling destruction of SIP dialog '1852355859' in 11392 ms (Method: ACK) [May 7 16:04:51] DEBUG[1802]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 6000333 [May 7 16:04:51] DEBUG[1802]: chan_sip.c:29365 sip_devicestate: Checking device state for peer 6000333 [May 7 16:04:51] DEBUG[1802]: devicestate.c:467 do_state_change: Changing state for SIP/6000333 - state 1 (Not in use) [May 7 16:04:51] DEBUG[1802]: devicestate.c:442 devstate_event: device 'SIP/6000333' state '1' [May 7 16:04:51] DEBUG[1843]: app_queue.c:1804 handle_statechange: Device 'SIP/6000333' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:89.209.99.97:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport=5060 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 103 INVITE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport=5060 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=1082013176 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking To) --From tag as08ba5b0e --To-tag 1082013176 [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4595 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #42572 - INVITE (got response) [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4602 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1852355859' Request 103: Found [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 100 to RE-invite on outgoing call 1852355859 [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from UDP:89.209.99.97:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport=5060 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 103 INVITE Contact: Content-Type: application/sdp User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 285 v=0 o=6000333 3649 1927 IN IP4 192.168.2.144 s=Talk c=IN IP4 192.168.2.144 b=AS:380 t=0 0 m=audio 7076 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 m=video 9078 RTP/AVP 102 a=rtpmap:102 H264/90000 a=fmtp:102 profile-level-id=428014 <-------------> [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK17f3e256;rport=5060 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=1082013176 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 35]: Contact: [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 29]: Content-Type: application/sdp [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 8 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 9 [ 19]: Content-Length: 285 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 10 [ 0]: [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 0 [ 3]: v=0 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 1 [ 40]: o=6000333 3649 1927 IN IP4 192.168.2.144 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 2 [ 6]: s=Talk [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 3 [ 22]: c=IN IP4 192.168.2.144 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 4 [ 8]: b=AS:380 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 5 [ 5]: t=0 0 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 6 [ 26]: m=audio 7076 RTP/AVP 9 101 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 7 [ 20]: a=rtpmap:9 G722/8000 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 9 [ 15]: a=fmtp:101 0-11 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 10 [ 24]: m=video 9078 RTP/AVP 102 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Body 11 [ 23]: a=rtpmap:102 H264/90000 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9615 parse_request: Body 12 [ 34]: a=fmtp:102 profile-level-id=428014 --- (10 headers 13 lines) --- [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking To) --From tag as08ba5b0e --To-tag 1082013176 [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4523 __sip_ack: Acked pending invite 103 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Request 103: Match Found [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:22416 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1852355859 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP o=6000333 3649 1927 IN IP4 192.168.2.144... OK. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.2.144' into... [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.2.144' and port ''. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP c=IN IP4 192.168.2.144... OK. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP b=AS:380... UNSUPPORTED OR FAILED. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10010 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x7fdba6c0db50 Found RTP audio format 101 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7fdba6c0db50 Found audio description format G722 for ID 9 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format telephone-event for ID 101 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. Found RTP video format 102 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 102 based on m type on 0x7fdba6c11ea0 Found video description format H264 for ID 102 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (video) SDP a=rtpmap:102 H264/90000... OK. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10416 process_sdp: Processing media-level (video) SDP a=fmtp:102 profile-level-id=428014... OK. Capabilities: us - (ulaw|g729|g722|h263|h264), peer - audio=(g722)/video=(h264)/text=(nothing), combined - (g722|h264) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [May 7 16:04:51] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb9426cab8' Peer audio RTP is at port 192.168.2.144:7076 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x7fdba6c0db50 to 0x7fdb9426cc80 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x7fdba6c0db50 to 0x7fdb9426cc80 [May 7 16:04:51] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3816 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fdb9426cab8' Peer video RTP is at port 192.168.2.144:9078 [May 7 16:04:51] DEBUG[1815][C-00000294]: rtp_engine.c:515 ast_rtp_codecs_payloads_copy: Copying payload 102 from 0x7fdba6c11ea0 to 0x7fdb942896e0 [May 7 16:04:51] DEBUG[1815][C-00000294]: res_rtp_asterisk.c:3895 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7fdb942ea4a8' Peer doesn't provide T.140 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:10687 process_sdp: We're settling with these formats: (g722|h264) [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:6674 update_call_counter: Updating call counter for incoming call [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 1852355859 set_destination: Parsing for address/port to send to [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. set_destination: set destination to 89.209.99.97:5060 Transmitting (NAT) to 89.209.99.97:5060: ACK sip:6000333@89.209.99.97 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK6cc44688;rport Max-Forwards: 70 From: ;tag=as08ba5b0e To: ;tag=1082013176 Contact: Call-ID: 1852355859 CSeq: 103 ACK User-Agent: Video Medicine PBX Content-Length: 0 --- [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'ACK sip:600' onto UDP socket destined for 89.209.99.97:5060 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:11832 reqprep: Strict routing enforced for session 1852355859 set_destination: Parsing for address/port to send to [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '89.209.99.97' into... [May 7 16:04:51] DEBUG[1815][C-00000294]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '89.209.99.97' and port ''. set_destination: set destination to 89.209.99.97:5060 Reliably Transmitting (NAT) to 89.209.99.97:5060: BYE sip:6000333@89.209.99.97 SIP/2.0 Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK751d07ea;rport Max-Forwards: 70 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 104 BYE User-Agent: Video Medicine PBX Proxy-Authorization: Digest username="6000333", realm="vm.intersog.com", algorithm=MD5, uri="sip:vm.intersog.com", nonce="0fd4b31a", response="8ee2cc2db6248ffbd442c2445cd63d4d" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4329 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #42575 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:3869 __sip_xmit: Trying to put 'BYE sip:600' onto UDP socket destined for 89.209.99.97:5060 Scheduling destruction of SIP dialog '1852355859' in 11392 ms (Method: ACK) [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. <--- SIP read from UDP:89.209.99.97:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK751d07ea;rport=5060 From: ;tag=as08ba5b0e To: ;tag=1082013176 Call-ID: 1852355859 CSeq: 104 BYE User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) Content-Length: 0 <-------------> [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP 209.239.114.51:5060;branch=z9hG4bK751d07ea;rport=5060 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 2 [ 50]: From: ;tag=as08ba5b0e [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 3 [ 48]: To: ;tag=1082013176 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 4 [ 19]: Call-ID: 1852355859 [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 5 [ 13]: CSeq: 104 BYE [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 6 [ 48]: User-Agent: LinphoneIPhone/2.0.2 (eXosip2/3.6.0) [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9578 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9128 find_call: = Looking for Call ID: 1852355859 (Checking To) --From tag as08ba5b0e --To-tag 1082013176 [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1332 ast_callid_threadassoc_add: CALL_ID [C-00000294] bound to thread. [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4528 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42575 [May 7 16:04:51] DEBUG[1815][C-00000294]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '1852355859' of Request 104: Match Found [May 7 16:04:51] DEBUG[1815][C-00000294]: logger.c:1354 ast_callid_threadassoc_remove: Call_ID [C-00000294] being removed from thread. [May 7 16:04:51] DEBUG[1815]: chan_sip.c:6822 sip_destroy: Destroying SIP dialog 1852355859 Really destroying SIP dialog '1852355859' Method: ACK [May 7 16:04:51] DEBUG[1815]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x7fdb9426cab8' [May 7 16:04:51] DEBUG[1815]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x7fdb94289518' [May 7 16:04:51] DEBUG[1815]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0x7fdb942ea4a8' <--- SIP read from UDP:89.209.99.97:5060 ---> jaK <-------------> [May 7 16:04:51] DEBUG[1815]: chan_sip.c:9615 parse_request: Header 0 [ 3]: jaK [May 7 16:04:54]