| Summary: | ASTERISK-12955: Asteris never responce ACK for 487 Request Terminated | ||
| Reporter: | Sahria Hao (sahria hao) | Labels: | |
| Date Opened: | 2008-10-23 06:34:33 | Date Closed: | 2011-06-07 14:08:04 |
| Priority: | Minor | Regression? | No |
| Status: | Closed/Complete | Components: | Channels/chan_sip/General |
| Versions: | Frequency of Occurrence | ||
| Related Issues: | |||
| Environment: | Attachments: | ||
| Description: | When Asteris received 487 Request Terminated, but Asterisk never responce ACK. [Oct 23 20:23:25] DEBUG[29206]: chan_sip.c:16243 sipsock_read: Invalid SIP message - rejected , no callid, len 364 Attached console debug with: core set debug 15 core set verbose 15 sip debug ****** ADDITIONAL INFORMATION ****** [Oct 23 20:22:50] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: (0) dev01*CLI> <--- SIP read from 123.45.67.145:2048 ---> INVITE sip:0368269002@111.22.33.53;user=phone SIP/2.0 Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-pbg1d01lmbqg;rport From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone> Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 1 INVITE Max-Forwards: 70 Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 P-Key-Flags: keys="3" User-Agent: snom300/7.1.30 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 477 v=0 o=root 988865281 988865281 IN IP4 123.45.67.145 s=call c=IN IP4 123.45.67.145 t=0 0 m=audio 61270 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:Jeyxs/3v1usNxIjWOE3I4Ciu4f0yhGSHB+c75YK2 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: INVITE sip:0368269002@111.22.33.53;user=phone SIP/2.0 (53) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-pbg1d01lmbqg;rport (70) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y (51) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.33.53;user=phone> (44) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 3c26a2a77bbc-c4675b7wav6n (34) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 1 INVITE (14) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 (63) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: P-Key-Flags: keys="3" (21) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: User-Agent: snom300/7.1.30 (26) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: Accept: application/sdp (23) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 13: Supported: timer, 100rel, replaces, callerid (44) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 14: Session-Expires: 3600;refresher=uas (35) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 15: Min-SE: 90 (10) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 16: Content-Type: application/sdp (29) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 17: Content-Length: 477 (19) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 18: (0) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: v=0 (3) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: o=root 988865281 988865281 IN IP4 123.45.67.145 (48) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: s=call (6) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: c=IN IP4 123.45.67.145 (23) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: t=0 0 (5) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: m=audio 61270 RTP/AVP 0 8 9 2 3 18 4 101 (40) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:Jeyxs/3v1usNxIjWOE3I4Ciu4f0yhGSHB+c75YK2 (82) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:9 g722/8000 (20) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:18 g729/8000 (21) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:4 g723/8000 (20) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=ptime:20 (10) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=encryption:optional (21) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=sendrecv (10) --- (18 headers 19 lines) --- [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4688 find_call: = No match Their Call ID: 127040593dd94a3f2322165b4b12d905@111.22.44.55 Their Tag 3433749802 Our tag: as1962c454 [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:2798 do_setnat: Setting NAT on RTP to Off [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:4632 sip_alloc: Allocating new SIP dialog for 3c26a2a77bbc-c4675b7wav6n - INVITE (With RTP) [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:16053 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1731 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, callerid" [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1739 parse_sip_options: Found SIP option: -timer- [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1745 parse_sip_options: Matched SIP option: timer [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1739 parse_sip_options: Found SIP option: -100rel- [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1745 parse_sip_options: Matched SIP option: 100rel [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1739 parse_sip_options: Found SIP option: -replaces- [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1745 parse_sip_options: Matched SIP option: replaces [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1739 parse_sip_options: Found SIP option: -callerid- [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:1753 parse_sip_options: Found no match for SIP option: callerid (Please file bug report!) Sending to 123.45.67.145 : 2048 (NAT) Using INVITE request as basis request - 3c26a2a77bbc-c4675b7wav6n [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:2798 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 123.45.67.145:2048 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-pbg1d01lmbqg From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone>;tag=as77c78176 Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="06b51c5d" Content-Length: 0 <------------> [Oct 23 20:22:51] DEBUG[29206]: chan_sip.c:2076 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 Scheduling destruction of SIP dialog '3c26a2a77bbc-c4675b7wav6n' in 32000 ms (Method: INVITE) Found user '9004' <--- SIP read from 123.45.67.145:2048 ---> ACK sip:0368269002@111.22.33.53;user=phone SIP/2.0 Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-pbg1d01lmbqg;rport From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone>;tag=as77c78176 Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 1 ACK Max-Forwards: 70 Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 Content-Length: 0 <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: ACK sip:0368269002@111.22.33.53;user=phone SIP/2.0 (50) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-pbg1d01lmbqg;rport (70) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y (51) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.33.53;user=phone>;tag=as77c78176 (59) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 3c26a2a77bbc-c4675b7wav6n (34) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 1 ACK (11) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 3c26a2a77bbc-c4675b7wav6n Their Tag osiafzl13y Our tag: as77c78176 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:16053 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2199 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid ASTERISK-29 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2225 __sip_ack: Stopping retransmission on '3c26a2a77bbc-c4675b7wav6n' of Response 1: Match Found dev01*CLI> <--- SIP read from 123.45.67.145:2048 ---> INVITE sip:0368269002@111.22.33.53;user=phone SIP/2.0 Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-nvmqr7pt09nq;rport From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone> Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 2 INVITE Max-Forwards: 70 Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 P-Key-Flags: keys="3" User-Agent: snom300/7.1.30 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Proxy-Authorization: Digest username="9004",realm="asterisk",nonce="06b51c5d",uri="sip:0368269002@111.22.33.53;user=phone",response="39f6632ed61562a4fb5c7a7973a97ca4",algorithm=MD5 Content-Type: application/sdp Content-Length: 477 v=0 o=root 988865281 988865281 IN IP4 123.45.67.145 s=call c=IN IP4 123.45.67.145 t=0 0 m=audio 61270 RTP/AVP 0 8 9 2 3 18 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:Jeyxs/3v1usNxIjWOE3I4Ciu4f0yhGSHB+c75YK2 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: INVITE sip:0368269002@111.22.33.53;user=phone SIP/2.0 (53) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-nvmqr7pt09nq;rport (70) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y (51) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.33.53;user=phone> (44) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 3c26a2a77bbc-c4675b7wav6n (34) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 2 INVITE (14) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Contact: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: P-Key-Flags: keys="3" (21) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: User-Agent: snom300/7.1.30 (26) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: Accept: application/sdp (23) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 12: Allow-Events: talk, hold, refer, call-info (42) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 13: Supported: timer, 100rel, replaces, callerid (44) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 14: Session-Expires: 3600;refresher=uas (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 15: Min-SE: 90 (10) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 16: Proxy-Authorization: Digest username="9004",realm="asterisk",nonce="06b51c5d",uri="sip:0368269002@111.22.33.53;user=phone",response="39f6632ed61562a4fb5c7a7973a97ca4",algorithm=MD5 (180) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 17: Content-Type: application/sdp (29) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 18: Content-Length: 477 (19) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 19: (0) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: v=0 (3) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: o=root 988865281 988865281 IN IP4 123.45.67.145 (48) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: s=call (6) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: c=IN IP4 123.45.67.145 (23) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: t=0 0 (5) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: m=audio 61270 RTP/AVP 0 8 9 2 3 18 4 101 (40) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:Jeyxs/3v1usNxIjWOE3I4Ciu4f0yhGSHB+c75YK2 (82) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:9 g722/8000 (20) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:18 g729/8000 (21) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:4 g723/8000 (20) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=ptime:20 (10) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=encryption:optional (21) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=sendrecv (10) --- (19 headers 19 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 3c26a2a77bbc-c4675b7wav6n Their Tag osiafzl13y Our tag: as77c78176 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:16053 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 123.45.67.145 : 2048 (NAT) Using INVITE request as basis request - 3c26a2a77bbc-c4675b7wav6n [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2798 do_setnat: Setting NAT on RTP to Off Found user '9004' Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 9 Found RTP audio format 2 Found RTP audio format 3 Found RTP audio format 18 Found RTP audio format 4 Found RTP audio format 101 Peer audio RTP is at port 123.45.67.145:61270 Got unsupported a:crypto in SDP offer Found audio description format pcmu for ID 0 Found audio description format pcma for ID 8 Found audio description format g722 for ID 9 Found audio description format g726-32 for ID 2 Found audio description format gsm for ID 3 Found audio description format g729 for ID 18 Found audio description format g723 for ID 4 Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:5556 process_sdp: T38 state changed to 0 on channel <none> Capabilities: us - 0x4 (ulaw), peer - audio=0x190f (g723|gsm|ulaw|alaw|g726|g729|g722)/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 123.45.67.145:61270 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:5636 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:14702 handle_request_invite: Checking SIP call limits for device 9004 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:3265 update_call_counter: Updating call counter for incoming call Looking for 0368269002 in innercall (domain 111.22.33.53) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4109 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4110 sip_new: *** Joint capabilities are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4111 sip_new: *** Our capabilities are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4112 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4135 sip_new: This channel will not be able to handle video. [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:8584 build_route: build_route: Contact hop: <sip:9004@123.45.67.145:2048;line=a4rpauw7>;flow-id=1 list_route: hop: <sip:9004@123.45.67.145:2048;line=a4rpauw7> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:14785 handle_request_invite: SIP/9004-0955ca30: New call is still down.... Trying... <--- Transmitting (no NAT) to 123.45.67.145:2048 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-nvmqr7pt09nq From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone> Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: <sip:0368269002@111.22.33.53> Content-Length: 0 <------------> [Oct 23 20:22:52] DEBUG[29206]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/9004 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 9004 [Oct 23 20:22:52] DEBUG[29200]: chan_sip.c:16734 sip_devicestate: Checking device state for peer 9004 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:287 do_state_change: Changing state for SIP/9004 - state 1 (Not in use) [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@innercall:1] NoOp("SIP/9004-0955ca30", "innercall-0-1") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '9004' [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@innercall:2] NoOp("SIP/9004-0955ca30", "CALLERIDnum___9004") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '9004' [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@innercall:3] NoOp("SIP/9004-0955ca30", "CALLERIDname__9004") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@innercall:4] NoOp("SIP/9004-0955ca30", "EXTEN_________0368269002") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [0368269002@innercall:5] Set("SIP/9004-0955ca30", "CALLERID(num)=0368269002") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [0368269002@innercall:6] Set("SIP/9004-0955ca30", "CALLERID(name)=0368269002") in new stack [Oct 23 20:22:52] DEBUG[29213]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [0368269002@innercall:7] Dial("SIP/9004-0955ca30", "SIP/0368269002@tr01|120|T") in new stack [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:16810 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4632 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:2798 do_setnat: Setting NAT on RTP to Off [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4109 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4110 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4111 sip_new: *** Our capabilities are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4112 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4114 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4135 sip_new: This channel will not be able to handle video. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:3067 sip_call: Outgoing Call for 0368269002 [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:3265 update_call_counter: Updating call counter for outgoing call [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:3082 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:6638 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:6639 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 111.22.33.53 port 12320 Adding codec 0x4 (ulaw) to SDP [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:6771 add_sdp: -- Done with adding codecs to SDP [Oct 23 20:22:52] DEBUG[29213]: channel.c:2375 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:6816 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 0: INVITE sip:0368269002@111.22.44.55 SIP/2.0 (43) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK38e8ecae (57) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002" <sip:0368269002@111.22.44.55>;tag=as3e286d7b (64) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.44.55> (34) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 4: Contact: <sip:0368269002@111.22.33.53> (38) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 5: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 6: CSeq: 102 INVITE (16) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 9: Date: Thu, 23 Oct 2008 11:22:52 GMT (35) [Oct 23 20:22:52] DEBUG[29207]: app_queue.c:661 handle_statechange: Device 'SIP/9004' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 10: Session-Expires: 1800;refresher=uac (35) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 11: Supported: timer (16) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 12: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 13: Content-Type: application/sdp (29) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 14: Content-Length: 184 (19) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4899 parse_request: Header 15: (0) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: v=0 (3) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: o=root 28369 28369 IN IP4 111.22.33.53 (38) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: s=session (9) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: c=IN IP4 111.22.33.53 (21) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: t=0 0 (5) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: m=audio 12320 RTP/AVP 0 (23) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: a=ptime:20 (10) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:4931 parse_request: Line: a=sendrecv (10) 15 headers, 10 lines Reliably Transmitting (no NAT) to 111.22.44.55:5060: INVITE sip:0368269002@111.22.44.55 SIP/2.0 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK38e8ecae From: "0368269002" <sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Contact: <sip:0368269002@111.22.33.53> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 23 Oct 2008 11:22:52 GMT Session-Expires: 1800;refresher=uac Supported: timer Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 184 v=0 o=root 28369 28369 IN IP4 111.22.33.53 s=session c=IN IP4 111.22.33.53 t=0 0 m=audio 12320 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:2076 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 -- Called 0368269002@tr01 <--- SIP read from 111.22.44.55:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK38e8ecae From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55>;tag=3433749823 Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 102 INVITE Date: Thu, 23 Oct 2008 11:22:52 GMT Content-Length: 0 Proxy-Authenticate: Digest realm="CX6820", domain="111.22.44.55", nonce="1224761023518889", opaque="", stale=FALSE, algorithm=MD5 Reason: Q.850;cause=21 <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 407 Proxy Authentication Required (41) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK38e8ecae (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.44.55>;tag=3433749823 (49) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Date: Thu, 23 Oct 2008 11:22:52 GMT (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Proxy-Authenticate: Digest realm="CX6820", domain="111.22.44.55", nonce="1224761023518889", opaque="", stale=FALSE, algorithm=MD5 (130) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Reason: Q.850;cause=21 (22) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Their Tag Our tag: as3e286d7b [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2191 __sip_ack: Acked pending invite 102 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2199 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid ASTERISK-31 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2225 __sip_ack: Stopping retransmission on '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' of Request 102: Match Found [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:12361 handle_response_invite: SIP response 407 to standard invite Transmitting (no NAT) to 111.22.44.55:5060: ACK sip:0368269002@111.22.44.55 SIP/2.0 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK38e8ecae From: "0368269002" <sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55>;tag=3433749823 Contact: <sip:0368269002@111.22.33.53> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:11740 do_proxy_auth: Auth attempt 1 on INVITE [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:6638 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:6639 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 111.22.33.53 port 12320 Adding codec 0x4 (ulaw) to SDP [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:6771 add_sdp: -- Done with adding codecs to SDP [Oct 23 20:22:52] DEBUG[29206]: channel.c:2375 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:6816 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (no NAT) to 111.22.44.55:5060: INVITE sip:0368269002@111.22.44.55 SIP/2.0 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 From: "0368269002" <sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Contact: <sip:0368269002@111.22.33.53> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Proxy-Authorization: Digest username="0368269002", realm="CX6820", algorithm=MD5, uri="111.22.44.55", nonce="1224761023518889", response="d96560662a989e68bd1073032fad9cd5" Date: Thu, 23 Oct 2008 11:22:52 GMT Session-Expires: 1800;refresher=uac Supported: timer Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 184 v=0 o=root 28369 28370 IN IP4 111.22.33.53 s=session c=IN IP4 111.22.33.53 t=0 0 m=audio 12320 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2076 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 <--- SIP read from 111.22.44.55:5060 ---> INVITE sip:0368269002@111.22.33.53 SIP/2.0 Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Contact: <sip:0368269002@111.22.33.53> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 69 Date: Thu, 23 Oct 2008 11:22:52 GMT Session-Expires: 1800;refresher=uac Supported: timer Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 184 Record-Route: <sip:111.22.44.55:5060;maddr=111.22.44.55;lr> v=0 o=root 28369 28370 IN IP4 111.22.33.53 s=session c=IN IP4 111.22.33.53 t=0 0 m=audio 12320 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: INVITE sip:0368269002@111.22.33.53 SIP/2.0 (42) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 (82) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: To: <sip:0368269002@111.22.44.55> (34) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: Contact: <sip:0368269002@111.22.33.53> (38) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: CSeq: 103 INVITE (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: User-Agent: Asterisk PBX (24) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Max-Forwards: 69 (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: Date: Thu, 23 Oct 2008 11:22:52 GMT (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 11: Session-Expires: 1800;refresher=uac (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 12: Supported: timer (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 13: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 14: Content-Type: application/sdp (29) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 15: Content-Length: 184 (19) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 16: Record-Route: <sip:111.22.44.55:5060;maddr=111.22.44.55;lr> (61) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 17: (0) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: v=0 (3) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: o=root 28369 28370 IN IP4 111.22.33.53 (38) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: s=session (9) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: c=IN IP4 111.22.33.53 (21) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: t=0 0 (5) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: m=audio 12320 RTP/AVP 0 (23) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=ptime:20 (10) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4931 parse_request: Line: a=sendrecv (10) --- (17 headers 10 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Their Tag Our tag: as3e286d7b [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:16053 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:1731 parse_sip_options: Begin: parsing SIP "Supported: timer" [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:1739 parse_sip_options: Found SIP option: -timer- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:1745 parse_sip_options: Matched SIP option: timer [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:14425 handle_request_invite: Potential spiral detected. Original RURI was sip:0368269002@111.22.44.55, new RURI is sip:0368269002@111.22.33.53 <--- Transmitting (no NAT) to 111.22.44.55:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 Record-Route: <sip:111.22.44.55:5060;maddr=111.22.44.55;lr> From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: <sip:0368269002@111.22.33.53> Content-Length: 0 <------------> <--- SIP read from 111.22.44.55:5060 ---> SIP/2.0 100 Trying Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Content-Length: 0 From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b Cseq: 103 INVITE To: <sip:0368269002@111.22.44.55> Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 Date: Thu, 23 Oct 2008 11:23:43 GMT <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 100 Trying (18) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Cseq: 103 INVITE (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: To: <sip:0368269002@111.22.44.55> (34) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Date: Thu, 23 Oct 2008 11:23:43 GMT (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Their Tag Our tag: as3e286d7b [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2258 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission ASTERISK-33 - INVITE (got response) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2266 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' Request 103: Found [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:12361 handle_response_invite: SIP response 100 to standard invite -- Now forwarding SIP/9004-0955ca30 to 'Local/0368269002@pstn' (thanks to SIP/tr01-0956d4b8) [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 23 20:22:52] DEBUG[29213]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 23 20:22:52] DEBUG[29213]: rtp.c:1585 ast_rtp_make_compatible: Channel 'Local/0368269002@pstn-6506,1' has no RTP, not doing anything [Oct 23 20:22:52] DEBUG[29213]: channel.c:1505 ast_hangup: Hanging up channel 'SIP/tr01-0956d4b8' [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:3582 sip_hangup: Hangup call SIP/tr01-0956d4b8, SIP callid 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:3605 sip_hangup: Hanging up channel in state Down (not UP) Scheduling destruction of SIP dialog '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' in 32000 ms (Method: INVITE) [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:2191 __sip_ack: Acked pending invite 103 [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:2225 __sip_ack: Stopping retransmission on '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' of Request 103: Match Found [Oct 23 20:22:52] NOTICE[29213]: chan_sip.c:3648 sip_hangup: 487 Hunter a Reliably Transmitting (no NAT) to 111.22.44.55:5060: CANCEL sip:0368269002@111.22.44.55 SIP/2.0 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 From: "0368269002" <sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Oct 23 20:22:52] DEBUG[29213]: chan_sip.c:2076 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 Scheduling destruction of SIP dialog '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' in 32000 ms (Method: INVITE) [Oct 23 20:22:52] DEBUG[29213]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tr01 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tr01 [Oct 23 20:22:52] DEBUG[29200]: chan_sip.c:16734 sip_devicestate: Checking device state for peer tr01 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:287 do_state_change: Changing state for SIP/tr01 - state 1 (Not in use) [Oct 23 20:22:52] DEBUG[29207]: app_queue.c:661 handle_statechange: Device 'SIP/tr01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@pstn:1] NoOp("Local/0368269002@pstn-6506,2", "pstn-0-0") in new stack [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0368269002' [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@pstn:2] NoOp("Local/0368269002@pstn-6506,2", "CALLERIDnum___0368269002") in new stack [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0368269002' [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@pstn:3] NoOp("Local/0368269002@pstn-6506,2", "CALLERIDname__0368269002") in new stack [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [0368269002@pstn:4] NoOp("Local/0368269002@pstn-6506,2", "EXTEN_________0368269002") in new stack [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0368269002' [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [0368269002@pstn:5] Set("Local/0368269002@pstn-6506,2", "CALLERID(num)=0368269002") in new stack [Oct 23 20:22:52] DEBUG[29214]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [0368269002@pstn:6] Dial("Local/0368269002@pstn-6506,2", "SIP/9005|120|t") in new stack [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:16810 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4632 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:2798 do_setnat: Setting NAT on RTP to Off [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4109 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4110 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4111 sip_new: *** Our capabilities are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4112 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4114 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4135 sip_new: This channel will not be able to handle video. [Oct 23 20:22:52] DEBUG[29214]: rtp.c:1592 ast_rtp_make_compatible: Channel 'Local/0368269002@pstn-6506,2' has no RTP, not doing anything [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:3067 sip_call: Outgoing Call for 9005 [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:3265 update_call_counter: Updating call counter for outgoing call [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:3082 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:6638 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:6639 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 111.22.33.53 port 13460 Adding codec 0x4 (ulaw) to SDP [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:6771 add_sdp: -- Done with adding codecs to SDP [Oct 23 20:22:52] DEBUG[29214]: channel.c:2375 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:6816 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 0: INVITE sip:9005@123.45.67.146:2051;line=7ddcubky SIP/2.0 (57) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 (57) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 (63) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 3: To: <sip:9005@123.45.67.146:2051;line=7ddcubky> (48) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 4: Contact: <sip:0368269002@111.22.33.53> (38) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 5: Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 (54) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 6: CSeq: 102 INVITE (16) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 9: Date: Thu, 23 Oct 2008 11:22:52 GMT (35) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 11: Content-Type: application/sdp (29) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 12: Content-Length: 184 (19) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4899 parse_request: Header 13: (0) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: v=0 (3) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: o=root 28369 28369 IN IP4 111.22.33.53 (38) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: s=session (9) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: c=IN IP4 111.22.33.53 (21) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: t=0 0 (5) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: m=audio 13460 RTP/AVP 0 (23) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) <--- SIP read from 111.22.44.55:5060 ---> CANCEL sip:0368269002@111.22.33.53 SIP/2.0 Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55> Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 CANCEL User-Agent: Asterisk PBX Max-Forwards: 69 Content-Length: 0 Date: Thu, 23 Oct 2008 11:23:43 GMT Reason: Q.850;cause=16 <-------------> [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: CANCEL sip:0368269002@111.22.33.53 SIP/2.0 (42) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 (82) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:0368269002@111.22.44.55> (34) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 103 CANCEL (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Max-Forwards: 69 (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Date: Thu, 23 Oct 2008 11:23:43 GMT (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: Reason: Q.850;cause=16 (22) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = No match Their Call ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 Their Tag Our tag: as1caad726 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Their Tag Our tag: as3e286d7b [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:16053 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL Sending to 111.22.44.55 : 5060 (no NAT) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:1684 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Scheduling destruction of SIP dialog '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' in 32000 ms (Method: CANCEL) <--- Transmitting (no NAT) to 111.22.44.55:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 111.22.44.55:5060;branch=z9hG4bKb43d8360eae971511618587f5bbd2ce6 From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b To: <sip:0368269002@111.22.44.55>;tag=as3e286d7b Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 CSeq: 103 CANCEL User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: <sip:0368269002@111.22.33.53> Content-Length: 0 <------------> <--- SIP read from 111.22.44.55:5060 ---> SIP/2.0 200 OK Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Content-Length: 0 From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b Cseq: 103 CANCEL To: <sip:0368269002@111.22.44.55>;tag=3433749823 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 Allow: INVITE,ACK,PRACK,BYE,CANCEL,REGISTER,UPDATE Date: Thu, 23 Oct 2008 11:23:43 GMT <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Call-ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 (55) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: From: "0368269002"<sip:0368269002@111.22.44.55>;tag=as3e286d7b (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Cseq: 103 CANCEL (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: To: <sip:0368269002@111.22.44.55>;tag=3433749823 (49) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK72ad35f1 (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Allow: INVITE,ACK,PRACK,BYE,CANCEL,REGISTER,UPDATE (50) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Date: Thu, 23 Oct 2008 11:23:43 GMT (35) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = No match Their Call ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 Their Tag Our tag: as1caad726 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 0ecddf452de602073dbcacd87d30f7ed@111.22.44.55 Their Tag as3e286d7b Our tag: as3e286d7b [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2199 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid ASTERISK-35 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2225 __sip_ack: Stopping retransmission on '0ecddf452de602073dbcacd87d30f7ed@111.22.44.55' of Request 103: Match Found [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: a=ptime:20 (10) [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:4931 parse_request: Line: a=sendrecv (10) 13 headers, 10 lines Reliably Transmitting (no NAT) to 123.45.67.146:2051: INVITE sip:9005@123.45.67.146:2051;line=7ddcubky SIP/2.0 Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 To: <sip:9005@123.45.67.146:2051;line=7ddcubky> Contact: <sip:0368269002@111.22.33.53> Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 23 Oct 2008 11:22:52 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 184 v=0 o=root 28369 28369 IN IP4 111.22.33.53 s=session c=IN IP4 111.22.33.53 t=0 0 m=audio 13460 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Oct 23 20:22:52] DEBUG[29214]: chan_sip.c:2076 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 -- Called 9005 <--- SIP read from 123.45.67.146:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 CSeq: 102 INVITE Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 (54) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 Their Tag Our tag: as1caad726 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2258 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission ASTERISK-38 - INVITE (got response) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2266 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53' Request 102: Found [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:12361 handle_response_invite: SIP response 180 to standard invite [Oct 23 20:22:52] DEBUG[29206]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/9005 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 9005 [Oct 23 20:22:52] DEBUG[29200]: chan_sip.c:16734 sip_devicestate: Checking device state for peer 9005 [Oct 23 20:22:52] DEBUG[29200]: devicestate.c:287 do_state_change: Changing state for SIP/9005 - state 1 (Not in use) -- SIP/9005-09570d38 is ringing [Oct 23 20:22:52] DEBUG[29207]: app_queue.c:661 handle_statechange: Device 'SIP/9005' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 23 20:22:52] DEBUG[29214]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Local/0368269002@pstn-6506,2' has no RTP, not doing anything -- Local/0368269002@pstn-6506,1 is ringing [Oct 23 20:22:52] DEBUG[29213]: rtp.c:1510 ast_rtp_early_bridge: Channel 'Local/0368269002@pstn-6506,1' has no RTP, not doing anything <--- Transmitting (no NAT) to 123.45.67.145:2048 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 123.45.67.145:2048;branch=z9hG4bK-nvmqr7pt09nq From: "9004" <sip:9004@111.22.33.53>;tag=osiafzl13y To: <sip:0368269002@111.22.33.53;user=phone>;tag=as7366348a Call-ID: 3c26a2a77bbc-c4675b7wav6n CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: <sip:0368269002@111.22.33.53> Content-Length: 0 <------------> dev01*CLI> <--- SIP read from 123.45.67.146:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 CSeq: 102 INVITE Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 (57) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 (54) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 (63) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Content-Length: 0 (17) [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 Their Tag p9u9uegei3 Our tag: as1caad726 [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:2266 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53' Request 102: Found [Oct 23 20:22:52] DEBUG[29206]: chan_sip.c:12361 handle_response_invite: SIP response 180 to standard invite -- SIP/9005-09570d38 is ringing [Oct 23 20:22:52] DEBUG[29214]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Local/0368269002@pstn-6506,2' has no RTP, not doing anything dev01*CLI> <--- SIP read from 123.45.67.146:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 CSeq: 102 INVITE Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Content-Length: 0 <-------------> [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 1: Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 (57) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 2: From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 (63) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 3: To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 (63) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 4: Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 (54) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 6: Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 (63) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 8: Allow-Events: talk, hold, refer, call-info (42) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 9: Content-Length: 0 (17) [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:4688 find_call: = Found Their Call ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 Their Tag p9u9uegei3 Our tag: as1caad726 [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:2266 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53' Request 102: Found [Oct 23 20:22:53] DEBUG[29206]: chan_sip.c:12361 handle_response_invite: SIP response 180 to standard invite -- SIP/9005-09570d38 is ringing [Oct 23 20:22:53] DEBUG[29214]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Local/0368269002@pstn-6506,2' has no RTP, not doing anything dev01*CLI> <--- SIP read from 123.45.67.146:2051 ---> <-------------> [Oct 23 20:22:54] DEBUG[29206]: chan_sip.c:4899 parse_request: Header 0: (0) [Oct 23 20:22:55] DEBUG[29214]: rtp.c:879 ast_rtcp_read: Got RTCP report of 52 bytes dev01*CLI> <--- SIP read from 123.45.67.146:2051 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 111.22.33.53:5060;branch=z9hG4bK6d018331 From: "0368269002" <sip:0368269002@111.22.33.53>;tag=as1caad726 To: <sip:9005@123.45.67.146:2051;line=7ddcubky>;tag=p9u9uegei3 Call-ID: 1621342f53fa7e6f771c94ca422f6dcf@111.22.33.53 CSeq: 102 INVITE Contact: <sip:9005@123.45.67.146:2051;line=7ddcubky>;flow-id=1 User-Agent: snom300/7.1.30 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 275 v=0 o=root 2016450807 2016450808 IN IP4 123.45.67.146 s=call c=IN IP4 123.45.67.146 t=0 0 m=audio 57446 RTP/AVP 0 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:e8BnqvcCMci9K+hXzCAjfJT7E2/z6QnlrmdfQzlV a=rtpmap | ||
| Comments: | By: Leif Madsen (lmadsen) 2008-10-27 19:46:05 I don't see where in your dialog where the 487 Request Terminated actually happens... Also, can you please attach this as a file, rather than as a paste into the bug? It makes working with the bug extremely difficult. For now I will leave what you have, but I'd prefer actually a PCAP capture (i.e. wireshark or tcpdump) so that it is easier to look at the trace. Thanks! By: Jason Parker (jparker) 2008-11-20 16:58:34.000-0600 Per lmadsen, we can't tell where the 487 is actually happening (looking at the line, it looks bogus). If you'd like to upload the log as a file, and/or upload a pcap trace of this happening, we can reopen this. | ||