Asterisk SVN-trunk-r46319M, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type '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 'show license' for details. ========================================================================= Connected to Asterisk SVN-trunk-r46319M currently running on main (pid = 21066) main*CLI> Verbosity is at least 3 Core debug is at least 9 main*CLI> <--- SIP read from 68.122.32.101:5360 ---> REGISTER sip:aster.templetons.com:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22419 REGISTER Contact: Expires: 120 Content-Length: 0 <-------------> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: REGISTER sip:aster.templetons.com:5160 SIP/2.0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 49]: To: "at320" [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 20]: CSeq: 22419 REGISTER [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 39]: Contact: [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 12]: Expires: 120 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Dec 16 18:32:27] DEBUG[21121]: acl.c:210 ast_apply_ha: ##### Testing 68.122.32.101 with 192.168.123.0 [Dec 16 18:32:27] DEBUG[21121]: acl.c:210 ast_apply_ha: ##### Testing 198.144.201.82 with 192.168.123.0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4296 sip_alloc: Allocating new SIP dialog for gzJlxMHsrbvIDd5b@68.122.32.101 - REGISTER (No RTP) [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 68.122.32.101 : 5360 (NAT) <--- Transmitting (no NAT) to 68.122.32.101:5360 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport;received=68.122.32.101 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22419 REGISTER User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 95]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport;received=68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 49]: To: "at320" [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 20]: CSeq: 22419 REGISTER [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 40]: Contact: [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: <--- Transmitting (no NAT) to 68.122.32.101:5360 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport;received=68.122.32.101 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" ;tag=as1eb07094 Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22419 REGISTER User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="templetons.com", nonce="3fe623cd" Content-Length: 0 <------------> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 95]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKKw4l3fkftBy0335u;rport;received=68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 64]: To: "at320" ;tag=as1eb07094 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 20]: CSeq: 22419 REGISTER [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 80]: WWW-Authenticate: Digest algorithm=MD5, realm="templetons.com", nonce="3fe623cd" [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: Scheduling destruction of SIP dialog 'gzJlxMHsrbvIDd5b@68.122.32.101' in 32000 ms (Method: REGISTER) main*CLI> <--- SIP read from 68.122.32.101:5360 ---> REGISTER sip:aster.templetons.com:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22420 REGISTER Contact: Expires: 120 Authorization: Digest username="at320", realm="templetons.com", nonce="3fe623cd", uri="sip:aster.templetons.com:5160", response="714fae38d8e14c9ebee89ff14cc24434", algorithm=MD5 Content-Length: 0 <-------------> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: REGISTER sip:aster.templetons.com:5160 SIP/2.0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 49]: To: "at320" [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 20]: CSeq: 22420 REGISTER [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 39]: Contact: [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 12]: Expires: 120 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [177]: Authorization: Digest username="at320", realm="templetons.com", nonce="3fe623cd", uri="sip:aster.templetons.com:5160", response="714fae38d8e14c9ebee89ff14cc24434", algorithm=MD5 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 17]: Content-Length: 0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: gzJlxMHsrbvIDd5b@68.122.32.101 Their Tag dIzTSMAZXM64QGKq Our tag: as1eb07094 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 68.122.32.101 : 5360 (NAT) <--- Transmitting (no NAT) to 68.122.32.101:5360 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport;received=68.122.32.101 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22420 REGISTER User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 95]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport;received=68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 49]: To: "at320" [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 20]: CSeq: 22420 REGISTER [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 40]: Contact: [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: main*CLI> <--- Transmitting (no NAT) to 68.122.32.101:5360 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport;received=68.122.32.101 From: "at320" ;tag=dIzTSMAZXM64QGKq To: "at320" ;tag=as1eb07094 Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 CSeq: 22420 REGISTER User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Sun, 17 Dec 2006 02:32:27 GMT Content-Length: 0 <------------> main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 95]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKUszjzijJOsI3uQqu;rport;received=68.122.32.101 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 72]: From: "at320" ;tag=dIzTSMAZXM64QGKq main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 64]: To: "at320" ;tag=as1eb07094 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 39]: Call-ID: gzJlxMHsrbvIDd5b@68.122.32.101 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 20]: CSeq: 22420 REGISTER main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 12]: Expires: 120 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 51]: Contact: ;expires=120 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 35]: Date: Sun, 17 Dec 2006 02:32:27 GMT main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 17]: Content-Length: 0 main*CLI> [Dec 16 18:32:27] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 13 [ 0]: [Dec 16 18:32:27] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320 Scheduling destruction of SIP dialog 'gzJlxMHsrbvIDd5b@68.122.32.101' in 32000 ms (Method: REGISTER) main*CLI> [Dec 16 18:32:27] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:27] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:27] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:27] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:27] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 main*CLI> [Dec 16 18:32:27] DEBUG[2544]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 198.144.201.83:5064 ---> BUGNOTE: Here the DID invites Asterisk with its SDP <-------------> --- (0 headers 0 lines) Nat keepalive --- main*CLI> <--- SIP read from 74.52.15.138:5060 ---> INVITE sip:4156928449@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport From: "Unavailable" ;tag=as57334032 To: Contact: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 INVITE User-Agent: iCall Softswitch Max-Forwards: 70 Date: Sun, 17 Dec 2006 02:32:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 308 v=0 o=root 6959 6959 IN IP4 74.52.15.138 s=session c=IN IP4 74.52.15.138 t=0 0 m=audio 17574 RTP/AVP 0 18 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 49]: INVITE sip:4156928449@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 64]: From: "Unavailable" ;tag=as57334032 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 40]: To: [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 38]: Contact: [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 28]: User-Agent: iCall Softswitch [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 35]: Date: Sun, 17 Dec 2006 02:32:39 GMT [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 19]: Content-Length: 308 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 13 [ 0]: [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 36]: o=root 6959 6959 IN IP4 74.52.15.138 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 21]: c=IN IP4 74.52.15.138 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 34]: m=audio 17574 RTP/AVP 0 18 8 3 101 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 10 [ 19]: a=rtpmap:3 GSM/8000 [Dec 16 18:32:35] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 12 [ 15]: a=fmtp:101 0-16 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 13 [ 25]: a=silenceSupp:off - - - - --- (13 headers 14 lines) --- [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4347 find_call: = No match Their Call ID: gzJlxMHsrbvIDd5b@68.122.32.101 Their Tag dIzTSMAZXM64QGKq Our tag: as1eb07094 [Dec 16 18:32:36] DEBUG[21121]: acl.c:210 ast_apply_ha: ##### Testing 74.52.15.138 with 192.168.123.0 [Dec 16 18:32:36] DEBUG[21121]: acl.c:210 ast_apply_ha: ##### Testing 198.144.201.82 with 192.168.123.0 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2617 do_setnat: Setting NAT on RTP to Off [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4296 sip_alloc: Allocating new SIP dialog for 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 - INVITE (With RTP) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 74.52.15.138 : 5060 (NAT) Using INVITE request as basis request - 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 No user 'Restricted' in SIP users list Found peer 'icall' for 'Restricted' from 74.52.15.138:5060 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2617 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Found RTP audio format 18 Found RTP audio format 8 Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 74.52.15.138:17574 Found description format PCMU for ID 0 Found description format G729 for ID 18 Got unsupported a:fmtp in SDP offer Found description format PCMA for ID 8 Found description format GSM for ID 3 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:5060 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264), peer - audio=0x10e (gsm|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x10e (gsm|ulaw|alaw|g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 74.52.15.138:17574 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:5137 process_sdp: We're settling with these formats: 0x10e (gsm|ulaw|alaw|g729) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:13262 handle_request_invite: Checking SIP call limits for device [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3025 update_call_counter: Updating call counter for incoming call Looking for 4156928449 in from-icall (domain 198.144.201.82) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3792 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3793 sip_new: *** Joint capabilities are 0x10e (gsm|ulaw|alaw|g729) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3794 sip_new: *** Our capabilities are 0x3f1fff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|jpeg|png|h261|h263|h263p|h264) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3795 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:3818 sip_new: This channel will not be able to handle video. [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:7849 build_route: build_route: Contact hop: list_route: hop: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:13336 handle_request_invite: SIP/74.52.15.138-08e1fce0: New call is still down.... Trying... <--- Transmitting (no NAT) to 74.52.15.138:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 From: "Unavailable" ;tag=as57334032 To: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 INVITE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 85]: Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 64]: From: "Unavailable" ;tag=as57334032 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 40]: To: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: [Dec 16 18:32:36] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/74.52.15.138-08e1fce0 [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 74.52.15.138 [Dec 16 18:32:36] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer 74.52.15.138 [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/74.52.15.138 - state 2 (In use) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: pbx.c:1683 pbx_extension_helper: Launching 'Goto' main*CLI> -- Executing [4156928449@from-icall:1] Goto("SIP/74.52.15.138-08e1fce0", "locals|298|1") in new stack main*CLI> -- Goto (locals,298,1) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: pbx.c:1683 pbx_extension_helper: Launching 'Gosub' main*CLI> -- Executing [298@locals:1] Gosub("SIP/74.52.15.138-08e1fce0", "internal-ext|s|1(SIP/at320&SIP/brad3)") in new stack main*CLI> [Dec 16 18:32:36] DEBUG[2551]: app_stack.c:174 gosub_exec: Setting 'ARG1' to 'SIP/at320&SIP/brad3' main*CLI> [Dec 16 18:32:36] DEBUG[2551]: app_stack.c:179 gosub_exec: Setting gosub return address to '1:locals|298|2' main*CLI> [Dec 16 18:32:36] DEBUG[2551]: pbx.c:1683 pbx_extension_helper: Launching 'Set' main*CLI> -- Executing [s@internal-ext:1] Set("SIP/74.52.15.138-08e1fce0", "devext=SIP/at320&SIP/brad3") in new stack main*CLI> [Dec 16 18:32:36] DEBUG[2551]: pbx.c:1683 pbx_extension_helper: Launching 'Dial' main*CLI> -- Executing [s@internal-ext:2] Dial("SIP/74.52.15.138-08e1fce0", "SIP/at320&SIP/brad3|90|t") in new stack main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:15108 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4296 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2617 do_setnat: Setting NAT on RTP to Off main*CLI> [Dec 16 18:32:36] DEBUG[2551]: acl.c:210 ast_apply_ha: ##### Testing 68.122.32.101 with 192.168.123.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: acl.c:210 ast_apply_ha: ##### Testing 198.144.201.82 with 192.168.123.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3792 sip_new: *** Our native formats are 0x400 (ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3793 sip_new: *** Joint capabilities are 0x0 (nothing) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3794 sip_new: *** Our capabilities are 0x140c (ulaw|alaw|ilbc|g722) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3795 sip_new: *** AST_CODEC_CHOOSE formats are 0x400 (ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3797 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3818 sip_new: This channel will not be able to handle video. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: rtp.c:1578 ast_rtp_make_compatible: Seeded SDP of 'SIP/at320-08e3a4c0' with that of 'SIP/74.52.15.138-08e1fce0' main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-internal-ext-s-2. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable devext. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-internal-ext-s-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable ARG1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-locals-298-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-from-icall-4156928449-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPCALLID. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPURI. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2865 sip_call: Outgoing Call for at320 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2873 sip_call: Our T38 capability (0), joint T38 capability (0) main*CLI> [Dec 16 18:32:36] WARNING[2551]: translate.c:86 powerof: No bits set? 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6116 add_sdp: ** Our capability: 0x40c (ulaw|alaw|ilbc) Video flag: False main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6117 add_sdp: ** Our prefcodec: 0x4 (ulaw) main*CLI> Audio is at 198.144.201.82 port 10166 main*CLI> Adding codec 0x4 (ulaw) to SDP main*CLI> Adding codec 0x400 (ilbc) to SDP main*CLI> Adding codec 0x8 (alaw) to SDP main*CLI> Adding non-codec 0x1 (telephone-event) to SDP main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6244 add_sdp: -- Done with adding codecs to SDP main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6289 add_sdp: Done building SDP. Settling with this capability: 0x40c (ulaw|alaw|ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 43]: INVITE sip:at320@68.122.32.101:5360 SIP/2.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as65601ebe main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 34]: To: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 16]: CSeq: 102 INVITE main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 35]: Date: Sun, 17 Dec 2006 02:32:36 GMT main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 12 [ 29]: Content-Type: application/sdp main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 13 [ 19]: Content-Length: 301 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 14 [ 0]: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21066 IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 5 [ 32]: m=audio 10166 RTP/AVP 0 97 8 101 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 7 [ 21]: a=rtpmap:97 iLBC/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 8 [ 17]: a=fmtp:97 mode=30 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 11 [ 15]: a=fmtp:101 0-16 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 12 [ 25]: a=silenceSupp:off - - - - main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 13 [ 10]: a=sendrecv main*CLI> Reliably Transmitting (no NAT) to 68.122.32.101:5360: BUGNOTE: Here Asterisk invites the phone using an Asterisk Server SDP INVITE sip:at320@68.122.32.101:5360 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport From: "Unavailable" ;tag=as65601ebe To: Contact: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 102 INVITE User-Agent: Caller Asterisk Max-Forwards: 70 Date: Sun, 17 Dec 2006 02:32:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 301 v=0 o=root 21066 21066 IN IP4 198.144.201.82 s=session c=IN IP4 198.144.201.82 t=0 0 m=audio 10166 RTP/AVP 0 97 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 43]: INVITE sip:at320@68.122.32.101:5360 SIP/2.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as65601ebe main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 34]: To: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 16]: CSeq: 102 INVITE main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 35]: Date: Sun, 17 Dec 2006 02:32:36 GMT main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 12 [ 29]: Content-Type: application/sdp main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 13 [ 19]: Content-Length: 301 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 14 [ 0]: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21066 IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 5 [ 32]: m=audio 10166 RTP/AVP 0 97 8 101 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 7 [ 21]: a=rtpmap:97 iLBC/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 8 [ 17]: a=fmtp:97 mode=30 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 11 [ 15]: a=fmtp:101 0-16 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 12 [ 25]: a=silenceSupp:off - - - - main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 13 [ 10]: a=sendrecv main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7354 main*CLI> -- Called at320 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:15108 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4296 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2617 do_setnat: Setting NAT on RTP to Off main*CLI> [Dec 16 18:32:36] DEBUG[2551]: acl.c:210 ast_apply_ha: ##### Testing 198.144.201.83 with 192.168.123.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: acl.c:210 ast_apply_ha: ##### Testing 198.144.201.82 with 192.168.123.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3792 sip_new: *** Our native formats are 0x400 (ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3793 sip_new: *** Joint capabilities are 0x0 (nothing) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3794 sip_new: *** Our capabilities are 0x140c (ulaw|alaw|ilbc|g722) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3795 sip_new: *** AST_CODEC_CHOOSE formats are 0x400 (ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3797 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3818 sip_new: This channel will not be able to handle video. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: rtp.c:1578 ast_rtp_make_compatible: Seeded SDP of 'SIP/brad3-08e268e0' with that of 'SIP/74.52.15.138-08e1fce0' main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-internal-ext-s-2. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable devext. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-internal-ext-s-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable ARG1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-locals-298-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable STACK-from-icall-4156928449-1. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPCALLID. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:3154 ast_channel_inherit_variables: Not copying variable SIPURI. main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2865 sip_call: Outgoing Call for brad3 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:2873 sip_call: Our T38 capability (0), joint T38 capability (0) main*CLI> [Dec 16 18:32:36] WARNING[2551]: translate.c:86 powerof: No bits set? 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6116 add_sdp: ** Our capability: 0x40c (ulaw|alaw|ilbc) Video flag: False main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6117 add_sdp: ** Our prefcodec: 0x4 (ulaw) main*CLI> Audio is at 198.144.201.82 port 10134 main*CLI> Adding codec 0x4 (ulaw) to SDP main*CLI> Adding codec 0x400 (ilbc) to SDP main*CLI> Adding codec 0x8 (alaw) to SDP main*CLI> Adding non-codec 0x1 (telephone-event) to SDP main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6244 add_sdp: -- Done with adding codecs to SDP main*CLI> [Dec 16 18:32:36] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=35) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:6289 add_sdp: Done building SDP. Settling with this capability: 0x40c (ulaw|alaw|ilbc) main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 44]: INVITE sip:brad3@198.144.201.83:5064 SIP/2.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 35]: To: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 16]: CSeq: 102 INVITE main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 35]: Date: Sun, 17 Dec 2006 02:32:36 GMT main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 12 [ 29]: Content-Type: application/sdp main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 13 [ 19]: Content-Length: 301 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 14 [ 0]: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21066 IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 5 [ 32]: m=audio 10134 RTP/AVP 0 97 8 101 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 7 [ 21]: a=rtpmap:97 iLBC/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 8 [ 17]: a=fmtp:97 mode=30 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 11 [ 15]: a=fmtp:101 0-16 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 12 [ 25]: a=silenceSupp:off - - - - main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 13 [ 10]: a=sendrecv main*CLI> Reliably Transmitting (no NAT) to 198.144.201.83:5064: BUGNOTE: Here Asterisk invites the other phone (on .83) using an Asterisk Server SDP (on .82) INVITE sip:brad3@198.144.201.83:5064 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: Contact: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 INVITE User-Agent: Caller Asterisk Max-Forwards: 70 Date: Sun, 17 Dec 2006 02:32:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 301 v=0 o=root 21066 21066 IN IP4 198.144.201.82 s=session c=IN IP4 198.144.201.82 t=0 0 m=audio 10134 RTP/AVP 0 97 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 44]: INVITE sip:brad3@198.144.201.83:5064 SIP/2.0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 35]: To: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 16]: CSeq: 102 INVITE main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 35]: Date: Sun, 17 Dec 2006 02:32:36 GMT main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 12 [ 29]: Content-Type: application/sdp main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 13 [ 19]: Content-Length: 301 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 14 [ 0]: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21066 IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 5 [ 32]: m=audio 10134 RTP/AVP 0 97 8 101 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 7 [ 21]: a=rtpmap:97 iLBC/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 8 [ 17]: a=fmtp:97 mode=30 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 11 [ 15]: a=fmtp:101 0-16 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 12 [ 25]: a=silenceSupp:off - - - - main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 13 [ 10]: a=sendrecv main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7356 main*CLI> -- Called brad3 main*CLI> [Dec 16 18:32:36] DEBUG[2552]: app_queue.c:537 changethread: Device 'SIP/74.52.15.138' changed to state '2' (In use) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 198.144.201.83:5064 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 INVITE User-Agent: Grandstream GXP2000 1.1.1.14 Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" Content-Length: 0 <-------------> [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 35]: To: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 40]: User-Agent: Grandstream GXP2000 1.1.1.14 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 71]: Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 17]: Content-Length: 0 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag Our tag: as179c52d5 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2094 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #7356 - INVITE (got response) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2103 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '558d59f50767a30056e0854954e7b471@198.144.201.82' Request 102: Found [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:11579 handle_response_invite: SIP response 100 to standard invite main*CLI> <--- SIP read from 198.144.201.83:5064 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: ;tag=eb2a66946835dfe3 Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 INVITE User-Agent: Grandstream GXP2000 1.1.1.14 Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Content-Length: 0 <-------------> [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 56]: To: ;tag=eb2a66946835dfe3 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 40]: User-Agent: Grandstream GXP2000 1.1.1.14 main*CLI> [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 71]: Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 40]: Contact: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 85]: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag Our tag: as179c52d5 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2103 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '558d59f50767a30056e0854954e7b471@198.144.201.82' Request 102: Found [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:11579 handle_response_invite: SIP response 180 to standard invite [Dec 16 18:32:36] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/brad3-08e268e0 main*CLI> [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - brad3 [Dec 16 18:32:36] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer brad3 [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/brad3 - state 1 (Not in use) main*CLI> -- SIP/brad3-08e268e0 is ringing main*CLI> [Dec 16 18:32:36] DEBUG[2553]: app_queue.c:537 changethread: Device 'SIP/brad3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. main*CLI> <--- Transmitting (no NAT) to 74.52.15.138:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 From: "Unavailable" ;tag=as57334032 To: ;tag=as5d66c0cb Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 INVITE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 85]: Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 64]: From: "Unavailable" ;tag=as57334032 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 55]: To: ;tag=as5d66c0cb main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 main*CLI> [Dec 16 18:32:36] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 0]: main*CLI> <--- SIP read from 68.122.32.101:5360 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 102 INVITE From: "Unavailable" ;tag=as65601ebe To: ;tag=Jvq9TPpaYGPB9HjA Contact: Content-Length: 0 <-------------> [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 71]: From: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 55]: To: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 39]: Contact: [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 17]: Content-Length: 0 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4347 find_call: = No match Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag eb2a66946835dfe3 Our tag: as179c52d5 [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Our tag: as65601ebe [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2094 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #7354 - INVITE (got response) [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:2103 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82' Request 102: Found [Dec 16 18:32:36] DEBUG[21121]: chan_sip.c:11579 handle_response_invite: SIP response 180 to standard invite [Dec 16 18:32:36] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320-08e3a4c0 main*CLI> -- SIP/at320-08e3a4c0 is ringing [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:36] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:36] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:36] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 main*CLI> [Dec 16 18:32:36] DEBUG[2555]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 198.144.201.83:5080 ---> BUGNOTE: Here the first phone says OK, and provides its SDP <-------------> [Dec 16 18:32:37] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 0]: --- (0 headers 0 lines) Nat keepalive --- main*CLI> <--- SIP read from 68.122.32.101:5360 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 102 INVITE From: "Unavailable" ;tag=as65601ebe To: ;tag=Jvq9TPpaYGPB9HjA Contact: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Supported: replaces Content-Type: application/sdp Content-Length: 194 v=0 o=- 58555086 00608788 IN IP4 68.122.32.101 s=SIP CALL c=IN IP4 68.122.32.101 t=0 0 m=audio 5364 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK1b61f819;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 71]: From: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 55]: To: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 39]: Contact: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 85]: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 19]: Content-Length: 194 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 42]: o=- 58555086 00608788 IN IP4 68.122.32.101 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 10]: s=SIP CALL [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 22]: c=IN IP4 68.122.32.101 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 26]: m=audio 5364 RTP/AVP 0 101 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 --- (11 headers 9 lines) --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = No match Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag eb2a66946835dfe3 Our tag: as179c52d5 main*CLI> [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2043 __sip_ack: Acked pending invite 102 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82' of Request 102: Match Not Found [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:11579 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 68.122.32.101:5364 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:5060 process_sdp: T38 state changed to 0 on channel SIP/at320-08e3a4c0 Capabilities: us - 0x140c (ulaw|alaw|ilbc|g722), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 68.122.32.101:5364 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:5137 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:5144 process_sdp: We have an owner, now see if we need to change this call [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:5149 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x4 (ulaw) and not 0x400 (ilbc) [Dec 16 18:32:38] DEBUG[21121]: channel.c:2687 set_format: Set channel SIP/at320-08e3a4c0 to read format ilbc [Dec 16 18:32:38] DEBUG[21121]: channel.c:2687 set_format: Set channel SIP/at320-08e3a4c0 to write format ilbc [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call --- set_address_from_contact host '68.122.32.101' [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:7849 build_route: build_route: Contact hop: list_route: hop: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:5569 reqprep: Strict routing enforced for session 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 set_destination: Parsing for address/port to send to set_destination: set destination to 68.122.32.101, port 5360 Transmitting (no NAT) to 68.122.32.101:5360: ACK sip:at320@68.122.32.101:5360 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK7743af4c;rport From: "Unavailable" ;tag=as65601ebe To: ;tag=Jvq9TPpaYGPB9HjA Contact: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 102 ACK User-Agent: Caller Asterisk Max-Forwards: 70 Content-Length: 0 --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 40]: ACK sip:at320@68.122.32.101:5360 SIP/2.0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK7743af4c;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 55]: To: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 13]: CSeq: 102 ACK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: main*CLI> [Dec 16 18:32:38] DEBUG[2551]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320-08e3a4c0 -- SIP/at320-08e3a4c0 answered SIP/74.52.15.138-08e1fce0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:16661 sip_set_rtp_peer: Early remote bridge setting SIP '050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138' - Sending media to 68.122.32.101 [Dec 16 18:32:38] DEBUG[2551]: rtp.c:1513 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/74.52.15.138-08e1fce0' with that of 'SIP/at320-08e3a4c0' [Dec 16 18:32:38] DEBUG[2551]: channel.c:1555 ast_hangup: Hanging up channel 'SIP/brad3-08e268e0' [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:3324 sip_hangup: Hangup call SIP/brad3-08e268e0, SIP callid 558d59f50767a30056e0854954e7b471@198.144.201.82) [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:3332 sip_hangup: update_call_counter(brad3) - decrement call limit counter on hangup [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:3345 sip_hangup: Hanging up channel in state Ringing (not UP) Scheduling destruction of SIP dialog '558d59f50767a30056e0854954e7b471@198.144.201.82' in 32000 ms (Method: INVITE) [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:2043 __sip_ack: Acked pending invite 102 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '558d59f50767a30056e0854954e7b471@198.144.201.82' of Request 102: Match Not Found main*CLI> Reliably Transmitting (no NAT) to 198.144.201.83:5064: CANCEL sip:brad3@198.144.201.83:5064 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 CANCEL User-Agent: Caller Asterisk Max-Forwards: 70 Content-Length: 0 --- [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 44]: CANCEL sip:brad3@198.144.201.83:5064 SIP/2.0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 35]: To: [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 CANCEL [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 0]: [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7359 Scheduling destruction of SIP dialog '558d59f50767a30056e0854954e7b471@198.144.201.82' in 32000 ms (Method: INVITE) [Dec 16 18:32:38] DEBUG[2551]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/brad3-08e268e0 [Dec 16 18:32:38] DEBUG[2551]: channel.c:2687 set_format: Set channel SIP/at320-08e3a4c0 to write format ulaw [Dec 16 18:32:38] DEBUG[2551]: channel.c:2687 set_format: Set channel SIP/at320-08e3a4c0 to read format ulaw [Dec 16 18:32:38] DEBUG[2551]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/74.52.15.138-08e1fce0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:3472 sip_answer: SIP answering channel: SIP/74.52.15.138-08e1fce0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:6344 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 16 18:32:38] WARNING[2551]: translate.c:86 powerof: No bits set? 0 [Dec 16 18:32:38] WARNING[2551]: translate.c:86 powerof: No bits set? 0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:6116 add_sdp: ** Our capability: 0x10e (gsm|ulaw|alaw|g729) Video flag: True [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:6117 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 198.144.201.82 port 10138 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:6244 add_sdp: -- Done with adding codecs to SDP [Dec 16 18:32:38] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:6289 add_sdp: Done building SDP. Settling with this capability: 0x10e (gsm|ulaw|alaw|g729) BUGNOTE: Here Asterisk gives the phone's SDP back to the DID. Thus the DID things it is talking BUGNOTE: To the phone, but the phone thinks it is talking to Asterisk. <--- Reliably Transmitting (no NAT) to 74.52.15.138:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 From: "Unavailable" ;tag=as57334032 To: ;tag=as5d66c0cb Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 INVITE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 323 v=0 o=root 21066 21066 IN IP4 68.122.32.101 s=session c=IN IP4 68.122.32.101 t=0 0 m=audio 5364 RTP/AVP 0 8 3 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv <------------> [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 85]: Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK77de9a36;rport;received=74.52.15.138 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 64]: From: "Unavailable" ;tag=as57334032 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 55]: To: ;tag=as5d66c0cb [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Content-Length: 323 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 12 [ 0]: [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 1 [ 39]: o=root 21066 21066 IN IP4 68.122.32.101 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 3 [ 22]: c=IN IP4 68.122.32.101 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 5 [ 33]: m=audio 5364 RTP/AVP 0 8 3 18 101 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 8 [ 19]: a=rtpmap:3 GSM/8000 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 10 [ 19]: a=fmtp:18 annexb=no [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 12 [ 15]: a=fmtp:101 0-16 [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 13 [ 25]: a=silenceSupp:off - - - - [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:4548 parse_request: Body 14 [ 10]: a=sendrecv [Dec 16 18:32:38] DEBUG[2551]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7361 main*CLI> [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:38] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:38] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - brad3 [Dec 16 18:32:38] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer brad3 [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/brad3 - state 1 (Not in use) [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 74.52.15.138 [Dec 16 18:32:38] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer 74.52.15.138 [Dec 16 18:32:38] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/74.52.15.138 - state 2 (In use) main*CLI> [Dec 16 18:32:38] DEBUG[2557]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. main*CLI> [Dec 16 18:32:38] DEBUG[2558]: app_queue.c:537 changethread: Device 'SIP/brad3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. main*CLI> [Dec 16 18:32:38] DEBUG[2559]: app_queue.c:537 changethread: Device 'SIP/74.52.15.138' changed to state '2' (In use) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 198.144.201.83:5064 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: ;tag=eb2a66946835dfe3 Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 CANCEL User-Agent: Grandstream GXP2000 1.1.1.14 Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 56]: To: ;tag=eb2a66946835dfe3 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 CANCEL [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 40]: User-Agent: Grandstream GXP2000 1.1.1.14 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 71]: Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 40]: Contact: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 85]: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 26]: Supported: replaces, timer [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag eb2a66946835dfe3 Our tag: as179c52d5 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2051 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7359 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '558d59f50767a30056e0854954e7b471@198.144.201.82' of Request 102: Match Not Found main*CLI> <--- SIP read from 198.144.201.83:5064 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: ;tag=eb2a66946835dfe3 Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 INVITE User-Agent: Grandstream GXP2000 1.1.1.14 Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" Content-Length: 0 <-------------> [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 29]: SIP/2.0 487 Request Cancelled [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 56]: To: ;tag=eb2a66946835dfe3 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 40]: User-Agent: Grandstream GXP2000 1.1.1.14 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 71]: Warning: 399 198.144.201.83 "detected NAT type is port restricted cone" [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 Their Tag eb2a66946835dfe3 Our tag: as179c52d5 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '558d59f50767a30056e0854954e7b471@198.144.201.82' of Request 102: Match Found [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call Transmitting (no NAT) to 198.144.201.83:5064: ACK sip:brad3@198.144.201.83:5064 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport From: "Unavailable" ;tag=as179c52d5 To: ;tag=eb2a66946835dfe3 Contact: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 CSeq: 102 ACK User-Agent: Caller Asterisk Max-Forwards: 70 Content-Length: 0 --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 41]: ACK sip:brad3@198.144.201.83:5064 SIP/2.0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK302825fb;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 71]: From: "Unavailable" ;tag=as179c52d5 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 56]: To: ;tag=eb2a66946835dfe3 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 45]: Contact: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 56]: Call-ID: 558d59f50767a30056e0854954e7b471@198.144.201.82 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 13]: CSeq: 102 ACK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: Really destroying SIP dialog '558d59f50767a30056e0854954e7b471@198.144.201.82' Method: INVITE main*CLI> <--- SIP read from 74.52.15.138:5060 ---> ACK sip:4156928449@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK0afda78b;rport From: "Unavailable" ;tag=as57334032 To: ;tag=as5d66c0cb Contact: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 ACK User-Agent: iCall Softswitch Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: ACK sip:4156928449@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 74.52.15.138:5060;branch=z9hG4bK0afda78b;rport [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 64]: From: "Unavailable" ;tag=as57334032 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 55]: To: ;tag=as5d66c0cb [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 38]: Contact: [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 13]: CSeq: 102 ACK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 28]: User-Agent: iCall Softswitch [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = No match Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 Their Tag as57334032 Our tag: as5d66c0cb [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2051 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7361 [Dec 16 18:32:38] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138' of Response 102: Match Not Found main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> BUGNOTE: Here the phone puts the line on hold <--- SIP read from 68.122.32.101:5360 ---> INVITE sip:Restricted@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKEeNa6YXo1zMEWb0b;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Contact: CSeq: 1 INVITE Supported: replaces Content-Type: application/sdp Content-Length: 200 v=0 o=- 17510006 89293408 IN IP4 68.122.32.101 s=SIP CALL c=IN IP4 0.0.0.0 t=0 0 m=audio 5364 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendonly <-------------> [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 49]: INVITE sip:Restricted@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKEeNa6YXo1zMEWb0b;rport [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 39]: Contact: [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 14]: CSeq: 1 INVITE [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 19]: Supported: replaces [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Content-Length: 200 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 42]: o=- 17510006 89293408 IN IP4 68.122.32.101 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 10]: s=SIP CALL [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 26]: m=audio 5364 RTP/AVP 0 101 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 9 [ 10]: a=sendonly --- (12 headers 10 lines) --- [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:1661 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:1669 parse_sip_options: Found SIP option: -replaces- [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:1675 parse_sip_options: Matched SIP option: replaces Sending to 68.122.32.101 : 5360 (NAT) Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:5364 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:5060 process_sdp: T38 state changed to 0 on channel SIP/at320-08e3a4c0 Capabilities: us - 0x140c (ulaw|alaw|ilbc|g722), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 0.0.0.0:5364 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:5137 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:5144 process_sdp: We have an owner, now see if we need to change this call [Dec 16 18:32:43] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:13314 handle_request_invite: Got a SIP re-invite for call 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:13403 handle_request_invite: SIP/at320-08e3a4c0: This call is UP.... [Dec 16 18:32:43] WARNING[21121]: translate.c:86 powerof: No bits set? 0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:6116 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:6117 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 198.144.201.82 port 10166 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:6244 add_sdp: -- Done with adding codecs to SDP [Dec 16 18:32:43] DEBUG[21121]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:6289 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 68.122.32.101:5360 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKEeNa6YXo1zMEWb0b;received=68.122.32.101;rport=5360 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 1 INVITE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 21066 21067 IN IP4 198.144.201.82 s=session c=IN IP4 198.144.201.82 t=0 0 m=audio 10166 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=recvonly <------------> [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [100]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKEeNa6YXo1zMEWb0b;received=68.122.32.101;rport=5360 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 69]: To: "Unavailable" ;tag=as65601ebe main*CLI> [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 14]: CSeq: 1 INVITE [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Content-Length: 232 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21067 IN IP4 198.144.201.82 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 27]: m=audio 10166 RTP/AVP 0 101 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 10 [ 10]: a=recvonly [Dec 16 18:32:43] DEBUG[21121]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7362 main*CLI> [Dec 16 18:32:43] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:43] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:43] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:43] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:43] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 main*CLI> [Dec 16 18:32:43] DEBUG[2551]: channel.c:2687 set_format: Set channel SIP/74.52.15.138-08e1fce0 to write format slin -- Started music on hold, class 'default', on channel 'SIP/74.52.15.138-08e1fce0' [Dec 16 18:32:43] DEBUG[2551]: channel.c:1859 ast_settimeout: Scheduling timer at 160 sample intervals main*CLI> [Dec 16 18:32:43] DEBUG[2578]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. main*CLI> [Dec 16 18:32:43] DEBUG[2551]: rtp.c:2616 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 16 18:32:43] DEBUG[2551]: rtp.c:2633 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 main*CLI> [Dec 16 18:32:43] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Dec 16 18:32:43] DEBUG[2551]: channel.c:2178 __ast_read: Generator got voice, switching to phase locked mode [Dec 16 18:32:43] DEBUG[2551]: channel.c:1859 ast_settimeout: Scheduling timer at 0 sample intervals main*CLI> [Dec 16 18:32:43] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:43] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:43] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> <--- SIP read from 68.122.32.101:5360 ---> ACK sip:Restricted@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKm7jRO5HLF6k4EBP0;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Contact: CSeq: 1 ACK Content-Length: 0 <-------------> [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: ACK sip:Restricted@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKm7jRO5HLF6k4EBP0;rport [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 39]: Contact: [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 11]: CSeq: 1 ACK [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:2051 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7362 [Dec 16 18:32:44] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82' of Response 1: Match Not Found main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:44] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) main*CLI> <--- SIP read from 68.122.32.101:5360 ---> INVITE sip:Restricted@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKlw6uUf8dkVES4mvi;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Contact: CSeq: 2 INVITE Supported: replaces Content-Type: application/sdp Content-Length: 194 v=0 o=- 98791219 89710141 IN IP4 68.122.32.101 s=SIP CALL c=IN IP4 68.122.32.101 t=0 0 m=audio 5364 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 49]: INVITE sip:Restricted@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKlw6uUf8dkVES4mvi;rport [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 39]: Contact: [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 14]: CSeq: 2 INVITE [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 19]: Supported: replaces [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Content-Length: 194 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 42]: o=- 98791219 89710141 IN IP4 68.122.32.101 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 10]: s=SIP CALL [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 22]: c=IN IP4 68.122.32.101 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 26]: m=audio 5364 RTP/AVP 0 101 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 --- (12 headers 9 lines) --- [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 68.122.32.101 : 5360 (NAT) Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 68.122.32.101:5364 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:5060 process_sdp: T38 state changed to 0 on channel SIP/at320-08e3a4c0 Capabilities: us - 0x140c (ulaw|alaw|ilbc|g722), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 68.122.32.101:5364 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:5137 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:5144 process_sdp: We have an owner, now see if we need to change this call [Dec 16 18:32:45] DEBUG[21121]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:13314 handle_request_invite: Got a SIP re-invite for call 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:13403 handle_request_invite: SIP/at320-08e3a4c0: This call is UP.... [Dec 16 18:32:45] WARNING[21121]: translate.c:86 powerof: No bits set? 0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:6116 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:6117 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 198.144.201.82 port 10166 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:6244 add_sdp: -- Done with adding codecs to SDP [Dec 16 18:32:45] DEBUG[21121]: channel.c:2227 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:6289 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 68.122.32.101:5360 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKlw6uUf8dkVES4mvi;received=68.122.32.101;rport=5360 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 2 INVITE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 21066 21068 IN IP4 198.144.201.82 s=session c=IN IP4 198.144.201.82 t=0 0 m=audio 10166 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv <------------> [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [100]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKlw6uUf8dkVES4mvi;received=68.122.32.101;rport=5360 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 19]: Content-Length: 232 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 12 [ 0]: [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 0 [ 3]: v=0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 1 [ 40]: o=root 21066 21068 IN IP4 198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 2 [ 9]: s=session [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 3 [ 23]: c=IN IP4 198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 4 [ 5]: t=0 0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 5 [ 27]: m=audio 10166 RTP/AVP 0 101 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Body 10 [ 10]: a=sendrecv [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7364 main*CLI> [Dec 16 18:32:45] DEBUG[2551]: channel.c:2687 set_format: Set channel SIP/74.52.15.138-08e1fce0 to write format ulaw -- Stopped music on hold on SIP/74.52.15.138-08e1fce0 [Dec 16 18:32:45] DEBUG[2551]: channel.c:1859 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 16 18:32:45] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:45] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:45] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:45] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:45] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 main*CLI> [Dec 16 18:32:45] DEBUG[2579]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. main*CLI> [Dec 16 18:32:45] DEBUG[2551]: rtp.c:2616 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 16 18:32:45] DEBUG[2551]: rtp.c:2633 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 main*CLI> <--- SIP read from 68.122.32.101:5360 ---> ACK sip:Restricted@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bK8seAwGN3mWJg4yW7;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Contact: CSeq: 2 ACK Content-Length: 0 <-------------> [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: ACK sip:Restricted@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bK8seAwGN3mWJg4yW7;rport [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 39]: Contact: [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 11]: CSeq: 2 ACK [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:2051 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7364 [Dec 16 18:32:45] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82' of Response 2: Match Not Found main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> main*CLI> [Dec 16 18:32:50] DEBUG[2551]: rtp.c:858 ast_rtcp_read: Got RTCP report of 64 bytes main*CLI> [Dec 16 18:32:51] DEBUG[21114]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/soyo main*CLI> [Dec 16 18:32:51] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - soyo main*CLI> [Dec 16 18:32:51] DEBUG[21096]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device soyo main*CLI> [Dec 16 18:32:51] DEBUG[21096]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of soyo? addr=1696627268, defaddr=0 maxms=0, lastms=0 main*CLI> [Dec 16 18:32:51] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for IAX2/soyo - state 1 (Not in use) main*CLI> [Dec 16 18:32:51] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - soyo main*CLI> [Dec 16 18:32:51] DEBUG[21096]: chan_iax2.c:9611 iax2_devicestate: Checking device state for device soyo main*CLI> [Dec 16 18:32:51] DEBUG[21096]: chan_iax2.c:9619 iax2_devicestate: iax2_devicestate: Found peer. What's device state of soyo? addr=1696627268, defaddr=0 maxms=0, lastms=0 main*CLI> [Dec 16 18:32:51] DEBUG[2589]: app_queue.c:537 changethread: Device 'IAX2/soyo' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 68.122.32.101:5360 ---> BYE sip:Restricted@198.144.201.82:5160 SIP/2.0 Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKI0Hvn1q5Tmjfvk9M;rport Max-Forwards: 70 User-Agent: IP Phone V1.54.004 CFG0 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Contact: CSeq: 3 BYE Content-Length: 0 <-------------> [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 46]: BYE sip:Restricted@198.144.201.82:5160 SIP/2.0 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 72]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKI0Hvn1q5Tmjfvk9M;rport [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 36]: User-Agent: IP Phone V1.54.004 CFG0 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 39]: Contact: [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 11]: CSeq: 3 BYE [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 Their Tag Jvq9TPpaYGPB9HjA Our tag: as65601ebe [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:14459 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 68.122.32.101 : 5360 (NAT) [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:14051 handle_request_bye: Received bye, issuing owner hangup . <--- Transmitting (NAT) to 68.122.32.101:5360 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKI0Hvn1q5Tmjfvk9M;received=68.122.32.101;rport=5360 From: ;tag=Jvq9TPpaYGPB9HjA To: "Unavailable" ;tag=as65601ebe Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 CSeq: 3 BYE User-Agent: Caller Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [100]: Via: SIP/2.0/UDP 68.122.32.101:5360;branch=z9hG4bKI0Hvn1q5Tmjfvk9M;received=68.122.32.101;rport=5360 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 57]: From: ;tag=Jvq9TPpaYGPB9HjA [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 69]: To: "Unavailable" ;tag=as65601ebe [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 56]: Call-ID: 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 11]: CSeq: 3 BYE [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 19]: Supported: replaces [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 45]: Contact: [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 17]: Content-Length: 0 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: [Dec 16 18:32:52] DEBUG[2551]: channel.c:3652 ast_generic_bridge: Didn't get a frame from channel: SIP/at320-08e3a4c0 [Dec 16 18:32:52] DEBUG[2551]: channel.c:3969 ast_channel_bridge: Bridge stops bridging channels SIP/74.52.15.138-08e1fce0 and SIP/at320-08e3a4c0 [Dec 16 18:32:52] DEBUG[2551]: channel.c:1555 ast_hangup: Hanging up channel 'SIP/at320-08e3a4c0' [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3324 sip_hangup: Hangup call SIP/at320-08e3a4c0, SIP callid 57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82) [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3332 sip_hangup: update_call_counter(at320) - decrement call limit counter on hangup [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3025 update_call_counter: Updating call counter for outgoing call [Dec 16 18:32:52] DEBUG[2551]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/at320-08e3a4c0 [Dec 16 18:32:52] DEBUG[2551]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Dec 16 18:32:52] DEBUG[2551]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 16 18:32:52] DEBUG[2551]: pbx.c:2281 __ast_pbx_run: Spawn extension (internal-ext,s,2) exited non-zero on 'SIP/74.52.15.138-08e1fce0' == Spawn extension (internal-ext, s, 2) exited non-zero on 'SIP/74.52.15.138-08e1fce0' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '"Unavailable" ' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'Restricted' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 's' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'internal-ext' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'SIP/74.52.15.138-08e1fce0' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'SIP/at320-08e3a4c0' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'SIP/at320&SIP/brad3|90|t' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '2006-12-16 18:32:36' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '2006-12-16 18:32:38' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '2006-12-16 18:32:52' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '16' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '14' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '1166322756.182' [Dec 16 18:32:52] DEBUG[2551]: pbx.c:1533 pbx_substitute_variables_helper_full: Function result is '' [Dec 16 18:32:52] DEBUG[2551]: channel.c:1555 ast_hangup: Hanging up channel 'SIP/74.52.15.138-08e1fce0' [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3324 sip_hangup: Hangup call SIP/74.52.15.138-08e1fce0, SIP callid 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138) [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3332 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:3025 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138' in 32000 ms (Method: ACK) [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:5569 reqprep: Strict routing enforced for session 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 set_destination: Parsing for address/port to send to set_destination: set destination to 74.52.15.138, port 5060 Reliably Transmitting (no NAT) to 74.52.15.138:5060: BYE sip:Restricted@74.52.15.138 SIP/2.0 Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK4d1e472b;rport From: ;tag=as5d66c0cb To: "Unavailable" ;tag=as57334032 Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 BYE User-Agent: Caller Asterisk Max-Forwards: 70 Content-Length: 0 --- [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 0 [ 39]: BYE sip:Restricted@74.52.15.138 SIP/2.0 [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK4d1e472b;rport [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 2 [ 57]: From: ;tag=as5d66c0cb [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 3 [ 62]: To: "Unavailable" ;tag=as57334032 [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 4 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 5 [ 13]: CSeq: 102 BYE [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 6 [ 27]: User-Agent: Caller Asterisk [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 8 [ 17]: Content-Length: 0 [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:4548 parse_request: Header 9 [ 0]: [Dec 16 18:32:52] DEBUG[2551]: chan_sip.c:1952 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7367 [Dec 16 18:32:52] DEBUG[2551]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/74.52.15.138-08e1fce0 Really destroying SIP dialog '57a8f35051f9673d5537a60f1bab5bf4@198.144.201.82' Method: BYE main*CLI> [Dec 16 18:32:52] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:52] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:52] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/at320 - state 8 (On Hold) [Dec 16 18:32:52] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - at320 [Dec 16 18:32:52] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer at320 [Dec 16 18:32:52] DEBUG[21096]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 74.52.15.138 [Dec 16 18:32:52] DEBUG[21096]: chan_sip.c:15050 sip_devicestate: Checking device state for peer 74.52.15.138 [Dec 16 18:32:52] DEBUG[21096]: devicestate.c:287 do_state_change: Changing state for SIP/74.52.15.138 - state 1 (Not in use) [Dec 16 18:32:52] DEBUG[2590]: app_queue.c:537 changethread: Device 'SIP/at320' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Dec 16 18:32:52] DEBUG[2591]: app_queue.c:537 changethread: Device 'SIP/74.52.15.138' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. main*CLI> <--- SIP read from 74.52.15.138:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK4d1e472b;received=198.144.201.82;rport=5160 From: ;tag=as5d66c0cb To: "Unavailable" ;tag=as57334032 Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 CSeq: 102 BYE User-Agent: iCall Softswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing <-------------> [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 1 [ 94]: Via: SIP/2.0/UDP 198.144.201.82:5160;branch=z9hG4bK4d1e472b;received=198.144.201.82;rport=5160 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 2 [ 57]: From: ;tag=as5d66c0cb [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 3 [ 62]: To: "Unavailable" ;tag=as57334032 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 4 [ 54]: Call-ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 5 [ 13]: CSeq: 102 BYE [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 6 [ 28]: User-Agent: iCall Softswitch [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 8 [ 38]: Contact: [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 9 [ 17]: Content-Length: 0 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 10 [ 39]: X-Asterisk-HangupCause: Normal Clearing [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4548 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:4347 find_call: = Found Their Call ID: 050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138 Their Tag as57334032 Our tag: as5d66c0cb [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:2051 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7367 [Dec 16 18:32:52] DEBUG[21121]: chan_sip.c:2061 __sip_ack: Stopping retransmission on '050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '050e5c7f4c3d014f3efce83f375d6b50@74.52.15.138' Method: ACK main*CLI> <--- SIP read from 68.122.32.101:5360 ---> <-------------> --- (0 headers 0 lines) Nat keepalive --- main*CLI> <--- SIP read from 198.144.201.83:5064 ---> <-------------> --- (0 headers 0 lines) Nat keepalive --- main*CLI> exit