Asterisk SVN-trunk-r59090, Copyright (C) 1999 - 2006 Digium, Inc. and others. ... Asterisk Ready. [Mar 22 22:02:47] NOTICE[25376]: chan_sip.c:12812 handle_response_peerpoke: Peer 'orbi' is now Reachable. (19ms / 2000ms) Core debug was 5 and is now 4 Verbosity was 5 and is now 4 SIP Debugging Enabled for IP: REMOTE.PROVIDER.IP:5060 *CLI> [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 42]: CANCEL sip:CALLED.NUMBER@LOCAL.AST.IP SIP/2.0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 58]: Via: SIP/2.0/UDP LOCAL.PHONE.IP:5060;branch=z9hG4bK-964daca2 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 63]: From: "spa921" ;tag=d1e723e5d10ffa7ao0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 33]: To: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 38]: Call-ID: f141481-f0d8628e@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 16]: CSeq: 102 CANCEL [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [165]: Authorization: Digest username="spa921",realm="asterisk",nonce="0499318b",uri="sip:CALLED.NUMBER@LOCAL.AST.IP",algorithm=MD5,response="42028cc47847de922136e344c8125821" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 35]: User-Agent: Sipura/SPA921-4.1.10(b) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 17]: Content-Length: 0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 0]: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4793 find_call: That's odd... Got a request in unknown dialog. Callid f141481-f0d8628e@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:15497 sipsock_read: Invalid SIP message - rejected , no callid, len 505 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 42]: INVITE sip:CALLED.NUMBER@LOCAL.AST.IP SIP/2.0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 58]: Via: SIP/2.0/UDP LOCAL.PHONE.IP:5060;branch=z9hG4bK-8d2b5afd [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 63]: From: "spa921" ;tag=60cbe6308be7bd85o0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 33]: To: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 39]: Call-ID: 600b37cc-85593899@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 16]: CSeq: 101 INVITE [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [ 48]: Contact: "spa921" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 12]: Expires: 240 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 35]: User-Agent: Sipura/SPA921-4.1.10(b) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 19]: Content-Length: 393 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 13 [ 0]: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 0 [ 3]: v=0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 1 [ 35]: o=- 47990 47990 IN IP4 LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 2 [ 3]: s=- [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 3 [ 21]: c=IN IP4 LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 4 [ 5]: t=0 0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 5 [ 45]: m=audio 16414 RTP/AVP 0 2 4 8 18 96 97 98 101 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 16 [ 10]: a=ptime:30 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 17 [ 10]: a=sendrecv [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2844 do_setnat: Setting NAT on RTP to Off [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4665 sip_alloc: Allocating new SIP dialog for 600b37cc-85593899@LOCAL.PHONE.IP - INVITE (With RTP) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:15312 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:13996 handle_request_invite: Initializing initreq for method INVITE - callid 600b37cc-85593899@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2844 do_setnat: Setting NAT on RTP to Off [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2117 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 39]: ACK sip:CALLED.NUMBER@LOCAL.AST.IP SIP/2.0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 58]: Via: SIP/2.0/UDP LOCAL.PHONE.IP:5060;branch=z9hG4bK-8d2b5afd [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 63]: From: "spa921" ;tag=60cbe6308be7bd85o0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 48]: To: ;tag=as06a2f0bb [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 39]: Call-ID: 600b37cc-85593899@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 13]: CSeq: 101 ACK [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [ 48]: Contact: "spa921" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 35]: User-Agent: Sipura/SPA921-4.1.10(b) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 17]: Content-Length: 0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 0]: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:15312 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2225 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #11 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2236 __sip_ack: Stopping retransmission on '600b37cc-85593899@LOCAL.PHONE.IP' of Response 101: Match Found [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 42]: INVITE sip:CALLED.NUMBER@LOCAL.AST.IP SIP/2.0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 57]: Via: SIP/2.0/UDP LOCAL.PHONE.IP:5060;branch=z9hG4bK-e57e172 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 63]: From: "spa921" ;tag=60cbe6308be7bd85o0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 33]: To: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 39]: Call-ID: 600b37cc-85593899@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [165]: Authorization: Digest username="spa921",realm="asterisk",nonce="05c0448c",uri="sip:CALLED.NUMBER@LOCAL.AST.IP",algorithm=MD5,response="6edac33bd3ae072cff16ea4d40b26378" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 48]: Contact: "spa921" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 12]: Expires: 240 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 35]: User-Agent: Sipura/SPA921-4.1.10(b) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 11 [ 19]: Content-Length: 393 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 14 [ 0]: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 0 [ 3]: v=0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 1 [ 35]: o=- 47990 47990 IN IP4 LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 2 [ 3]: s=- [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 3 [ 21]: c=IN IP4 LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 4 [ 5]: t=0 0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 5 [ 45]: m=audio 16414 RTP/AVP 0 2 4 8 18 96 97 98 101 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 7 [ 23]: a=rtpmap:2 G726-32/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 8 [ 20]: a=rtpmap:4 G723/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 16 [ 10]: a=ptime:30 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 17 [ 10]: a=sendrecv [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:15312 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:13996 handle_request_invite: Initializing initreq for method INVITE - callid 600b37cc-85593899@LOCAL.PHONE.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2844 do_setnat: Setting NAT on RTP to Off [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:5535 process_sdp: T38 state changed to 0 on channel [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:5626 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:14077 handle_request_invite: Checking SIP call limits for device spa921 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:3307 update_call_counter: Updating call counter for incoming call [Mar 22 22:03:26] DEBUG[25376]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4128 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4129 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4130 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Mar 22 22:03:26] DEBUG[25376]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4131 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4161 sip_new: This channel will not be able to handle video. [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:8492 build_route: build_route: Contact hop: "spa921" [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:14152 handle_request_invite: SIP/spa921-081da970: New call is still down.... Trying... [Mar 22 22:03:26] DEBUG[25376]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/spa921-081da970 [Mar 22 22:03:26] DEBUG[25376]: pbx.c:1716 pbx_extension_helper: Launching 'Set' -- Executing [CALLED.NUMBER@toorbi:1] Set("SIP/spa921-081da970", "CALLERID(all)=Joe Smith ") in new stack [Mar 22 22:03:26] DEBUG[25376]: pbx.c:1716 pbx_extension_helper: Launching 'Dial' -- Executing [CALLED.NUMBER@toorbi:2] Dial("SIP/spa921-081da970", "SIP/CALLED.NUMBER@orbi") in new stack [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:16013 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4665 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2844 do_setnat: Setting NAT on RTP to Off [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:1785 obproxy_get: OBPROXY: Not applying OBproxy to this call [Mar 22 22:03:26] DEBUG[25376]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4128 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4129 sip_new: *** Joint capabilities are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4130 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Mar 22 22:03:26] DEBUG[25376]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4131 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4133 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4161 sip_new: This channel will not be able to handle video. [Mar 22 22:03:26] DEBUG[25376]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - spa921 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:15944 sip_devicestate: Checking device state for peer spa921 [Mar 22 22:03:26] DEBUG[25376]: devicestate.c:428 do_state_change: Changing state for SIP/spa921 - state 1 (Not in use) [Mar 22 22:03:26] DEBUG[25376]: channel.c:3244 ast_channel_inherit_variables: Not copying variable STACK-toorbi-CALLED.NUMBER-2. [Mar 22 22:03:26] DEBUG[25376]: channel.c:3244 ast_channel_inherit_variables: Not copying variable STACK-toorbi-CALLED.NUMBER-1. [Mar 22 22:03:26] DEBUG[25376]: channel.c:3244 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 22 22:03:26] DEBUG[25376]: channel.c:3244 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 22 22:03:26] DEBUG[25376]: channel.c:3244 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:3124 sip_call: Outgoing Call for CALLED.NUMBER [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:3307 update_call_counter: Updating call counter for outgoing call [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:3142 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:6678 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:6680 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:6697 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at LOCAL.IP port 13570 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:6841 add_sdp: -- Done with adding codecs to SDP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:6901 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:1720 initialize_initreq: Initializing initreq for method INVITE - callid 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 44]: INVITE sip:CALLED.NUMBER@REMOTE.PROVIDER.IP SIP/2.0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 69]: From: "Joe Smith" ;tag=as30f63193 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 35]: To: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 45]: Contact: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 54]: Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r59090 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 35]: Date: Thu, 22 Mar 2007 20:03:26 GMT [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 11 [ 19]: Supported: replaces [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 13 [ 19]: Content-Length: 287 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 14 [ 0]: [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 0 [ 3]: v=0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 1 [ 38]: o=root 25372 25372 IN IP4 LOCAL.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 2 [ 9]: s=session [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 3 [ 21]: c=IN IP4 LOCAL.IP [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 4 [ 5]: t=0 0 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 5 [ 31]: m=audio 13570 RTP/AVP 0 3 8 101 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 12 [ 10]: a=ptime:20 [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 13 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to REMOTE.PROVIDER.IP:5060: INVITE sip:CALLED.NUMBER@REMOTE.PROVIDER.IP SIP/2.0 Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport Max-Forwards: 70 From: "Joe Smith" ;tag=as30f63193 To: Contact: Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r59090 Date: Thu, 22 Mar 2007 20:03:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 287 v=0 o=root 25372 25372 IN IP4 LOCAL.IP s=session c=IN IP4 LOCAL.IP t=0 0 m=audio 13570 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/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 --- [Mar 22 22:03:26] DEBUG[25376]: chan_sip.c:2117 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 -- Called CALLED.NUMBER@orbi <--- SIP read from REMOTE.PROVIDER.IP:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport From: "Joe Smith" ;tag=as30f63193 To: ;tag=007D-0005-DED5D839 Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP CSeq: 102 INVITE Contact: User-Agent: VEGA400/10.02.07.2xS019 Content-Length: 0 <-------------> [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 69]: From: "Joe Smith" ;tag=as30f63193 [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 58]: To: ;tag=007D-0005-DED5D839 [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 54]: Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 45]: Contact: [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [ 35]: User-Agent: VEGA400/10.02.07.2xS019 [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 17]: Content-Length: 0 [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:2270 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #13 - INVITE (got response) [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:2279 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP' Request 102: Found [Mar 22 22:03:27] DEBUG[25376]: chan_sip.c:12305 handle_response_invite: SIP response 100 to standard invite <--- SIP read from REMOTE.PROVIDER.IP:5060 ---> SIP/2.0 183 Progress With Media Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport From: "Joe Smith" ;tag=as30f63193 To: ;tag=007D-0005-DED5D839 Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP CSeq: 102 INVITE Contact: User-Agent: VEGA400/10.02.07.2xS019 Content-Type: application/sdp Content-Length: 202 v=0 o=Vega 193 193 IN IP4 REMOTE.PROVIDER.IP s=Sip Call c=IN IP4 REMOTE.PROVIDER.IP t=0 0 m=audio 10042 RTP/AVP 0 96 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15,16 <-------------> [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 0 [ 31]: SIP/2.0 183 Progress With Media [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP LOCAL.IP:5060;branch=z9hG4bK76788ca4;rport [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 2 [ 69]: From: "Joe Smith" ;tag=as30f63193 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 3 [ 58]: To: ;tag=007D-0005-DED5D839 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 4 [ 54]: Call-ID: 595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 6 [ 45]: Contact: [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 7 [ 35]: User-Agent: VEGA400/10.02.07.2xS019 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 8 [ 29]: Content-Type: application/sdp [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 9 [ 19]: Content-Length: 202 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Header 10 [ 0]: [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 0 [ 3]: v=0 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 1 [ 36]: o=Vega 193 193 IN IP4 REMOTE.PROVIDER.IP [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 2 [ 10]: s=Sip Call [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 3 [ 23]: c=IN IP4 REMOTE.PROVIDER.IP [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 4 [ 5]: t=0 0 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 5 [ 26]: m=audio 10042 RTP/AVP 0 96 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 6 [ 10]: a=sendrecv [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 8 [ 32]: a=rtpmap:96 telephone-event/8000 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:4943 parse_request: Body 9 [ 17]: a=fmtp:96 0-15,16 --- (10 headers 10 lines) --- [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:2279 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '595da9c10ebd2f5f2fa5efa34aaaafa7@LOCAL.IP' Request 102: Found [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:12305 handle_response_invite: SIP response 183 to standard invite Found RTP audio format 0 Found RTP audio format 96 Peer audio RTP is at port REMOTE.PROVIDER.IP:10042 Found description format PCMU for ID 0 Found description format telephone-event for ID 96 Got unsupported a:fmtp in SDP offer [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:5535 process_sdp: T38 state changed to 0 on channel SIP/orbi-081e1990 Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port REMOTE.PROVIDER.IP:10042 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:5626 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:5633 process_sdp: We have an owner, now see if we need to change this call -- SIP/orbi-081e1990 is making progress passing it to SIP/spa921-081da970 [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:6956 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:6678 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:6680 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:6841 add_sdp: -- Done with adding codecs to SDP [Mar 22 22:03:33] DEBUG[25376]: chan_sip.c:6901 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 22 22:03:33] DEBUG[25376]: rtp.c:2811 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 22 22:03:33] DEBUG[25376]: rtp.c:2828 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 22 22:03:33] DEBUG[25376]: rtp.c:2811 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 22 22:03:33] DEBUG[25376]: rtp.c:2828 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160