localhost*CLI> localhost*CLI> -- Attempting call on SIP/2000 for 2000@demo:2 (Retry 1) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:15662 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4454 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3948 sip_new: *** Our native formats are 0x2 (gsm) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3949 sip_new: *** Joint capabilities are 0x0 (nothing) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3950 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3951 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3953 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3974 sip_new: This channel will not be able to handle video. [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:2953 sip_call: Outgoing Call for [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:2968 sip_call: Our T38 capability (0), joint T38 capability (0) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:6342 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:6343 add_sdp: ** Our prefcodec: 0x40 (slin) Audio is at 192.168.15.102 port 11798 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:6474 add_sdp: -- Done with adding codecs to SDP [Nov 2 20:45:36] DEBUG[24008]: channel.c:2565 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:6519 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 0: INVITE sip:192.168.15.101 SIP/2.0 (33) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.15.102:5060;branch=z9hG4bK48e657aa;rport (65) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 2: From: "asterisk" ;tag=as67552c31 (61) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 3: To: (24) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 4: Contact: (38) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 5: Call-ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 (56) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 6: CSeq: 102 INVITE (16) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 8: Max-Forwards: 70 (16) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 9: Date: Sat, 03 Nov 2007 01:45:36 GMT (35) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 11: Supported: replaces (19) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 12: Content-Type: application/sdp (29) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 13: Content-Length: 291 (19) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4719 parse_request: Header 14: (0) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: v=0 (3) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: o=root 23947 23947 IN IP4 192.168.15.102 (40) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: s=session (9) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: c=IN IP4 192.168.15.102 (23) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: t=0 0 (5) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: m=audio 11798 RTP/AVP 3 0 8 101 (31) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=fmtp:101 0-16 (15) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=silenceSupp:off - - - - (25) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=ptime:20 (10) [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:4751 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 192.168.15.101:5060: INVITE sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.102:5060;branch=z9hG4bK48e657aa;rport From: "asterisk" ;tag=as67552c31 To: Contact: Call-ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Sat, 03 Nov 2007 01:45:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 291 v=0 o=root 23947 23947 IN IP4 192.168.15.102 s=session c=IN IP4 192.168.15.102 t=0 0 m=audio 11798 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Nov 2 20:45:36] DEBUG[24008]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Nov 2 20:45:36] DEBUG[24008]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #15 localhost*CLI> <--- SIP read from 192.168.15.101:5060 ---> SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 192.168.15.102:5060;branch=z9hG4bK48e657aa;rport From: "asterisk" ;tag=as67552c31 To: ;tag=7 Call-ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 CSeq: 102 INVITE Contact: Content-Length: 0 <-------------> [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 0: SIP/2.0 302 Moved Temporarily (29) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.15.102:5060;branch=z9hG4bK48e657aa;rport (65) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 2: From: "asterisk" ;tag=as67552c31 (61) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 3: To: ;tag=7 (30) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 4: Call-ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 (56) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 5: CSeq: 102 INVITE (16) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 6: Contact: (39) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 7: Content-Length: 0 (17) [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4719 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:4507 find_call: = Found Their Call ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 Their Tag Our tag: as67552c31 [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:2140 __sip_ack: Acked pending invite 102 [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '1657fa010f18e4fb63683b5f4c562346@192.168.15.102' of Request 102: Match Not Found -- Got SIP response 302 "Moved Temporarily" back from 192.168.15.101 [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:11752 parse_moved_contact: Found promiscuous redirection to 'SIP/1000@192.168.15.101:5061' Transmitting (NAT) to 192.168.15.101:5060: ACK sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.102:5060;branch=z9hG4bK48e657aa;rport From: "asterisk" ;tag=as67552c31 To: ;tag=7 Contact: Call-ID: 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Nov 2 20:45:36] DEBUG[23965]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1657fa010f18e4fb63683b5f4c562346@192.168.15.102 > Channel SIP/2000-09c13400 was never answered. [Nov 2 20:45:37] DEBUG[24008]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/2000-09c13400' [Nov 2 20:45:37] DEBUG[24008]: chan_sip.c:3445 sip_hangup: Hangup call SIP/2000-09c13400, SIP callid 1657fa010f18e4fb63683b5f4c562346@192.168.15.102) [Nov 2 20:45:37] DEBUG[24008]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2000-09c13400 [Nov 2 20:45:37] NOTICE[24008]: cdr.c:434 ast_cdr_free: CDR on channel 'SIP/2000-09c13400' not posted [Nov 2 20:45:37] NOTICE[24008]: pbx_spool.c:341 attempt_thread: Call failed to go through, reason (5) Remote end is Busy [Nov 2 20:45:37] DEBUG[23950]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2000 [Nov 2 20:45:37] DEBUG[23950]: chan_sip.c:15593 sip_devicestate: Checking device state for peer 2000 [Nov 2 20:45:37] DEBUG[23950]: devicestate.c:287 do_state_change: Changing state for SIP/2000 - state 1 (Not in use) [Nov 2 20:45:37] DEBUG[24009]: app_queue.c:566 changethread: Device 'SIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Really destroying SIP dialog '1657fa010f18e4fb63683b5f4c562346@192.168.15.102' Method: INVITE localhost*CLI>