[Mar 28 13:26:59] Asterisk SVN-branch-1.8-r360625, Copyright (C) 1999 - 2012 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= [Mar 28 13:26:59] Connected to Asterisk SVN-branch-1.8-r360625 currently running on fsdev (pid = 2851) fsdev*CLI> Verbosity is at least 10 Core debug is at least 10 fsdev*CLI> [Mar 28 13:26:59] DEBUG[2856]: chan_sip.c:3575 retrans_pkt: SIP TIMER: Not rescheduling id #7601:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (no NAT) to 64.19.145.20:5060: OPTIONS sip:64.19.145.20 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK7aa9af00 Max-Forwards: 70 From: "unknown" ;tag=as3b2f21b1 To: Contact: Call-ID: 5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:26:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:26:59] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.20:5060 fsdev*CLI> [Mar 28 13:27:00] DEBUG[2856]: chan_sip.c:3575 retrans_pkt: SIP TIMER: Not rescheduling id #7601:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (no NAT) to 64.19.145.20:5060: OPTIONS sip:64.19.145.20 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK7aa9af00 Max-Forwards: 70 From: "unknown" ;tag=as3b2f21b1 To: Contact: Call-ID: 5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:26:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:27:00] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.20:5060 fsdev*CLI>  <--- SIP read from UDP:209.191.13.6:5063 ---> INVITE sip:*55@64.19.145.13 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-85da0e98 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: Call-ID: 6936fca8-1df900d8@localhost CSeq: 101 INVITE Max-Forwards: 70 Contact: "Anonymous" Expires: 240 User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 399 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 189153 189153 IN IP4 192.168.15.187 s=- c=IN IP4 192.168.15.187 t=0 0 m=audio 16478 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 35]: INVITE sip:*55@64.19.145.13 SIP/2.0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-85da0e98 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "Anonymous" ;tag=7eab4a68447b0e18o3 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 26]: To: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 36]: Call-ID: 6936fca8-1df900d8@localhost [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 16]: CSeq: 101 INVITE [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 54]: Contact: "Anonymous" [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 12]: Expires: 240 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: User-Agent: Linksys/SPA942-6.1.5(a) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 19]: Content-Length: 399 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 12 [ 19]: Supported: replaces [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 14 [ 0]: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 0 [ 3]: v=0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 1 [ 39]: o=- 189153 189153 IN IP4 192.168.15.187 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 2 [ 3]: s=- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 3 [ 23]: c=IN IP4 192.168.15.187 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 4 [ 5]: t=0 0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 5 [ 45]: m=audio 16478 RTP/AVP 0 2 4 8 18 96 97 98 101 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 16 [ 10]: a=ptime:20 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8533 parse_request: Body 17 [ 10]: a=sendrecv --- (14 headers 18 lines) --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 6936fca8-1df900d8@localhost (Checking From) --From tag 7eab4a68447b0e18o3 --To-tag [Mar 28 13:27:01] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '209.191.13.6', our source address is '64.19.145.13'. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 6936fca8-1df900d8@localhost - INVITE (No RTP) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Mar 28 13:27:01] DEBUG[2856]: sip/reqresp_parser.c:1647 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Mar 28 13:27:01] DEBUG[2856]: sip/reqresp_parser.c:1663 parse_sip_options: Found SIP option: -replaces- [Mar 28 13:27:01] DEBUG[2856]: sip/reqresp_parser.c:1671 parse_sip_options: Matched SIP option: replaces [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.15.187:5063' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.15.187' and port '5063'. Sending to 209.191.13.6:5063 (NAT) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:22482 handle_request_invite: Initializing initreq for method INVITE - callid 6936fca8-1df900d8@localhost Using INVITE request as basis request - 6936fca8-1df900d8@localhost [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. Found peer '175-eng' for '175-eng' from 209.191.13.6:5063 <--- Reliably Transmitting (NAT) to 209.191.13.6:5063 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-85da0e98;received=209.191.13.6;rport=5063 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as5b215695 Call-ID: 6936fca8-1df900d8@localhost CSeq: 101 INVITE Server: Asterisk PBX SVN-branch-1.8-r360625 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5be3d74c" Content-Length: 0 <------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7603 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 209.191.13.6:5063 Scheduling destruction of SIP dialog '6936fca8-1df900d8@localhost' in 32000 ms (Method: INVITE) fsdev*CLI>  <--- SIP read from UDP:209.191.13.6:5063 ---> ACK sip:*55@64.19.145.13 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-85da0e98 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as5b215695 Call-ID: 6936fca8-1df900d8@localhost CSeq: 101 ACK Max-Forwards: 70 Contact: "Anonymous" User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 0 <-------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: ACK sip:*55@64.19.145.13 SIP/2.0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-85da0e98 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "Anonymous" ;tag=7eab4a68447b0e18o3 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 41]: To: ;tag=as5b215695 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 36]: Call-ID: 6936fca8-1df900d8@localhost [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 13]: CSeq: 101 ACK [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 54]: Contact: "Anonymous" [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 35]: User-Agent: Linksys/SPA942-6.1.5(a) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 6936fca8-1df900d8@localhost (Checking From) --From tag 7eab4a68447b0e18o3 --To-tag as5b215695 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7603 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '6936fca8-1df900d8@localhost' of Response 101: Match Found fsdev*CLI>  <--- SIP read from UDP:209.191.13.6:5063 ---> INVITE sip:*55@64.19.145.13 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d851796c From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: Call-ID: 6936fca8-1df900d8@localhost CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13",algorithm=MD5,response="e2da7c774169cb398e1e245f54dc1436" Contact: "Anonymous" Expires: 240 User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 399 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 189153 189153 IN IP4 192.168.15.187 s=- c=IN IP4 192.168.15.187 t=0 0 m=audio 16478 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 35]: INVITE sip:*55@64.19.145.13 SIP/2.0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d851796c [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "Anonymous" ;tag=7eab4a68447b0e18o3 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 26]: To: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 36]: Call-ID: 6936fca8-1df900d8@localhost [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [159]: Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13",algorithm=MD5,response="e2da7c774169cb398e1e245f54dc1436" [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 54]: Contact: "Anonymous" [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 12]: Expires: 240 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 35]: User-Agent: Linksys/SPA942-6.1.5(a) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Content-Length: 399 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 13 [ 19]: Supported: replaces [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 14 [ 29]: Content-Type: application/sdp [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 15 [ 0]: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 0 [ 3]: v=0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 1 [ 39]: o=- 189153 189153 IN IP4 192.168.15.187 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 2 [ 3]: s=- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 3 [ 23]: c=IN IP4 192.168.15.187 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 4 [ 5]: t=0 0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 5 [ 45]: m=audio 16478 RTP/AVP 0 2 4 8 18 96 97 98 101 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 16 [ 10]: a=ptime:20 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8533 parse_request: Body 17 [ 10]: a=sendrecv --- (15 headers 18 lines) --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 6936fca8-1df900d8@localhost (Checking From) --From tag 7eab4a68447b0e18o3 --To-tag [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.15.187:5063' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.15.187' and port '5063'. Sending to 209.191.13.6:5063 (NAT) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:22482 handle_request_invite: Initializing initreq for method INVITE - callid 6936fca8-1df900d8@localhost Using INVITE request as basis request - 6936fca8-1df900d8@localhost [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. Found peer '175-eng' for '175-eng' from 209.191.13.6:5063 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb6c88260' [Mar 28 13:27:01] DEBUG[2856]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 17126 for RTP instance '0xb6c88260' [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0xb6c88260' is setup and ready to go [Mar 28 13:27:01] DEBUG[2856]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb6c88260' == Using SIP RTP CoS mark 5 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to On [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP o=- 189153 189153 IN IP4 192.168.15.187... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP s=-... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.15.187' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.15.187' and port ''. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP c=IN IP4 192.168.15.187... OK. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 0 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0xb78fa440 Found RTP audio format 2 Found RTP audio format 4 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 4 based on m type on 0xb78fa440 Found RTP audio format 8 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0xb78fa440 Found RTP audio format 18 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0xb78fa440 Found RTP audio format 96 Found RTP audio format 97 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 97 based on m type on 0xb78fa440 Found RTP audio format 98 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 98 based on m type on 0xb78fa440 Found RTP audio format 101 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0xb78fa440 Found audio description format PCMU for ID 0 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format G726-32 for ID 2 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. Found audio description format G723 for ID 4 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. Found audio description format PCMA for ID 8 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format G729a for ID 18 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:604 ast_rtp_codecs_payloads_unset: Unsetting payload 96 on 0xb78fa440 Found unknown media description format G726-40 for ID 96 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:604 ast_rtp_codecs_payloads_unset: Unsetting payload 97 on 0xb78fa440 Found unknown media description format G726-24 for ID 97 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:604 ast_rtp_codecs_payloads_unset: Unsetting payload 98 on 0xb78fa440 fsdev*CLI> Found unknown media description format G726-16 for ID 98 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. Found audio description format telephone-event for ID 101 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0xb78fa440 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 2 on 0xb78fa440 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 4 on 0xb78fa440 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0xb78fa440 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0xb78fa440 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0xb78fa440 Capabilities: us - 0x4 (ulaw), peer - audio=0x90d (g723|ulaw|alaw|g726|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x1 (telephone-event|), combined - 0x0 (nothing) [Mar 28 13:27:01] DEBUG[2856]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb6c88260' Peer audio RTP is at port 192.168.15.187:16478 [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 2 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 4 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0xb78fa440 to 0xb6c8840c [Mar 28 13:27:01] DEBUG[2856]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xb6c88260' [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:9354 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:22619 handle_request_invite: Checking SIP call limits for device 175-eng [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:5900 update_call_counter: Updating call counter for incoming call [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... [Mar 28 13:27:01] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. Looking for *55 in page (domain 64.19.145.13) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7070 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7071 sip_new: *** Joint capabilities are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7072 sip_new: *** Our capabilities are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7073 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:7103 sip_new: This channel will not be able to handle video. [Mar 28 13:27:01] DEBUG[2856]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 28 13:27:01] DEBUG[2856]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:14244 build_route: build_route: Contact hop: "Anonymous" list_route: hop: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:22918 handle_request_invite: SIP/175-eng-0000000c: New call is still down.... Trying... <--- Transmitting (NAT) to 209.191.13.6:5063 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d851796c;received=209.191.13.6;rport=5063 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: Call-ID: 6936fca8-1df900d8@localhost CSeq: 102 INVITE Server: Asterisk PBX SVN-branch-1.8-r360625 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 209.191.13.6:5063 [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 175-eng [Mar 28 13:27:01] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 175-eng [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/175-eng - state 1 (Not in use) [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/175-eng' state '1' [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1485 handle_statechange: Device 'SIP/175-eng' changed to state '1' (Not in use) [Mar 28 13:27:01] DEBUG[3018]: pbx.c:4230 pbx_extension_helper: Launching 'SIPAddHeader' -- Executing [*55@page:1] SIPAddHeader("SIP/175-eng-0000000c", "Alert-Info: ") in new stack [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:29356 sip_addheader: SIP Header added "Alert-Info: " as __SIPADDHEADER01 [Mar 28 13:27:01] DEBUG[3018]: pbx.c:4230 pbx_extension_helper: Launching 'Page' -- Executing [*55@page:2] Page("SIP/175-eng-0000000c", "MulticastRTP/basic/209.191.39.117:34560&SIP/256-eng") in new stack [Mar 28 13:27:01] DEBUG[3018]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.39.117:34560' into... [Mar 28 13:27:01] DEBUG[3018]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.39.117' and port '34560'. [Mar 28 13:27:01] DEBUG[3018]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'multicast' for RTP instance '0xa82dae0' [Mar 28 13:27:01] DEBUG[3018]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0xa82dae0' is setup and ready to go [Mar 28 13:27:01] DEBUG[3018]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01. [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called basic/209.191.39.117:34560 [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:26461 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 3989e9b62343b03547d9aa9c03f8fb64@127.0.0.1:5060 - INVITE (No RTP) [Mar 28 13:27:01] DEBUG[3018]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xaf62748' [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 10514 for RTP instance '0xaf62748' [Mar 28 13:27:01] DEBUG[3018]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0xaf62748' is setup and ready to go [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0xaf62748' == Using SIP RTP CoS mark 5 [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to Off [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:3144 obproxy_get: OBPROXY: Not applying OBproxy to this call [Mar 28 13:27:01] DEBUG[3018]: acl.c:728 ast_ouraddrfor: For destination '209.191.39.117', our source address is '64.19.145.13'. [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7070 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7071 sip_new: *** Joint capabilities are 0x4 (ulaw) fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7072 sip_new: *** Our capabilities are 0x4 (ulaw) [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7073 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7075 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:7103 sip_new: This channel will not be able to handle video. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER01. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPCALLID. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPURI. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:5637 sip_call: Outgoing Call for 256-eng fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:5900 update_call_counter: Updating call counter for outgoing call fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:6005 update_call_counter: Call to peer '256-eng' is 1 out of 2147483647 fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 6 (Ringing) fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '6' fsdev*CLI> [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:12263 transmit_invite: Adding SIP Header "Alert-Info" with content :: fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:11344 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x4 (ulaw) fsdev*CLI> Audio is at 10514 fsdev*CLI> Adding codec 0x4 (ulaw) to SDP fsdev*CLI> Adding non-codec 0x1 (telephone-event) to SDP fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:11454 add_sdp: -- Done with adding codecs to SDP fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:11640 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method INVITE - callid 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 0 [ 72]: INVITE sip:256-eng@209.191.39.117:5060;adtnpxyid-1i2c6kcj=7jb6f2 SIP/2.0 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 3 [ 53]: From: "175" ;tag=as5cbf24d1 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 4 [ 63]: To: fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 7 [ 16]: CSeq: 102 INVITE fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:01 GMT fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 12 [ 25]: Alert-Info: fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:8496 parse_request: Header 13 [ 29]: Content-Type: application/sdp fsdev*CLI> Reliably Transmitting (no NAT) to 209.191.39.117:5060: INVITE sip:256-eng@209.191.39.117:5060;adtnpxyid-1i2c6kcj=7jb6f2 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 Max-Forwards: 70 From: "175" ;tag=as5cbf24d1 To: Contact: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:01 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Alert-Info: Content-Type: application/sdp Content-Length: 249 v=0 o=root 303575990 303575990 IN IP4 64.19.145.13 s=Asterisk PBX SVN-branch-1.8-r360625 c=IN IP4 64.19.145.13 t=0 0 m=audio 10514 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7606 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: chan_sip.c:3344 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 209.191.39.117:5060 fsdev*CLI>  -- Called 256-eng fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to ulaw fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:1253 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0xb6c88260' fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: channel.c:3506 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second fsdev*CLI>  -- Playing 'beep.ulaw' (language 'en') fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for MulticastRTP - 0xa82dae0 fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for MulticastRTP/0xa82dae0 - state 0 (Unknown) fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:438 devstate_event: device 'MulticastRTP/0xa82dae0' state '0' fsdev*CLI> [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'MulticastRTP/0xa82dae0' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. fsdev*CLI>  -- MulticastRTP/0xa82dae0 answered fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: app_meetme.c:4007 find_conf: The requested confno is '13577307d'? fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: app_meetme.c:4022 find_conf: Building dynamic conference '13577307d' fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: chan_dahdi.c:13589 dahdi_request: Using channel -2 fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for DAHDI/pseudo - state 2 (In use) fsdev*CLI> [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:438 devstate_event: device 'DAHDI/pseudo' state '2' fsdev*CLI> [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'DAHDI/pseudo' changed to state '2' (In use) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: channel.c:5171 set_format: Set channel DAHDI/pseudo-1014325463 to read format slin fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: channel.c:5171 set_format: Set channel DAHDI/pseudo-1014325463 to write format slin fsdev*CLI>  -- Created MeetMe conference 1023 for conference '13577307d' fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: devicestate.c:438 devstate_event: device 'meetme:13577307d' state '2' fsdev*CLI> [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'meetme:13577307d' changed to state '2' (In use) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: channel.c:5171 set_format: Set channel MulticastRTP/0xa82dae0 to write format slin fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: channel.c:5171 set_format: Set channel MulticastRTP/0xa82dae0 to read format slin fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: app_meetme.c:2683 conf_run: Placed channel MulticastRTP/0xa82dae0 in DAHDI conf 1023 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3019]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI>  <--- SIP read from UDP:209.191.39.117:5060 ---> SIP/2.0 100 Trying From: "175";tag=as5cbf24d1 To: "256";tag=58623014-D214389F Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 Contact: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 Accept-Language: en Content-Length: 0 fsdev*CLI> <-------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 52]: From: "175";tag=as5cbf24d1 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 90]: To: "256";tag=58623014-D214389F [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 59]: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 68]: Contact: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 19]: Accept-Language: en [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 (Checking To) --From tag as5cbf24d1 --To-tag 58623014-D214389F [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:4063 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #7606 - INVITE (got response) [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' Request 102: Found [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:19947 handle_response_invite: SIP response 100 to standard invite fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3575 retrans_pkt: SIP TIMER: Not rescheduling id #7601:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (no NAT) to 64.19.145.20:5060: OPTIONS sip:64.19.145.20 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK7aa9af00 Max-Forwards: 70 From: "unknown" ;tag=as3b2f21b1 To: Contact: Call-ID: 5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:26:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.20:5060 fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI>  <--- SIP read from UDP:209.191.39.117:5060 ---> SIP/2.0 180 Ringing From: "175";tag=as5cbf24d1 To: "256";tag=58623014-D214389F Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 Contact: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 Accept-Language: en Allow-Events: talk,hold,conference Content-Length: 0 <-------------> [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 52]: From: "175";tag=as5cbf24d1 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 90]: To: "256";tag=58623014-D214389F [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 59]: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 68]: Contact: [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 19]: Accept-Language: en [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 34]: Allow-Events: talk,hold,conference [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 (Checking To) --From tag as5cbf24d1 --To-tag 58623014-D214389F [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' Request 102: Found [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:19947 handle_response_invite: SIP response 180 to standard invite [Mar 28 13:27:01] DEBUG[2856]: chan_sip.c:14244 build_route: build_route: Contact hop: list_route: hop: [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng [Mar 28 13:27:01] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 6 (Ringing) [Mar 28 13:27:01] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '6' fsdev*CLI> [Mar 28 13:27:01] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- SIP/256-eng-0000000d is ringing fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:01] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 28 13:27:02] DEBUG[3018]: channel.c:3506 ast_settimeout: Scheduling timer at (182 requested / 182 actual) timer ticks per second fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 28 13:27:02] DEBUG[3018]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 28 13:27:02] DEBUG[3018]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:6474 sip_answer: SIP answering channel: SIP/175-eng-0000000c [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:11745 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:11344 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 17126 Adding codec 0x4 (ulaw) to SDP [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:11454 add_sdp: -- Done with adding codecs to SDP [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:11640 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 209.191.13.6:5063 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d851796c;received=209.191.13.6;rport=5063 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as20f6385e Call-ID: 6936fca8-1df900d8@localhost CSeq: 102 INVITE Server: Asterisk PBX SVN-branch-1.8-r360625 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Type: application/sdp Content-Length: 195 v=0 o=root 1753041491 1753041491 IN IP4 64.19.145.13 s=Asterisk PBX SVN-branch-1.8-r360625 c=IN IP4 64.19.145.13 t=0 0 m=audio 17126 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7609 [Mar 28 13:27:02] DEBUG[3018]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 209.191.13.6:5063 [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 175-eng [Mar 28 13:27:02] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 175-eng [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/175-eng - state 1 (Not in use) [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/175-eng' state '1' fsdev*CLI> [Mar 28 13:27:02] DEBUG[2883]: app_queue.c:1485 handle_statechange: Device 'SIP/175-eng' changed to state '1' (Not in use) fsdev*CLI>  <--- SIP read from UDP:209.191.13.6:5063 ---> ACK sip:*55@64.19.145.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d6a10b2c From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as20f6385e Call-ID: 6936fca8-1df900d8@localhost CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13",algorithm=MD5,response="e2da7c774169cb398e1e245f54dc1436" Contact: "Anonymous" User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 0 <-------------> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 37]: ACK sip:*55@64.19.145.13:5060 SIP/2.0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-d6a10b2c [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "Anonymous" ;tag=7eab4a68447b0e18o3 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 41]: To: ;tag=as20f6385e [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 36]: Call-ID: 6936fca8-1df900d8@localhost [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 13]: CSeq: 102 ACK [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [159]: Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13",algorithm=MD5,response="e2da7c774169cb398e1e245f54dc1436" [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 54]: Contact: "Anonymous" [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: User-Agent: Linksys/SPA942-6.1.5(a) [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 6936fca8-1df900d8@localhost (Checking From) --From tag 7eab4a68447b0e18o3 --To-tag as20f6385e [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7609 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '6936fca8-1df900d8@localhost' of Response 102: Match Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb6c88260' [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:2212 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 209.191.13.6:16478 [Mar 28 13:27:02] DEBUG[3018]: app_meetme.c:4007 find_conf: The requested confno is '13577307d'? fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: app_meetme.c:4010 find_conf: Does conf 13577307d match 13577307d? fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: channel.c:5171 set_format: Set channel SIP/175-eng-0000000c to write format slin fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: channel.c:5171 set_format: Set channel SIP/175-eng-0000000c to read format slin fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: app_meetme.c:2683 conf_run: Placed channel SIP/175-eng-0000000c in DAHDI conf 1023 fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 28 13:27:02] DEBUG[3018]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 fsdev*CLI> [Mar 28 13:27:02] DEBUG[3018]: res_rtp_asterisk.c:1174 ast_rtp_raw_write: Difference is 1112, ms is 159 fsdev*CLI>  <--- SIP read from UDP:209.191.39.117:5060 ---> SIP/2.0 200 OK From: "175";tag=as5cbf24d1 To: "256";tag=58623014-D214389F Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 Contact: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,MESSAGE,SUBSCRIBE,NOTIFY,PRACK,UPDATE,REFER Supported: 100rel Supported: replaces User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 Accept-Language: en Content-Type: application/sdp Content-Length: 204 v=0 o=- 1332955618 1332955618 IN IP4 209.191.39.117 s=Polycom IP Phone c=IN IP4 209.191.39.117 t=0 0 m=audio 50422 RTP/AVP 0 127 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:127 telephone-event/8000 <-------------> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 52]: From: "175";tag=as5cbf24d1 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 90]: To: "256";tag=58623014-D214389F [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 59]: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK316985a8 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 68]: Contact: [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 85]: Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,INFO,MESSAGE,SUBSCRIBE,NOTIFY,PRACK,UPDATE,REFER [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 17]: Supported: 100rel [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 19]: Supported: replaces [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Accept-Language: en [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 13 [ 19]: Content-Length: 204 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 14 [ 0]: [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 0 [ 3]: v=0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 1 [ 47]: o=- 1332955618 1332955618 IN IP4 209.191.39.117 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 2 [ 18]: s=Polycom IP Phone [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 3 [ 23]: c=IN IP4 209.191.39.117 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 4 [ 5]: t=0 0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 5 [ 27]: m=audio 50422 RTP/AVP 0 127 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 6 [ 10]: a=sendrecv [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8533 parse_request: Body 8 [ 33]: a=rtpmap:127 telephone-event/8000 --- (14 headers 9 lines) --- [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 (Checking To) --From tag as5cbf24d1 --To-tag 58623014-D214389F [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3991 __sip_ack: Acked pending invite 102 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' of Request 102: Match Found [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:19947 handle_response_invite: SIP response 200 to standard invite [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP o=- 1332955618 1332955618 IN IP4 209.191.39.117... UNSUPPORTED. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED. [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.39.117' into... [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.39.117' and port ''. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP c=IN IP4 209.191.39.117... OK. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8891 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 0 [Mar 28 13:27:02] DEBUG[2856]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0xb78fa110 Found RTP audio format 127 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Found audio description format PCMU for ID 0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format telephone-event for ID 127 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:127 telephone-event/8000... OK. [Mar 28 13:27:02] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0xb78fa110 [Mar 28 13:27:02] DEBUG[2856]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 127 on 0xb78fa110 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Mar 28 13:27:02] DEBUG[2856]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xaf62748' Peer audio RTP is at port 209.191.39.117:50422 [Mar 28 13:27:02] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0xb78fa110 to 0xaf628f4 [Mar 28 13:27:02] DEBUG[2856]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 127 from 0xb78fa110 to 0xaf628f4 [Mar 28 13:27:02] DEBUG[2856]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xaf62748' [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:9354 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:9359 process_sdp: We have an owner, now see if we need to change this call [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:5900 update_call_counter: Updating call counter for outgoing call [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:14244 build_route: build_route: Contact hop: list_route: hop: [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.39.117:5060' into... [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.39.117' and port '5060'. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:10327 reqprep: Strict routing enforced for session 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 set_destination: Parsing for address/port to send to [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.39.117:5060' into... [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.39.117' and port '5060'. set_destination: set destination to 209.191.39.117:5060 Transmitting (no NAT) to 209.191.39.117:5060: ACK sip:256-eng@209.191.39.117:5060;adtnpxyid-1i2c6kcj=7jb6f2 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK3dc16bb2 Max-Forwards: 70 From: "175" ;tag=as5cbf24d1 To: ;tag=58623014-D214389F Contact: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Content-Length: 0 --- [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'ACK sip:256' onto UDP socket destined for 209.191.39.117:5060 -- SIP/256-eng-0000000d answered [Mar 28 13:27:02] DEBUG[3020]: app_meetme.c:4007 find_conf: The requested confno is '13577307d'? [Mar 28 13:27:02] DEBUG[3020]: app_meetme.c:4010 find_conf: Does conf 13577307d match 13577307d? [Mar 28 13:27:02] DEBUG[3020]: channel.c:5171 set_format: Set channel SIP/256-eng-0000000d to write format slin [Mar 28 13:27:02] DEBUG[3020]: channel.c:5171 set_format: Set channel SIP/256-eng-0000000d to read format slin [Mar 28 13:27:02] DEBUG[3020]: app_meetme.c:2683 conf_run: Placed channel SIP/256-eng-0000000d in DAHDI conf 1023 [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng [Mar 28 13:27:02] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 2 (In use) [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '2' [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng [Mar 28 13:27:02] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 2 (In use) [Mar 28 13:27:02] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '2' [Mar 28 13:27:02] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 28 13:27:02] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 28 13:27:02] DEBUG[3020]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 28 13:27:02] DEBUG[3020]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 fsdev*CLI> [Mar 28 13:27:02] DEBUG[3020]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to ulaw fsdev*CLI> [Mar 28 13:27:02] DEBUG[3020]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 fsdev*CLI> [Mar 28 13:27:02] DEBUG[3020]: res_rtp_asterisk.c:1253 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0xaf62748' fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 2cbfd4852055391a42abf6b2123dcaed@127.0.0.1:5060 - OPTIONS (No RTP) [Mar 28 13:27:02] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '64.19.145.18', our source address is '64.19.145.13'. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: OPTIONS sip:64.19.145.18 SIP/2.0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK53cde96a [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 57]: From: "unknown" ;tag=as08bd0728 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 22]: To: fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:02 GMT fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces Reliably Transmitting (no NAT) to 64.19.145.18:5060: OPTIONS sip:64.19.145.18 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK53cde96a Max-Forwards: 70 From: "unknown" ;tag=as08bd0728 To: Contact: Call-ID: 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:02 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7611 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.18:5060 <--- SIP read from UDP:64.19.145.18:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK53cde96a;received=64.19.145.13 From: "unknown" ;tag=as08bd0728 To: ;tag=as116aafc5 Call-ID: 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.6.1-r230383M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Accept: application/sdp Content-Length: 0 <-------------> fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 21]: SIP/2.0 404 Not Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK53cde96a;received=64.19.145.13 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 57]: From: "unknown" ;tag=as08bd0728 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 37]: To: ;tag=as116aafc5 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 59]: Call-ID: 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 46]: Server: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 23]: Accept: application/sdp fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 fsdev*CLI> --- (11 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 (Checking To) --From tag as08bd0728 --To-tag as116aafc5 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7611 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '01261518144cabbf09ed849359f4125f@64.19.145.13:5060' of Request 102: Match Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 01261518144cabbf09ed849359f4125f@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '01261518144cabbf09ed849359f4125f@64.19.145.13:5060' Method: OPTIONS fsdev*CLI>  <--- SIP read from UDP:209.191.44.130:5060 ---> OPTIONS sip:64.19.145.13 SIP/2.0 Via: SIP/2.0/UDP 209.191.44.130:5060;branch=z9hG4bK26c18261;rport Max-Forwards: 70 From: "asterisk" ;tag=as0920ca3d To: Contact: Call-ID: 218f969c5a847c800148a72c53785e86@209.191.44.130 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.6.1-r230383M Date: Wed, 28 Mar 2012 17:27:02 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <-------------> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: OPTIONS sip:64.19.145.13 SIP/2.0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 209.191.44.130:5060;branch=z9hG4bK26c18261;rport [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as0920ca3d [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 22]: To: [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 38]: Contact: [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 56]: Call-ID: 218f969c5a847c800148a72c53785e86@209.191.44.130 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 50]: User-Agent: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:02 GMT [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 12 [ 17]: Content-Length: 0 fsdev*CLI> --- (13 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 218f969c5a847c800148a72c53785e86@209.191.44.130 (Checking From) --From tag as0920ca3d --To-tag fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '209.191.44.130', our source address is '64.19.145.13'. fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 218f969c5a847c800148a72c53785e86@209.191.44.130 - OPTIONS (No RTP) fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '64.19.145.13' into... fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '64.19.145.13' and port ''. fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.44.130' into... fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.44.130' and port ''. fsdev*CLI> Looking for s in from-outside (domain 64.19.145.13) fsdev*CLI>  <--- Transmitting (NAT) to 209.191.44.130:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 209.191.44.130:5060;branch=z9hG4bK26c18261;received=209.191.44.130;rport=5060 From: "asterisk" ;tag=as0920ca3d To: ;tag=as634374ad Call-ID: 218f969c5a847c800148a72c53785e86@209.191.44.130 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.8-r360625 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 209.191.44.130:5060 fsdev*CLI> Scheduling destruction of SIP dialog '218f969c5a847c800148a72c53785e86@209.191.44.130' in 32000 ms (Method: OPTIONS) fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 4f6f005775dcf6183181a9ee75552977@127.0.0.1:5060 - OPTIONS (No RTP) [Mar 28 13:27:02] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '64.19.145.15', our source address is '64.19.145.13'. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: OPTIONS sip:64.19.145.15 SIP/2.0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK071756cb [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 57]: From: "unknown" ;tag=as69f9987b fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 22]: To: [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:02 GMT fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces Reliably Transmitting (no NAT) to 64.19.145.15:5060: OPTIONS sip:64.19.145.15 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK071756cb Max-Forwards: 70 From: "unknown" ;tag=as69f9987b To: Contact: Call-ID: 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:02 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7615 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.15:5060 <--- SIP read from UDP:64.19.145.15:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK071756cb;received=64.19.145.13 From: "unknown" ;tag=as69f9987b To: ;tag=as419545dc Call-ID: 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.6.1-r230383M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Accept: application/sdp Content-Length: 0 <-------------> fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 21]: SIP/2.0 404 Not Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK071756cb;received=64.19.145.13 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 57]: From: "unknown" ;tag=as69f9987b fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 37]: To: ;tag=as419545dc fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 59]: Call-ID: 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 46]: Server: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 23]: Accept: application/sdp fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 fsdev*CLI> --- (11 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 (Checking To) --From tag as69f9987b --To-tag as419545dc fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7615 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060' of Request 102: Match Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '011e6a7b1597d4f00f05780d63c04f2c@64.19.145.13:5060' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3575 retrans_pkt: SIP TIMER: Not rescheduling id #7601:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (no NAT) to 64.19.145.20:5060: OPTIONS sip:64.19.145.20 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK7aa9af00 Max-Forwards: 70 From: "unknown" ;tag=as3b2f21b1 To: Contact: Call-ID: 5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:26:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.20:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '5286b78f47ec57355a5dd7b2409ed76b@64.19.145.13:5060' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 4f71562c4be8acfc1c0336a61969f06f@127.0.0.1:5060 - OPTIONS (No RTP) [Mar 28 13:27:02] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '64.19.145.7', our source address is '64.19.145.13'. [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 31]: OPTIONS sip:64.19.145.7 SIP/2.0 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK13399b53;rport [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 57]: From: "unknown" ;tag=as77e66d07 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 21]: To: fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:02 GMT fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces fsdev*CLI> Reliably Transmitting (NAT) to 64.19.145.7:5060: OPTIONS sip:64.19.145.7 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK13399b53;rport Max-Forwards: 70 From: "unknown" ;tag=as77e66d07 To: Contact: Call-ID: 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:02 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7619 [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.7:5060 <--- SIP read from UDP:64.19.145.7:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK13399b53;received=64.19.145.13;rport=5060 From: "unknown" ;tag=as77e66d07 To: ;tag=as23e36519 Call-ID: 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.6.1-r230383M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 21]: SIP/2.0 404 Not Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK13399b53;received=64.19.145.13;rport=5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 57]: From: "unknown" ;tag=as77e66d07 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 36]: To: ;tag=as23e36519 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 59]: Call-ID: 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 46]: Server: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 23]: Accept: application/sdp fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 fsdev*CLI> --- (11 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 (Checking To) --From tag as77e66d07 --To-tag as23e36519 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7619 fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060' of Request 102: Match Found fsdev*CLI> [Mar 28 13:27:02] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '5a858f686829c05b2d2232b92c35efc5@64.19.145.13:5060' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 45fbefc7493eed004e9329f663985d11@127.0.0.1:5060 - OPTIONS (No RTP) [Mar 28 13:27:03] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '64.19.145.12', our source address is '64.19.145.13'. [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: OPTIONS sip:64.19.145.12 SIP/2.0 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK28e118e9 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 57]: From: "unknown" ;tag=as3d3df5f0 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 22]: To: fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:03 GMT [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces Reliably Transmitting (no NAT) to 64.19.145.12:5060: OPTIONS sip:64.19.145.12 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK28e118e9 Max-Forwards: 70 From: "unknown" ;tag=as3d3df5f0 To: Contact: Call-ID: 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:03 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7622 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.12:5060 fsdev*CLI>  <--- SIP read from UDP:64.19.145.12:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK28e118e9;received=64.19.145.13 From: "unknown" ;tag=as3d3df5f0 To: ;tag=as5ac5d816 Call-ID: 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.6.1-r230383M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Accept: application/sdp Content-Length: 0 <-------------> fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 21]: SIP/2.0 404 Not Found fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK28e118e9;received=64.19.145.13 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 57]: From: "unknown" ;tag=as3d3df5f0 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 37]: To: ;tag=as5ac5d816 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 59]: Call-ID: 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 46]: Server: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 23]: Accept: application/sdp fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 fsdev*CLI> --- (11 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 (Checking To) --From tag as3d3df5f0 --To-tag as5ac5d816 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7622 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060' of Request 102: Match Found fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '4bf8ab716cdd9f03759b308e4273e097@64.19.145.13:5060' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 6a53e65b273a13497a3289945e294044@127.0.0.1:5060 - OPTIONS (No RTP) [Mar 28 13:27:03] DEBUG[2856]: acl.c:728 ast_ouraddrfor: For destination '64.19.145.11', our source address is '64.19.145.13'. [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 64.19.145.13:5060 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 32]: OPTIONS sip:64.19.145.11 SIP/2.0 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK74ff3c9e [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 57]: From: "unknown" ;tag=as273ef255 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 22]: To: fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 40]: Contact: fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 59]: Call-ID: 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX SVN-branch-1.8-r360625 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Wed, 28 Mar 2012 17:27:03 GMT fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 11 [ 19]: Supported: replaces fsdev*CLI> Reliably Transmitting (no NAT) to 64.19.145.11:5060: OPTIONS sip:64.19.145.11 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK74ff3c9e Max-Forwards: 70 From: "unknown" ;tag=as273ef255 To: Contact: Call-ID: 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-branch-1.8-r360625 Date: Wed, 28 Mar 2012 17:27:03 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 --- fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7625 [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 64.19.145.11:5060 <--- SIP read from UDP:64.19.145.11:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK74ff3c9e;received=64.19.145.13 From: "unknown" ;tag=as273ef255 To: ;tag=as36bc5353 Call-ID: 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 CSeq: 102 OPTIONS Server: Asterisk PBX SVN-branch-1.6.1-r230383M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 21]: SIP/2.0 404 Not Found [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK74ff3c9e;received=64.19.145.13 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 57]: From: "unknown" ;tag=as273ef255 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 37]: To: ;tag=as36bc5353 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 59]: Call-ID: 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 46]: Server: Asterisk PBX SVN-branch-1.6.1-r230383M fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 26]: Supported: replaces, timer fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 23]: Accept: application/sdp fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 10 [ 17]: Content-Length: 0 fsdev*CLI> --- (11 headers 0 lines) --- fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 (Checking To) --From tag as273ef255 --To-tag as36bc5353 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7625 fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060' of Request 102: Match Found fsdev*CLI> [Mar 28 13:27:03] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060 fsdev*CLI> Really destroying SIP dialog '74c211c50d6ddcf204471b7766b1bcee@64.19.145.13:5060' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:04] DEBUG[2856]: chan_sip.c:3885 __sip_autodestruct: Auto destroying SIP dialog '38f11d9b6b9734420b3b83567f795fe7@209.191.44.130' fsdev*CLI> [Mar 28 13:27:04] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 38f11d9b6b9734420b3b83567f795fe7@209.191.44.130 fsdev*CLI> Really destroying SIP dialog '38f11d9b6b9734420b3b83567f795fe7@209.191.44.130' Method: OPTIONS fsdev*CLI> [Mar 28 13:27:06] DEBUG[2856]: chan_sip.c:3885 __sip_autodestruct: Auto destroying SIP dialog '7793124c6b7cd97236f2b2d1054784b2@64.19.145.4' fsdev*CLI> [Mar 28 13:27:06] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 7793124c6b7cd97236f2b2d1054784b2@64.19.145.4 fsdev*CLI> Really destroying SIP dialog '7793124c6b7cd97236f2b2d1054784b2@64.19.145.4' Method: OPTIONS fsdev*CLI>  <--- SIP read from UDP:209.191.13.6:5063 ---> BYE sip:*55@64.19.145.13:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-c660a669 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as20f6385e Call-ID: 6936fca8-1df900d8@localhost CSeq: 103 BYE Max-Forwards: 70 Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13:5060",algorithm=MD5,response="7931e3bbe547ac712fa3550773d8db6a" User-Agent: Linksys/SPA942-6.1.5(a) Content-Length: 0 <-------------> [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 37]: BYE sip:*55@64.19.145.13:5060 SIP/2.0 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-c660a669 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "Anonymous" ;tag=7eab4a68447b0e18o3 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 41]: To: ;tag=as20f6385e [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 36]: Call-ID: 6936fca8-1df900d8@localhost [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 13]: CSeq: 103 BYE [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 16]: Max-Forwards: 70 fsdev*CLI> [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [164]: Authorization: Digest username="175-eng",realm="asterisk",nonce="5be3d74c",uri="sip:*55@64.19.145.13:5060",algorithm=MD5,response="7931e3bbe547ac712fa3550773d8db6a" [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 35]: User-Agent: Linksys/SPA942-6.1.5(a) [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 6936fca8-1df900d8@localhost (Checking From) --From tag 7eab4a68447b0e18o3 --To-tag as20f6385e [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:25092 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:23791 handle_request_bye: Initializing initreq for method BYE - callid 6936fca8-1df900d8@localhost [Mar 28 13:27:07] DEBUG[2856]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.15.187:5063' into... [Mar 28 13:27:07] DEBUG[2856]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.15.187' and port '5063'. Sending to 209.191.13.6:5063 (NAT) [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:3086 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6936fca8-1df900d8@localhost [Mar 28 13:27:07] DEBUG[2856]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb6c88260' Scheduling destruction of SIP dialog '6936fca8-1df900d8@localhost' in 32000 ms (Method: BYE) [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:23894 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 209.191.13.6:5063 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.15.187:5063;branch=z9hG4bK-c660a669;received=209.191.13.6;rport=5063 From: "Anonymous" ;tag=7eab4a68447b0e18o3 To: ;tag=as20f6385e Call-ID: 6936fca8-1df900d8@localhost CSeq: 103 BYE Server: Asterisk PBX SVN-branch-1.8-r360625 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 <------------> [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 209.191.13.6:5063 [Mar 28 13:27:07] DEBUG[3018]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'MulticastRTP/0xa82dae0' [Mar 28 13:27:07] DEBUG[3020]: devicestate.c:438 devstate_event: device 'meetme:13577307d' state '1' [Mar 28 13:27:07] DEBUG[3020]: channel.c:2831 ast_hangup: Hanging up channel 'DAHDI/pseudo-1014325463' [Mar 28 13:27:07] DEBUG[3020]: chan_dahdi.c:6125 dahdi_hangup: dahdi_hangup(DAHDI/pseudo-1014325463) [Mar 28 13:27:07] DEBUG[3020]: chan_dahdi.c:6292 dahdi_hangup: Hangup: channel: -2 index = 0, normal = 38, callwait = -1, thirdcall = -1 [Mar 28 13:27:07] DEBUG[3020]: chan_dahdi.c:6733 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/pseudo-1014325463 [Mar 28 13:27:07] DEBUG[3020]: chan_dahdi.c:4857 update_conf: Updated conferencing on -2, with 0 conference users -- Hungup 'DAHDI/pseudo-1014325463' [Mar 28 13:27:07] DEBUG[3020]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/256-eng-0000000d' [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:6278 sip_hangup: update_call_counter(256-eng) - decrement call limit counter on hangup [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:5900 update_call_counter: Updating call counter for outgoing call [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:5971 update_call_counter: Call to peer '256-eng' removed from call limit 2147483647 [Mar 28 13:27:07] DEBUG[3020]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xaf62748' Scheduling destruction of SIP dialog '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' in 32000 ms (Method: INVITE) [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:10327 reqprep: Strict routing enforced for session 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 set_destination: Parsing for address/port to send to [Mar 28 13:27:07] DEBUG[3020]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '209.191.39.117:5060' into... [Mar 28 13:27:07] DEBUG[3020]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '209.191.39.117' and port '5060'. set_destination: set destination to 209.191.39.117:5060 Reliably Transmitting (no NAT) to 209.191.39.117:5060: BYE sip:256-eng@209.191.39.117:5060;adtnpxyid-1i2c6kcj=7jb6f2 SIP/2.0 Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK5db6690e Max-Forwards: 70 From: "175" ;tag=as5cbf24d1 To: ;tag=58623014-D214389F Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 103 BYE User-Agent: Asterisk PBX SVN-branch-1.8-r360625 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #7630 [Mar 28 13:27:07] DEBUG[3020]: chan_sip.c:3344 __sip_xmit: Trying to put 'BYE sip:256' onto UDP socket destined for 209.191.39.117:5060 [Mar 28 13:27:07] DEBUG[3018]: channel.c:2831 ast_hangup: Hanging up channel 'MulticastRTP/0xa82dae0' [Mar 28 13:27:07] DEBUG[3018]: rtp_engine.c:294 instance_destructor: Destroyed RTP instance '0xa82dae0' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:5047 __ast_pbx_run: Spawn extension (page,*55,2) exited non-zero on 'SIP/175-eng-0000000c' == Spawn extension (page, *55, 2) exited non-zero on 'SIP/175-eng-0000000c' [Mar 28 13:27:07] DEBUG[3018]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/175-eng-0000000c' [Mar 28 13:27:07] DEBUG[3018]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/175-eng-0000000c' [Mar 28 13:27:07] DEBUG[3018]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Mar 28 13:27:07] DEBUG[3018]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb6c88260' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(clid)' (from 'CDR(clid)}","${CDR(src)}","${CDR(dst)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 9) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '"175" <175-eng>' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(src)' (from 'CDR(src)}","${CDR(dst)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 8) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '175-eng' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(dst)' (from 'CDR(dst)}","${CDR(channel)}","${CDR(dstchannel)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 8) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '*55' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(channel)' (from 'CDR(channel)}","${CDR(dstchannel)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 12) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is 'SIP/175-eng-0000000c' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)}","${CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 15) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(start)' (from 'CDR(start)}","${CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 10) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '2012-03-28 13:27:01' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(answer)' (from 'CDR(answer)}","${CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 11) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '2012-03-28 13:27:02' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(end)' (from 'CDR(end)}","${CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 8) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '2012-03-28 13:27:07' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(duration)' (from 'CDR(duration)}","${CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 13) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '6' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(billsec)' (from 'CDR(billsec)}","${CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 12) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '5' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(disposition)' (from 'CDR(disposition)}","${CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 16) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is 'ANSWERED' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)}","${CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 13) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '1332955621.24' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(SIPCALLID1)' (from 'CDR(SIPCALLID1)}","${CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 15) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(SIPCALLID2)' (from 'CDR(SIPCALLID2)}","${CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 15) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(CGPN)' (from 'CDR(CGPN)}","${CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 9) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(CDPN)' (from 'CDR(CDPN)}","${CDR(CHRN)}","${CDR(calltype)}" ' len 9) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(CHRN)' (from 'CDR(CHRN)}","${CDR(calltype)}" ' len 9) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3825 ast_str_substitute_variables_full: Evaluating 'CDR(calltype)' (from 'CDR(calltype)}" ' len 13) [Mar 28 13:27:07] DEBUG[3018]: pbx.c:3859 ast_str_substitute_variables_full: Function result is '(null)' [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for DAHDI/pseudo - state 0 (Unknown) [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:438 devstate_event: device 'DAHDI/pseudo' state '0' [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng [Mar 28 13:27:07] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 1 (Not in use) [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '1' [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 256-eng [Mar 28 13:27:07] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 256-eng [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/256-eng - state 1 (Not in use) [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/256-eng' state '1' [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for MulticastRTP - 0xa82dae0 [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for MulticastRTP/0xa82dae0 - state 0 (Unknown) [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:438 devstate_event: device 'MulticastRTP/0xa82dae0' state '0' [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 175-eng [Mar 28 13:27:07] DEBUG[2858]: chan_sip.c:26361 sip_devicestate: Checking device state for peer 175-eng [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:458 do_state_change: Changing state for SIP/175-eng - state 1 (Not in use) [Mar 28 13:27:07] DEBUG[2858]: devicestate.c:438 devstate_event: device 'SIP/175-eng' state '1' [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'meetme:13577307d' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'DAHDI/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'SIP/256-eng' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1487 handle_statechange: Device 'MulticastRTP/0xa82dae0' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. fsdev*CLI> [Mar 28 13:27:07] DEBUG[2883]: app_queue.c:1485 handle_statechange: Device 'SIP/175-eng' changed to state '1' (Not in use) fsdev*CLI>  <--- SIP read from UDP:209.191.39.117:5060 ---> SIP/2.0 200 OK From: "175";tag=as5cbf24d1 To: "256";tag=58623014-D214389F Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 CSeq: 103 BYE Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK5db6690e Contact: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 Accept-Language: en Content-Length: 0 <-------------> [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 1 [ 52]: From: "175";tag=as5cbf24d1 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 2 [ 90]: To: "256";tag=58623014-D214389F [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 3 [ 59]: Call-ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 4 [ 13]: CSeq: 103 BYE [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 5 [ 57]: Via: SIP/2.0/UDP 64.19.145.13:5060;branch=z9hG4bK5db6690e [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 6 [ 68]: Contact: [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.3.1734 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 8 [ 19]: Accept-Language: en [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8496 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:8089 find_call: = Looking for Call ID: 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 (Checking To) --From tag as5cbf24d1 --To-tag 58623014-D214389F [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7630 [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' of Request 103: Match Found [Mar 28 13:27:07] DEBUG[2856]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 65ac29982123780f70f8431a262efbe8@64.19.145.13:5060 Really destroying SIP dialog '65ac29982123780f70f8431a262efbe8@64.19.145.13:5060' Method: INVITE [Mar 28 13:27:07] DEBUG[2856]: rtp_engine.c:294 instance_destructor: Destroyed RTP instance '0xaf62748' fsdev*CLI> exit