Asterisk 1.4.0, 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.0 currently running on poweredge (pid = 14695) Verbosity is at least 3 poweredge*CLI> core set debug 3 Core debug was 0 and is now 3 [Mar 19 18:12:22] DEBUG[14746]: chan_sip.c:14631 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-326d3710 From: 1003 ;tag=aa50ac78fb564ad0o0 To: Call-ID: 8d306b98-59d49630@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=- 190487145 190487145 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16476 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:12:33] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2564 do_setnat: Setting NAT on VRTP to Off [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for 8d306b98-59d49630@192.168.48.92 - INVITE (With RTP) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:1662 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:1670 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:1682 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 - 8d306b98-59d49630@192.168.48.92 [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2564 do_setnat: Setting NAT on VRTP to Off <--- 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-326d3710;received=192.168.48.92 From: 1003 ;tag=aa50ac78fb564ad0o0 To: ;tag=as2f75ad51 Call-ID: 8d306b98-59d49630@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="70304b82" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '8d306b98-59d49630@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-326d3710 From: 1003 ;tag=aa50ac78fb564ad0o0 To: ;tag=as2f75ad51 Call-ID: 8d306b98-59d49630@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:12:33] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '8d306b98-59d49630@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-91adae98 From: 1003 ;tag=aa50ac78fb564ad0o0 To: Call-ID: 8d306b98-59d49630@192.168.48.92 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="70304b82",uri="sip:1005@phonegw.xarin.com",algorithm=MD5,response="14168782aa56dd22ac06c54836116e54" 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=- 190487145 190487145 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16476 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:12:33] DEBUG[14746]: chan_sip.c:1662 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:1670 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:1682 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 - 8d306b98-59d49630@192.168.48.92 [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2564 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:16476 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:12:33] DEBUG[14746]: chan_sip.c:5068 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:16476 Peer video RTP is at port 192.168.48.92:52224 [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:13237 handle_request_invite: Checking SIP call limits for device sipura3 [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call Looking for 1005 in internal (domain phonegw.xarin.com) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:3768 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:12:33] DEBUG[14746]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:7891 build_route: build_route: Contact hop: 1003 list_route: hop: [Mar 19 18:12:33] DEBUG[14746]: chan_sip.c:13310 handle_request_invite: SIP/sipura3-08c71988: New call is still down.... Trying... poweredge*CLI> <--- 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-91adae98;received=192.168.48.92 From: 1003 ;tag=aa50ac78fb564ad0o0 To: Call-ID: 8d306b98-59d49630@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:12:33] DEBUG[14746]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c71988 [Mar 19 18:12:33] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 18:12:33] DEBUG[14758]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' [Mar 19 18:12:33] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) -- Executing [1005@internal:1] Dial("SIP/sipura3-08c71988", "SIP/polycom1|20|rh") in new stack [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:15106 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14759]: 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:12:33] DEBUG[14758]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:2564 do_setnat: Setting NAT on VRTP to Off [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:3768 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:12:33] DEBUG[14758]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Mar 19 18:12:33] DEBUG[14758]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-internal-1005-1. [Mar 19 18:12:33] DEBUG[14758]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 19 18:12:33] DEBUG[14758]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 19 18:12:33] DEBUG[14758]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 19 18:12:33] DEBUG[14758]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:2812 sip_call: Outgoing Call for polycom1 [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:6122 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:12:33] DEBUG[14758]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:6138 add_sdp: This call needs video offers! Video is at 192.168.48.1 port 17708 Audio is at 192.168.48.1 port 18944 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:12:33] DEBUG[14758]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Mar 19 18:12:33] DEBUG[14758]: chan_sip.c:6299 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=z9hG4bK7425f047;rport From: "48 Lounge" ;tag=as7c11a78e To: Contact: Call-ID: 24c444451508b0982ab018c375cc2922@192.168.48.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 19 Mar 2007 18:12:33 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 684 v=0 o=root 14695 14695 IN IP4 192.168.48.1 s=session c=IN IP4 192.168.48.1 b=CT:384 t=0 0 m=audio 18944 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 17708 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 <--- 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-91adae98;received=192.168.48.92 From: 1003 ;tag=aa50ac78fb564ad0o0 To: ;tag=as1fec724b Call-ID: 8d306b98-59d49630@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=z9hG4bK7425f047;rport From: "48 Lounge" ;tag=as7c11a78e To: ;tag=C9DD93F4-33F0FD07 CSeq: 102 INVITE Call-ID: 24c444451508b0982ab018c375cc2922@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:12:34] DEBUG[14746]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '24c444451508b0982ab018c375cc2922@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=z9hG4bK7425f047;rport From: "48 Lounge" ;tag=as7c11a78e To: ;tag=C9DD93F4-33F0FD07 CSeq: 102 INVITE Call-ID: 24c444451508b0982ab018c375cc2922@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:12:34] DEBUG[14746]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '24c444451508b0982ab018c375cc2922@192.168.48.1' Request 102: Found [Mar 19 18:12:34] DEBUG[14746]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c7e388 [Mar 19 18:12:34] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:12:34] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) -- SIP/polycom1-08c7e388 is ringing [Mar 19 18:12:34] DEBUG[14760]: 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=z9hG4bK7425f047;rport From: "48 Lounge" ;tag=as7c11a78e To: ;tag=C9DD93F4-33F0FD07 CSeq: 102 INVITE Call-ID: 24c444451508b0982ab018c375cc2922@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=- 1174323842 1174323842 IN IP4 192.168.48.93 s=Polycom IP Phone c=IN IP4 192.168.48.93 t=0 0 m=audio 2230 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:12:35] DEBUG[14746]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '24c444451508b0982ab018c375cc2922@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:2230 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:12:35] DEBUG[14746]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/polycom1-08c7e388 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:2230 [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x3d0004 (ulaw|jpeg|h261|h263|h263p|h264) [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:7891 build_route: build_route: Contact hop: list_route: hop: [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:5576 reqprep: Strict routing enforced for session 24c444451508b0982ab018c375cc2922@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=z9hG4bK5bbae6f3;rport From: "48 Lounge" ;tag=as7c11a78e To: ;tag=C9DD93F4-33F0FD07 Contact: Call-ID: 24c444451508b0982ab018c375cc2922@192.168.48.1 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 18:12:35] DEBUG[14758]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c7e388 -- SIP/polycom1-08c7e388 answered SIP/sipura3-08c71988 [Mar 19 18:12:35] DEBUG[14758]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c71988 [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:3428 sip_answer: SIP answering channel: SIP/sipura3-08c71988 [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:6354 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:6122 add_sdp: ** Our capability: 0x90d (g723|ulaw|alaw|g726|g729) Video flag: True [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.48.1 port 15340 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:12:35] DEBUG[14758]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Mar 19 18:12:35] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:12:35] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 18:12:35] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 18:12:35] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:6299 add_sdp: Done building SDP. Settling with this capability: 0x90d (g723|ulaw|alaw|g726|g729) <--- 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-91adae98;received=192.168.48.92 From: 1003 ;tag=aa50ac78fb564ad0o0 To: ;tag=as1fec724b Call-ID: 8d306b98-59d49630@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 14695 14695 IN IP4 192.168.48.1 s=session c=IN IP4 192.168.48.1 t=0 0 m=audio 15340 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:12:35] DEBUG[14761]: 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:12:35] DEBUG[14762]: 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 ---> ACK sip:1005@192.168.48.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-40402ff5 From: 1003 ;tag=aa50ac78fb564ad0o0 To: ;tag=as1fec724b Call-ID: 8d306b98-59d49630@192.168.48.92 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="70304b82",uri="sip:1005@192.168.48.1",algorithm=MD5,response="61da97dab211a4649b0e024f938a7dc5" Contact: 1003 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- [Mar 19 18:12:35] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '8d306b98-59d49630@192.168.48.92' of Response 102: Match Not Found [Mar 19 18:12:35] DEBUG[14758]: chan_sip.c:4046 sip_rtp_read: Oooh, format changed to 256 [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/sipura3-08c71988 to read format ulaw [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/sipura3-08c71988 to write format ulaw [Mar 19 18:12:35] DEBUG[14758]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 19 18:12:35] DEBUG[14758]: rtp.c:2664 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/sipura3-08c71988 to read format slin [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/polycom1-08c7e388 to write format slin [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/polycom1-08c7e388 to read format slin [Mar 19 18:12:35] DEBUG[14758]: channel.c:2731 set_format: Set channel SIP/sipura3-08c71988 to write format slin [Mar 19 18:12:36] DEBUG[14758]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 19 18:12:36] DEBUG[14758]: rtp.c:2664 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-200197c8 From: "Beith" ;tag=5e505bd34ee6eb8co0 To: Call-ID: b811403e-9c33da24@192.168.1.2 CSeq: 1257 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA841-3.1.4(a) Content-Length: 0 <-------------> --- (10 headers 0 lines) --- <--- 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-200197c8;received=86.139.222.79 From: "Beith" ;tag=5e505bd34ee6eb8co0 To: ;tag=as72156dd0 Call-ID: b811403e-9c33da24@192.168.1.2 CSeq: 1257 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Mar 19 18:12:37] DEBUG[14746]: chan_sip.c:14631 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=z9hG4bK4926794d1F73DEE2 From: ;tag=C9DD93F4-33F0FD07 To: "48 Lounge" ;tag=as7c11a78e CSeq: 1 BYE Call-ID: 24c444451508b0982ab018c375cc2922@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:12:42] DEBUG[14746]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 24c444451508b0982ab018c375cc2922@192.168.48.1 [Mar 19 18:12:42] DEBUG[14746]: chan_sip.c:14030 handle_request_bye: Received bye, issuing owner hangup . <--- Transmitting (no NAT) to 192.168.48.93:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.48.93;branch=z9hG4bK4926794d1F73DEE2;received=192.168.48.93 From: ;tag=C9DD93F4-33F0FD07 To: "48 Lounge" ;tag=as7c11a78e Call-ID: 24c444451508b0982ab018c375cc2922@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:12:42] DEBUG[14758]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/polycom1-08c7e388 [Mar 19 18:12:42] DEBUG[14758]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/sipura3-08c71988 and SIP/polycom1-08c7e388 [Mar 19 18:12:42] DEBUG[14758]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/polycom1-08c7e388' [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:3278 sip_hangup: Hangup call SIP/polycom1-08c7e388, SIP callid 24c444451508b0982ab018c375cc2922@192.168.48.1) [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:3286 sip_hangup: update_call_counter(polycom1) - decrement call limit counter on hangup [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 18:12:42] DEBUG[14758]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c7e388 [Mar 19 18:12:42] DEBUG[14758]: rtp.c:1465 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 19 18:12:42] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 18:12:42] DEBUG[14758]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 19 18:12:42] DEBUG[14758]: pbx.c:2363 __ast_pbx_run: Spawn extension (internal,1005,1) exited non-zero on 'SIP/sipura3-08c71988' == Spawn extension (internal, 1005, 1) exited non-zero on 'SIP/sipura3-08c71988' [Mar 19 18:12:42] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1767 pbx_extension_helper: Launching 'Hangup' -- Executing [h@internal:1] Hangup("SIP/sipura3-08c71988", "") in new stack [Mar 19 18:12:42] DEBUG[14758]: pbx.c:2483 __ast_pbx_run: Spawn extension (internal,h,1) exited non-zero on 'SIP/sipura3-08c71988' == Spawn extension (internal, h, 1) exited non-zero on 'SIP/sipura3-08c71988' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"48 Lounge" <1003>' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1003' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1005' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'internal' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sipura3-08c71988' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/polycom1-08c7e388' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:12:33' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:12:35' [Mar 19 18:12:42] DEBUG[14766]: 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:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 18:12:42' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '9' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '7' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1174327953.0' [Mar 19 18:12:42] DEBUG[14758]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 18:12:42] DEBUG[14758]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sipura3-08c71988' [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:3278 sip_hangup: Hangup call SIP/sipura3-08c71988, SIP callid 8d306b98-59d49630@192.168.48.92) [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:3286 sip_hangup: update_call_counter(sipura3) - decrement call limit counter on hangup [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '8d306b98-59d49630@192.168.48.92' in 32000 ms (Method: ACK) [Mar 19 18:12:42] DEBUG[14758]: chan_sip.c:5576 reqprep: Strict routing enforced for session 8d306b98-59d49630@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=z9hG4bK69a9fd01;rport From: ;tag=as1fec724b To: 1003 ;tag=aa50ac78fb564ad0o0 Call-ID: 8d306b98-59d49630@192.168.48.92 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 18:12:42] DEBUG[14758]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c71988 [Mar 19 18:12:42] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 18:12:42] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 18:12:42] DEBUG[14767]: 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=aa50ac78fb564ad0o0 From: ;tag=as1fec724b Call-ID: 8d306b98-59d49630@192.168.48.92 CSeq: 102 BYE Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK69a9fd01 Server: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> --- (8 headers 0 lines) --- [Mar 19 18:12:42] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '8d306b98-59d49630@192.168.48.92' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '24c444451508b0982ab018c375cc2922@192.168.48.1' Method: BYE Really destroying SIP dialog '8d306b98-59d49630@192.168.48.92' Method: ACK