Asterisk 1.4.1, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= Connected to Asterisk 1.4.1 currently running on poweredge (pid = 14139) -- Remote UNIX connection Verbosity is at least 3 poweredge*CLI> core set debug 3 Core debug was 0 and is now 3 [Mar 19 18:08:05] DEBUG[14183]: chan_sip.c:14774 sipsock_read: Invalid SIP message - rejected , no callid, len 351 poweredge*CLI> sip debug SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. poweredge*CLI> <--- SIP read from 192.168.48.92:5060 ---> INVITE sip:1005@phonegw.xarin.com SIP/2.0 Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-a3b07ef0 From: 1003 ;tag=78b9c320ffab7f70o0 To: Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 101 INVITE Max-Forwards: 70 Contact: 1003 Expires: 240 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 430 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 190461329 190461329 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16474 RTP/AVP 18 0 2 4 8 96 97 98 100 101 a=rtpmap:18 G729a/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> --- (14 headers 19 lines) --- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2578 do_setnat: Setting NAT on VRTP to Off [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:4308 sip_alloc: Allocating new SIP dialog for 9bf010e0-a3538cb0@192.168.48.92 - INVITE (With RTP) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1686 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1698 parse_sip_options: Found private SIP option, not supported: x-sipura Sending to 192.168.48.92 : 5060 (no NAT) Using INVITE request as basis request - 9bf010e0-a3538cb0@192.168.48.92 [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2578 do_setnat: Setting NAT on VRTP to Off poweredge*CLI> <--- Reliably Transmitting (no NAT) to 192.168.48.92:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-a3b07ef0;received=192.168.48.92 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as6a19a9e6 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="phonegw.xarin.com", nonce="224b1e3a" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '9bf010e0-a3538cb0@192.168.48.92' in 32000 ms (Method: INVITE) Found user 'sipura3' poweredge*CLI> <--- SIP read from 192.168.48.92:5060 ---> ACK sip:1005@phonegw.xarin.com SIP/2.0 Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-a3b07ef0 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as6a19a9e6 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 101 ACK Max-Forwards: 70 Contact: 1003 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> --- (10 headers 0 lines) --- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '9bf010e0-a3538cb0@192.168.48.92' of Response 101: Match Not Found poweredge*CLI> <--- SIP read from 192.168.48.92:5060 ---> INVITE sip:1005@phonegw.xarin.com SIP/2.0 Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-c5229b98 From: 1003 ;tag=78b9c320ffab7f70o0 To: Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="224b1e3a",uri="sip:1005@phonegw.xarin.com",algorithm=MD5,response="7709fb1793d8ca5315720ab2202f91b2" Contact: 1003 Expires: 240 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 430 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 190461329 190461329 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16474 RTP/AVP 18 0 2 4 8 96 97 98 100 101 a=rtpmap:18 G729a/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> --- (15 headers 19 lines) --- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1686 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:1698 parse_sip_options: Found private SIP option, not supported: x-sipura Sending to 192.168.48.92 : 5060 (no NAT) Using INVITE request as basis request - 9bf010e0-a3538cb0@192.168.48.92 [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2578 do_setnat: Setting NAT on VRTP to Off Found user 'sipura3' Found RTP audio format 18 Found RTP audio format 0 Found RTP audio format 2 Found RTP audio format 4 Found RTP audio format 8 Found RTP audio format 96 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 100 Found RTP audio format 101 Peer audio RTP is at port 192.168.48.92:16474 Found description format G729a for ID 18 Found description format PCMU for ID 0 Found description format G726-32 for ID 2 Found description format G723 for ID 4 Found description format PCMA for ID 8 Found description format G726-40 for ID 96 Found description format G726-24 for ID 97 Found description format G726-16 for ID 98 Found description format NSE for ID 100 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:5123 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x3f19ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|g722|jpeg|png|h261|h263|h263p|h264), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x90d (g723|ulaw|alaw|g726|g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.48.92:16474 [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:5203 process_sdp: We're settling with these formats: 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:13378 handle_request_invite: Checking SIP call limits for device sipura3 [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call Looking for 1005 in internal (domain phonegw.xarin.com) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3803 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x3f19ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|g722|jpeg|png|h261|h263|h263p|h264) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:7964 build_route: build_route: Contact hop: 1003 list_route: hop: [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:13453 handle_request_invite: SIP/sipura3-08c357d0: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.48.92:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-c5229b98;received=192.168.48.92 From: 1003 ;tag=78b9c320ffab7f70o0 To: Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 18:08:15] DEBUG[14183]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c357d0 [Mar 19 18:08:15] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer sipura3 [Mar 19 18:08:15] DEBUG[14164]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 18:08:15] DEBUG[14197]: pbx.c:1791 pbx_extension_helper: Launching 'Dial' -- Executing [1005@internal:1] Dial("SIP/sipura3-08c357d0", "SIP/polycom1|20|rh") in new stack [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:15267 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14198]: app_queue.c:546 changethread: Device 'SIP/sipura3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:4308 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:2578 do_setnat: Setting NAT on VRTP to Off [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3803 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x3f19ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|g722|jpeg|png|h261|h263|h263p|h264) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3808 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Mar 19 18:08:15] DEBUG[14197]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-internal-1005-1. [Mar 19 18:08:15] DEBUG[14197]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 19 18:08:15] DEBUG[14197]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 19 18:08:15] DEBUG[14197]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 19 18:08:15] DEBUG[14197]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:2828 sip_call: Outgoing Call for polycom1 [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:3001 update_call_counter: Updating call counter for outgoing call [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:2843 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:6182 add_sdp: ** Our capability: 0x3f09ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|jpeg|png|h261|h263|h263p|h264) Video flag: False [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:6198 add_sdp: This call needs video offers! Video is at 192.168.48.1 port 15370 Audio is at 192.168.48.1 port 14742 Adding codec 0x4 (ulaw) to SDP Adding codec 0x1 (g723) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x10 (g726aal2) to SDP Adding codec 0x20 (adpcm) to SDP Adding codec 0x40 (slin) to SDP Adding codec 0x80 (lpc10) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x800 (g726) to SDP Adding codec 0x10000 (jpeg) to SDP Adding codec 0x20000 (png) to SDP Adding codec 0x40000 (h261) to SDP Adding codec 0x80000 (h263) to SDP Adding codec 0x100000 (h263p) to SDP Adding codec 0x200000 (h264) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 19 18:08:15] DEBUG[14197]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x3f09ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|jpeg|png|h261|h263|h263p|h264) Reliably Transmitting (no NAT) to 192.168.48.93:5060: INVITE sip:polycom1@192.168.48.93 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK72e81e40;rport From: "48 Lounge" ;tag=as4f3a8c95 To: Contact: Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 19 Mar 2007 18:08:15 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 684 v=0 o=root 14139 14139 IN IP4 192.168.48.1 s=session c=IN IP4 192.168.48.1 b=CT:384 t=0 0 m=audio 14742 RTP/AVP 0 4 3 8 112 5 10 7 18 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:112 AAL2-G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:10 L16/8000 a=rtpmap:7 LPC/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 15370 RTP/AVP 26 31 34 103 99 a=rtpmap:26 JPEG/90000 a=rtpmap:31 H261/90000 a=rtpmap:34 H263/90000 a=rtpmap:103 h263-1998/90000 a=rtpmap:99 H264/90000 a=sendrecv --- -- Called polycom1 poweredge*CLI> <--- Transmitting (no NAT) to 192.168.48.92:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-c5229b98;received=192.168.48.92 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as05aceab8 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> poweredge*CLI> <--- SIP read from 192.168.48.93:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK72e81e40;rport From: "48 Lounge" ;tag=as4f3a8c95 To: ;tag=1108809A-8D40D865 CSeq: 102 INVITE Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- [Mar 19 18:08:15] DEBUG[14183]: chan_sip.c:2129 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1' Request 102: Found poweredge*CLI> <--- SIP read from 192.168.48.93:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK72e81e40;rport From: "48 Lounge" ;tag=as4f3a8c95 To: ;tag=1108809A-8D40D865 CSeq: 102 INVITE Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Allow-Events: talk,hold,conference Content-Length: 0 <-------------> --- (10 headers 0 lines) --- [Mar 19 18:08:16] DEBUG[14183]: chan_sip.c:2129 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1' Request 102: Found [Mar 19 18:08:16] DEBUG[14183]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c3c120 -- SIP/polycom1-08c3c120 is ringing [Mar 19 18:08:16] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:08:16] DEBUG[14164]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 18:08:16] DEBUG[14199]: app_queue.c:546 changethread: Device 'SIP/polycom1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. poweredge*CLI> <--- SIP read from 192.168.48.93:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK72e81e40;rport From: "48 Lounge" ;tag=as4f3a8c95 To: ;tag=1108809A-8D40D865 CSeq: 102 INVITE Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Content-Type: application/sdp Content-Length: 374 v=0 o=- 1174323585 1174323585 IN IP4 192.168.48.93 s=Polycom IP Phone c=IN IP4 192.168.48.93 t=0 0 m=audio 2228 RTP/AVP 0 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 m=video 0 RTP/AVP 26 31 34 103 99 a=inactive a=rtpmap:26 jpeg/90000 a=rtpmap:31 h261/90000 a=rtpmap:34 h263/90000 a=rtpmap:103 h263-1998/90000 a=rtpmap:99 h264/90000 <-------------> --- (11 headers 16 lines) --- [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:2069 __sip_ack: Acked pending invite 102 [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1' of Request 102: Match Not Found Found RTP audio format 0 Found RTP audio format 101 Found RTP video format 26 Found RTP video format 31 Found RTP video format 34 Found RTP video format 103 Found RTP video format 99 Peer audio RTP is at port 192.168.48.93:2228 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Found description format jpeg for ID 26 Found description format h261 for ID 31 Found description format h263 for ID 34 Found description format h263-1998 for ID 103 Found description format h264 for ID 99 [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:5123 process_sdp: T38 state changed to 0 on channel SIP/polycom1-08c3c120 Capabilities: us - 0x3f19ff (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|g726aal2|g722|jpeg|png|h261|h263|h263p|h264), peer - audio=0x3d0004 (ulaw|jpeg|h261|h263|h263p|h264)/video=0x3d0000 (jpeg|h261|h263|h263p|h264), combined - 0x3d0004 (ulaw|jpeg|h261|h263|h263p|h264) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.48.93:2228 [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:5203 process_sdp: We're settling with these formats: 0x3d0004 (ulaw|jpeg|h261|h263|h263p|h264) [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:3001 update_call_counter: Updating call counter for outgoing call [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:7964 build_route: build_route: Contact hop: list_route: hop: [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:5637 reqprep: Strict routing enforced for session 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.48.93, port 5060 Transmitting (no NAT) to 192.168.48.93:5060: ACK sip:polycom1@192.168.48.93 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK2e2d2e36;rport From: "48 Lounge" ;tag=as4f3a8c95 To: ;tag=1108809A-8D40D865 Contact: Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- Call on SIP/polycom1-08c3c120 placed on hold [Mar 19 18:08:18] DEBUG[14197]: channel.c:2587 ast_prod: Prodding channel 'SIP/sipura3-08c357d0' [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6414 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6182 add_sdp: ** Our capability: 0x90d (g723|ulaw|alaw|g726|g729) Video flag: True [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.48.1 port 16110 Adding codec 0x1 (g723) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x100 (g729) to SDP Adding codec 0x800 (g726) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x90d (g723|ulaw|alaw|g726|g729) <--- Transmitting (no NAT) to 192.168.48.92:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-c5229b98;received=192.168.48.92 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as05aceab8 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 362 v=0 o=root 14139 14139 IN IP4 192.168.48.1 s=session c=IN IP4 192.168.48.1 t=0 0 m=audio 16110 RTP/AVP 4 0 8 18 2 101 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:2 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> -- Started music on hold, class 'default', on SIP/sipura3-08c357d0 [Mar 19 18:08:18] DEBUG[14197]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 19 18:08:18] DEBUG[14197]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c3c120 -- SIP/polycom1-08c3c120 answered SIP/sipura3-08c357d0 -- Stopped music on hold on SIP/sipura3-08c357d0 [Mar 19 18:08:18] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:08:18] DEBUG[14164]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 18:08:18] DEBUG[14197]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 19 18:08:18] DEBUG[14197]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c357d0 [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:3461 sip_answer: SIP answering channel: SIP/sipura3-08c357d0 [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6414 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6182 add_sdp: ** Our capability: 0x90d (g723|ulaw|alaw|g726|g729) Video flag: True [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.48.1 port 16110 Adding codec 0x1 (g723) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP [Mar 19 18:08:18] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer sipura3 Adding codec 0x100 (g729) to SDP [Mar 19 18:08:18] DEBUG[14164]: devicestate.c:287 do_state_change: Adding codec 0x800 (g726) to SDP Adding non-codec 0x1 (telephone-event) to SDP Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 18:08:18] DEBUG[14200]: app_queue.c:546 changethread: Device 'SIP/polycom1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x90d (g723|ulaw|alaw|g726|g729) poweredge*CLI> <--- Reliably Transmitting (no NAT) to 192.168.48.92:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-c5229b98;received=192.168.48.92 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as05aceab8 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 362 v=0 o=root 14139 14140 IN IP4 192.168.48.1 s=session c=IN IP4 192.168.48.1 t=0 0 m=audio 16110 RTP/AVP 4 0 8 18 2 101 a=rtpmap:4 G723/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:2 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 19 18:08:18] DEBUG[14201]: app_queue.c:546 changethread: Device 'SIP/sipura3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 18:08:18] DEBUG[14197]: chan_sip.c:4090 sip_rtp_read: Oooh, format changed to 256 [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/sipura3-08c357d0 to read format ulaw [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/sipura3-08c357d0 to write format ulaw [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/sipura3-08c357d0 to read format slin [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/polycom1-08c3c120 to write format slin [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/polycom1-08c3c120 to read format slin [Mar 19 18:08:18] DEBUG[14197]: channel.c:2845 set_format: Set channel SIP/sipura3-08c357d0 to write format slin poweredge*CLI> <--- SIP read from 192.168.48.92:5060 ---> ACK sip:1005@192.168.48.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-5f07c290 From: 1003 ;tag=78b9c320ffab7f70o0 To: ;tag=as05aceab8 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="224b1e3a",uri="sip:1005@192.168.48.1",algorithm=MD5,response="d54d2440825066cc5ce0256050c600dc" Contact: 1003 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- [Mar 19 18:08:18] DEBUG[14183]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '9bf010e0-a3538cb0@192.168.48.92' of Response 102: Match Not Found [Mar 19 18:08:18] DEBUG[14197]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 19 18:08:18] DEBUG[14197]: rtp.c:2687 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 poweredge*CLI> <--- SIP read from 86.139.222.79:5060 ---> NOTIFY sip:phonegw.xarin.com SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-6d149498 From: "Beith" ;tag=5e505bd34ee6eb8co0 To: Call-ID: b811403e-9c33da24@192.168.1.2 CSeq: 1240 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA841-3.1.4(a) Content-Length: 0 <-------------> --- (10 headers 0 lines) --- poweredge*CLI> <--- Transmitting (no NAT) to 86.139.222.79:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-6d149498;received=86.139.222.79 From: "Beith" ;tag=5e505bd34ee6eb8co0 To: ;tag=as2e5f4e51 Call-ID: b811403e-9c33da24@192.168.1.2 CSeq: 1240 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Mar 19 18:08:20] DEBUG[14183]: chan_sip.c:14774 sipsock_read: Invalid SIP message - rejected , no callid, len 351 poweredge*CLI> <--- SIP read from 192.168.48.93:5060 ---> BYE sip:1003@192.168.48.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.93;branch=z9hG4bK94bbef1b9AE2A238 From: ;tag=1108809A-8D40D865 To: "48 Lounge" ;tag=as4f3a8c95 CSeq: 1 BYE Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Max-Forwards: 70 Content-Length: 0 <-------------> --- (10 headers 0 lines) --- Sending to 192.168.48.93 : 5060 (no NAT) [Mar 19 18:08:25] DEBUG[14183]: chan_sip.c:1631 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 [Mar 19 18:08:25] DEBUG[14183]: chan_sip.c:14167 handle_request_bye: Received bye, issuing owner hangup poweredge*CLI> <--- Transmitting (no NAT) to 192.168.48.93:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.48.93;branch=z9hG4bK94bbef1b9AE2A238;received=192.168.48.93 From: ;tag=1108809A-8D40D865 To: "48 Lounge" ;tag=as4f3a8c95 Call-ID: 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1 CSeq: 1 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 18:08:25] DEBUG[14197]: channel.c:3800 ast_generic_bridge: Didn't get a frame from channel: SIP/polycom1-08c3c120 [Mar 19 18:08:25] DEBUG[14197]: channel.c:4118 ast_channel_bridge: Bridge stops bridging channels SIP/sipura3-08c357d0 and SIP/polycom1-08c3c120 [Mar 19 18:08:25] DEBUG[14197]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/polycom1-08c3c120' [Mar 19 18:08:25] DEBUG[14197]: chan_sip.c:3310 sip_hangup: Hangup call SIP/polycom1-08c3c120, SIP callid 37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1) [Mar 19 18:08:25] DEBUG[14197]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c3c120 [Mar 19 18:08:25] DEBUG[14197]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 19 18:08:25] DEBUG[14197]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 19 18:08:25] DEBUG[14197]: pbx.c:2389 __ast_pbx_run: Spawn extension (internal,1005,1) exited non-zero on 'SIP/sipura3-08c357d0' == Spawn extension (internal, 1005, 1) exited non-zero on 'SIP/sipura3-08c357d0' [Mar 19 18:08:25] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:08:25] DEBUG[14164]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1791 pbx_extension_helper: Launching 'Hangup' -- Executing [h@internal:1] Hangup("SIP/sipura3-08c357d0", "") in new stack [Mar 19 18:08:25] DEBUG[14204]: app_queue.c:546 changethread: Device 'SIP/polycom1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 18:08:25] DEBUG[14197]: pbx.c:2510 __ast_pbx_run: Spawn extension (internal,h,1) exited non-zero on 'SIP/sipura3-08c357d0' == Spawn extension (internal, h, 1) exited non-zero on 'SIP/sipura3-08c357d0' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '"48 Lounge" <1003>' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1003' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1005' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'internal' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/sipura3-08c357d0' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/polycom1-08c3c120' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:08:15' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:08:18' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:08:25' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '10' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '7' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1174327695.0' [Mar 19 18:08:25] DEBUG[14197]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:08:25] DEBUG[14197]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/sipura3-08c357d0' [Mar 19 18:08:25] DEBUG[14197]: chan_sip.c:3310 sip_hangup: Hangup call SIP/sipura3-08c357d0, SIP callid 9bf010e0-a3538cb0@192.168.48.92) Scheduling destruction of SIP dialog '9bf010e0-a3538cb0@192.168.48.92' in 32000 ms (Method: ACK) [Mar 19 18:08:25] DEBUG[14197]: chan_sip.c:5637 reqprep: Strict routing enforced for session 9bf010e0-a3538cb0@192.168.48.92 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.48.92, port 5060 Reliably Transmitting (no NAT) to 192.168.48.92:5060: BYE sip:sipura3@192.168.48.92:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK06025fe0;rport From: ;tag=as05aceab8 To: 1003 ;tag=78b9c320ffab7f70o0 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 18:08:25] DEBUG[14197]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c357d0 [Mar 19 18:08:25] DEBUG[14164]: chan_sip.c:15201 sip_devicestate: Checking device state for peer sipura3 [Mar 19 18:08:25] DEBUG[14164]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 18:08:25] DEBUG[14205]: app_queue.c:546 changethread: Device 'SIP/sipura3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. poweredge*CLI> <--- SIP read from 192.168.48.92:5060 ---> SIP/2.0 200 OK To: 1003 ;tag=78b9c320ffab7f70o0 From: ;tag=as05aceab8 Call-ID: 9bf010e0-a3538cb0@192.168.48.92 CSeq: 102 BYE Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK06025fe0 Server: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> --- (8 headers 0 lines) --- [Mar 19 18:08:25] DEBUG[14183]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '9bf010e0-a3538cb0@192.168.48.92' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '37af96be5d6fe6bd6b7d68c53b5b3b79@192.168.48.1' Method: BYE Really destroying SIP dialog '9bf010e0-a3538cb0@192.168.48.92' Method: ACK