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 4 Core debug is at least 4 [Mar 19 20:38:49] DEBUG[14738]: chan_iax2.c:7087 socket_process: Peer iaxtel: got pong, lastms 167, historicms 167, maxms 2000 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-868a5cd5 From: 1003 ;tag=472759e69df03104o0 To: Call-ID: d1658d0e-2adf57fc@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=- 191364915 191364915 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16482 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 <-------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: INVITE sip:1005@phonegw.xarin.com SIP/2.0 (41) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-868a5cd5 (59) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: 1003 ;tag=472759e69df03104o0 (65) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: (32) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: Call-ID: d1658d0e-2adf57fc@192.168.48.92 (40) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: CSeq: 101 INVITE (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Max-Forwards: 70 (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Contact: 1003 (46) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Expires: 240 (12) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: User-Agent: Sipura/SPA2000-3.1.5 (32) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: Content-Length: 430 (19) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 12: Supported: x-sipura (19) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 13: Content-Type: application/sdp (29) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 14: (0) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: o=- 191364915 191364915 IN IP4 192.168.48.92 (44) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: s=- (3) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: c=IN IP4 192.168.48.92 (22) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 (49) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-15 (15) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=ptime:30 (10) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) --- (14 headers 19 lines) --- [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2564 do_setnat: Setting NAT on VRTP to Off [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for d1658d0e-2adf57fc@192.168.48.92 - INVITE (With RTP) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:14453 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:1662 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:1670 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 20:38:51] 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 - d1658d0e-2adf57fc@192.168.48.92 [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 20:38:51] 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-868a5cd5;received=192.168.48.92 From: 1003 ;tag=472759e69df03104o0 To: ;tag=as56bb2b20 Call-ID: d1658d0e-2adf57fc@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="4e1576bd" Content-Length: 0 <------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1874 Scheduling destruction of SIP dialog 'd1658d0e-2adf57fc@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-868a5cd5 From: 1003 ;tag=472759e69df03104o0 To: ;tag=as56bb2b20 Call-ID: d1658d0e-2adf57fc@192.168.48.92 CSeq: 101 ACK Max-Forwards: 70 Contact: 1003 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: ACK sip:1005@phonegw.xarin.com SIP/2.0 (38) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-868a5cd5 (59) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: 1003 ;tag=472759e69df03104o0 (65) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: ;tag=as56bb2b20 (47) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: Call-ID: d1658d0e-2adf57fc@192.168.48.92 (40) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: CSeq: 101 ACK (13) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Max-Forwards: 70 (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Contact: 1003 (46) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: User-Agent: Sipura/SPA2000-3.1.5 (32) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Content-Length: 0 (17) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:14453 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1874 [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd1658d0e-2adf57fc@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-53953c21 From: 1003 ;tag=472759e69df03104o0 To: Call-ID: d1658d0e-2adf57fc@192.168.48.92 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="4e1576bd",uri="sip:1005@phonegw.xarin.com",algorithm=MD5,response="a719a0fbc40d6174b6077e5362c4bc6f" 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=- 191364915 191364915 IN IP4 192.168.48.92 s=- c=IN IP4 192.168.48.92 t=0 0 m=audio 16482 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 <-------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: INVITE sip:1005@phonegw.xarin.com SIP/2.0 (41) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-53953c21 (59) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: 1003 ;tag=472759e69df03104o0 (65) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: (32) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: Call-ID: d1658d0e-2adf57fc@192.168.48.92 (40) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Max-Forwards: 70 (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="4e1576bd",uri="sip:1005@phonegw.xarin.com",algorithm=MD5,response="a719a0fbc40d6174b6077e5362c4bc6f" (180) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Contact: 1003 (46) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Expires: 240 (12) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: User-Agent: Sipura/SPA2000-3.1.5 (32) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 11: Content-Length: 430 (19) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 13: Supported: x-sipura (19) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 14: Content-Type: application/sdp (29) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 15: (0) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: o=- 191364915 191364915 IN IP4 192.168.48.92 (44) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: s=- (3) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: c=IN IP4 192.168.48.92 (22) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: m=audio 16482 RTP/AVP 18 0 2 4 8 96 97 98 100 101 (49) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-15 (15) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=ptime:30 (10) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) --- (15 headers 19 lines) --- [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:14453 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:1662 parse_sip_options: Begin: parsing SIP "Supported: x-sipura" [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:1670 parse_sip_options: Found SIP option: -x-sipura- [Mar 19 20:38:51] 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 - d1658d0e-2adf57fc@192.168.48.92 [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 20:38:51] 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:16482 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 20:38:51] 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:16482 Peer video RTP is at port 192.168.48.92:52224 [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:13237 handle_request_invite: Checking SIP call limits for device sipura3 [Mar 19 20:38:51] 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 20:38:51] DEBUG[14746]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x90d (g723|ulaw|alaw|g726|g729) [Mar 19 20:38:51] 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 20:38:51] DEBUG[14746]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:7891 build_route: build_route: Contact hop: 1003 list_route: hop: [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:13310 handle_request_invite: SIP/sipura3-08c7ff00: 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-53953c21;received=192.168.48.92 From: 1003 ;tag=472759e69df03104o0 To: Call-ID: d1658d0e-2adf57fc@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 20:38:51] DEBUG[14746]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c7ff00 [Mar 19 20:38:51] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura3 [Mar 19 20:38:51] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 20:38:51] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 20:38:51] DEBUG[17858]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' -- Executing [1005@internal:1] Dial("SIP/sipura3-08c7ff00", "SIP/polycom1|20|rh") in new stack [Mar 19 20:38:51] DEBUG[17859]: 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 20:38:51] DEBUG[17858]: chan_sip.c:15106 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:2564 do_setnat: Setting NAT on VRTP to Off [Mar 19 20:38:51] DEBUG[17858]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 19 20:38:51] DEBUG[17858]: 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 20:38:51] DEBUG[17858]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Mar 19 20:38:51] DEBUG[17858]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-internal-1005-1. [Mar 19 20:38:51] DEBUG[17858]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 19 20:38:51] DEBUG[17858]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 19 20:38:51] DEBUG[17858]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 19 20:38:51] DEBUG[17858]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:2812 sip_call: Outgoing Call for polycom1 [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 19 20:38:51] DEBUG[17858]: 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 20:38:51] DEBUG[17858]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:6138 add_sdp: This call needs video offers! Video is at 192.168.48.1 port 14898 Audio is at 192.168.48.1 port 14944 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 20:38:51] DEBUG[17858]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Mar 19 20:38:51] DEBUG[17858]: 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) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 0: INVITE sip:polycom1@192.168.48.93 SIP/2.0 (41) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK6e78cf8b;rport (63) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 2: From: "48 Lounge" ;tag=as4a208b6d (56) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 3: To: (32) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 4: Contact: (32) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 (54) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 9: Date: Mon, 19 Mar 2007 20:38:51 GMT (35) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 11: Supported: replaces (19) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 13: Content-Length: 684 (19) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4527 parse_request: Header 14: (0) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: o=root 14695 14695 IN IP4 192.168.48.1 (38) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: s=session (9) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: c=IN IP4 192.168.48.1 (21) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: b=CT:384 (8) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: m=audio 14944 RTP/AVP 0 4 3 8 112 5 10 7 18 111 101 (51) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:112 AAL2-G726-32/8000 (30) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:5 DVI4/8000 (20) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:10 L16/8000 (20) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:7 LPC/8000 (19) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=ptime:20 (10) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: m=video 14898 RTP/AVP 26 31 34 103 99 (37) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:26 JPEG/90000 (22) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:31 H261/90000 (22) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:34 H263/90000 (22) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:103 h263-1998/90000 (28) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=rtpmap:99 H264/90000 (22) [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) 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=z9hG4bK6e78cf8b;rport From: "48 Lounge" ;tag=as4a208b6d To: Contact: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 19 Mar 2007 20:38:51 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 14944 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 14898 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 --- [Mar 19 20:38:51] DEBUG[17858]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1876 -- 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-53953c21;received=192.168.48.92 From: 1003 ;tag=472759e69df03104o0 To: ;tag=as655d511d Call-ID: d1658d0e-2adf57fc@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=z9hG4bK6e78cf8b;rport From: "48 Lounge" ;tag=as4a208b6d To: ;tag=F4503775-C05C1E3C CSeq: 102 INVITE Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Content-Length: 0 <-------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK6e78cf8b;rport (63) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: "48 Lounge" ;tag=as4a208b6d (56) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: ;tag=F4503775-C05C1E3C (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: CSeq: 102 INVITE (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Contact: (37) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Content-Length: 0 (17) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2104 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1876 - INVITE (got response) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1' Request 102: Found [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:11531 handle_response_invite: SIP response 100 to standard invite 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=z9hG4bK6e78cf8b;rport From: "48 Lounge" ;tag=as4a208b6d To: ;tag=F4503775-C05C1E3C CSeq: 102 INVITE Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Allow-Events: talk,hold,conference Content-Length: 0 <-------------> [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK6e78cf8b;rport (63) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: "48 Lounge" ;tag=as4a208b6d (56) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: ;tag=F4503775-C05C1E3C (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: CSeq: 102 INVITE (16) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Contact: (37) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 (54) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Allow-Events: talk,hold,conference (34) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Content-Length: 0 (17) [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1' Request 102: Found [Mar 19 20:38:51] DEBUG[14746]: chan_sip.c:11531 handle_response_invite: SIP response 180 to standard invite [Mar 19 20:38:51] DEBUG[14746]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c8bc88 [Mar 19 20:38:51] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - polycom1 [Mar 19 20:38:51] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 20:38:51] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) -- SIP/polycom1-08c8bc88 is ringing [Mar 19 20:38:51] DEBUG[17860]: 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 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-b4077446 From: "Beith" ;tag=b669e2452194b008o0 To: Call-ID: f1f63f78-ccdb3c78@192.168.1.2 CSeq: 173 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA841-3.1.4(a) Content-Length: 0 <-------------> [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: NOTIFY sip:phonegw.xarin.com SIP/2.0 (36) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:5060;branch=z9hG4bK-b4077446 (57) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: "Beith" ;tag=b669e2452194b008o0 (70) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: (27) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: Call-ID: f1f63f78-ccdb3c78@192.168.1.2 (38) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: CSeq: 173 NOTIFY (16) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Max-Forwards: 70 (16) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Event: keep-alive (17) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: User-Agent: Sipura/SPA841-3.1.4(a) (34) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Content-Length: 0 (17) [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: (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-b4077446;received=86.139.222.79 From: "Beith" ;tag=b669e2452194b008o0 To: ;tag=as2c4e0c4e Call-ID: f1f63f78-ccdb3c78@192.168.1.2 CSeq: 173 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Mar 19 20:38:53] DEBUG[14746]: chan_sip.c:14631 sipsock_read: Invalid SIP message - rejected , no callid, len 350 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=z9hG4bK6e78cf8b;rport From: "48 Lounge" ;tag=as4a208b6d To: ;tag=F4503775-C05C1E3C CSeq: 102 INVITE Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@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=- 1174332625 1174332625 IN IP4 192.168.48.93 s=Polycom IP Phone c=IN IP4 192.168.48.93 t=0 0 m=audio 2232 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 <-------------> [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK6e78cf8b;rport (63) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: "48 Lounge" ;tag=as4a208b6d (56) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: ;tag=F4503775-C05C1E3C (54) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: CSeq: 102 INVITE (16) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 (54) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Contact: (37) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 (54) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: Content-Length: 374 (19) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 11: (0) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: v=0 (3) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: o=- 1174332625 1174332625 IN IP4 192.168.48.93 (46) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: s=Polycom IP Phone (18) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: c=IN IP4 192.168.48.93 (22) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: t=0 0 (5) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: m=audio 2232 RTP/AVP 0 101 (26) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=sendrecv (10) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: m=video 0 RTP/AVP 26 31 34 103 99 (33) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=inactive (10) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:26 jpeg/90000 (22) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:31 h261/90000 (22) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:34 h263/90000 (22) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:103 h263-1998/90000 (28) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4559 parse_request: Line: a=rtpmap:99 h264/90000 (22) --- (11 headers 16 lines) --- [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1' of Request 102: Match Not Found [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:11531 handle_response_invite: SIP response 200 to standard invite 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:2232 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 20:38:58] DEBUG[14746]: chan_sip.c:5068 process_sdp: T38 state changed to 0 on channel SIP/polycom1-08c8bc88 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:2232 [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:5145 process_sdp: We're settling with these formats: 0x3d0004 (ulaw|jpeg|h261|h263|h263p|h264) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:5152 process_sdp: We have an owner, now see if we need to change this call [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:7891 build_route: build_route: Contact hop: list_route: hop: [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:5576 reqprep: Strict routing enforced for session 2f22a7e142b0e50745e3d5b9385baa52@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=z9hG4bK673e69da;rport From: "48 Lounge" ;tag=as4a208b6d To: ;tag=F4503775-C05C1E3C Contact: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 20:38:58] DEBUG[17858]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c8bc88 [Mar 19 20:38:58] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - polycom1 [Mar 19 20:38:58] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 20:38:58] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) -- SIP/polycom1-08c8bc88 answered SIP/sipura3-08c7ff00 [Mar 19 20:38:58] DEBUG[17858]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c7ff00 [Mar 19 20:38:58] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura3 [Mar 19 20:38:58] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 20:38:58] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 20:38:58] DEBUG[17858]: chan_sip.c:3428 sip_answer: SIP answering channel: SIP/sipura3-08c7ff00 [Mar 19 20:38:58] DEBUG[17858]: chan_sip.c:6354 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 20:38:58] DEBUG[17858]: chan_sip.c:6122 add_sdp: ** Our capability: 0x90d (g723|ulaw|alaw|g726|g729) Video flag: True [Mar 19 20:38:58] DEBUG[17858]: chan_sip.c:6123 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.48.1 port 18058 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 20:38:58] DEBUG[17863]: 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 20:38:58] DEBUG[17864]: 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 20:38:58] DEBUG[17858]: chan_sip.c:6254 add_sdp: -- Done with adding codecs to SDP [Mar 19 20:38:58] DEBUG[17858]: 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-53953c21;received=192.168.48.92 From: 1003 ;tag=472759e69df03104o0 To: ;tag=as655d511d Call-ID: d1658d0e-2adf57fc@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 18058 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 20:38:58] DEBUG[17858]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1878 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-8917bea6 From: 1003 ;tag=472759e69df03104o0 To: ;tag=as655d511d Call-ID: d1658d0e-2adf57fc@192.168.48.92 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="4e1576bd",uri="sip:1005@192.168.48.1",algorithm=MD5,response="41da96ed04db6f6d3643cf40c3ce8c12" Contact: 1003 User-Agent: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: ACK sip:1005@192.168.48.1 SIP/2.0 (33) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.92:5060;branch=z9hG4bK-8917bea6 (59) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: 1003 ;tag=472759e69df03104o0 (65) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: ;tag=as655d511d (47) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: Call-ID: d1658d0e-2adf57fc@192.168.48.92 (40) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: CSeq: 102 ACK (13) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Max-Forwards: 70 (16) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Proxy-Authorization: Digest username="sipura3",realm="phonegw.xarin.com",nonce="4e1576bd",uri="sip:1005@192.168.48.1",algorithm=MD5,response="41da96ed04db6f6d3643cf40c3ce8c12" (175) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Contact: 1003 (46) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: User-Agent: Sipura/SPA2000-3.1.5 (32) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: Content-Length: 0 (17) [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:14453 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1878 [Mar 19 20:38:58] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd1658d0e-2adf57fc@192.168.48.92' of Response 102: Match Not Found [Mar 19 20:38:58] DEBUG[17858]: chan_sip.c:4046 sip_rtp_read: Oooh, format changed to 256 [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/sipura3-08c7ff00 to read format ulaw [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/sipura3-08c7ff00 to write format ulaw [Mar 19 20:38:58] DEBUG[17858]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 19 20:38:58] DEBUG[17858]: rtp.c:2664 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/sipura3-08c7ff00 to read format slin [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/polycom1-08c8bc88 to write format slin [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/polycom1-08c8bc88 to read format slin [Mar 19 20:38:58] DEBUG[17858]: channel.c:2731 set_format: Set channel SIP/sipura3-08c7ff00 to write format slin [Mar 19 20:38:58] DEBUG[17858]: rtp.c:2647 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 19 20:38:58] DEBUG[17858]: rtp.c:2664 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 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=z9hG4bK35d6ad6aA2D6CAAB From: ;tag=F4503775-C05C1E3C To: "48 Lounge" ;tag=as4a208b6d CSeq: 1 BYE Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: BYE sip:1003@192.168.48.1 SIP/2.0 (33) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.48.93;branch=z9hG4bK35d6ad6aA2D6CAAB (61) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: ;tag=F4503775-C05C1E3C (56) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: To: "48 Lounge" ;tag=as4a208b6d (54) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: CSeq: 1 BYE (11) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 (54) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Contact: (37) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.3.0067 (54) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 9: Content-Length: 0 (17) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:14453 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.48.93 : 5060 (no NAT) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1 [Mar 19 20:39:00] 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=z9hG4bK35d6ad6aA2D6CAAB;received=192.168.48.93 From: ;tag=F4503775-C05C1E3C To: "48 Lounge" ;tag=as4a208b6d Call-ID: 2f22a7e142b0e50745e3d5b9385baa52@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 20:39:00] DEBUG[17858]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/polycom1-08c8bc88 [Mar 19 20:39:00] DEBUG[17858]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/sipura3-08c7ff00 and SIP/polycom1-08c8bc88 [Mar 19 20:39:00] DEBUG[17858]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/polycom1-08c8bc88' [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:3278 sip_hangup: Hangup call SIP/polycom1-08c8bc88, SIP callid 2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1) [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:3286 sip_hangup: update_call_counter(polycom1) - decrement call limit counter on hangup [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Mar 19 20:39:00] DEBUG[17858]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/polycom1-08c8bc88 [Mar 19 20:39:00] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - polycom1 [Mar 19 20:39:00] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer polycom1 [Mar 19 20:39:00] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/polycom1 - state 1 (Not in use) [Mar 19 20:39:00] DEBUG[17858]: rtp.c:1465 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 19 20:39:00] DEBUG[17858]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 19 20:39:00] DEBUG[17858]: pbx.c:2363 __ast_pbx_run: Spawn extension (internal,1005,1) exited non-zero on 'SIP/sipura3-08c7ff00' == Spawn extension (internal, 1005, 1) exited non-zero on 'SIP/sipura3-08c7ff00' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1767 pbx_extension_helper: Launching 'Hangup' -- Executing [h@internal:1] Hangup("SIP/sipura3-08c7ff00", "") in new stack [Mar 19 20:39:00] DEBUG[17858]: pbx.c:2483 __ast_pbx_run: Spawn extension (internal,h,1) exited non-zero on 'SIP/sipura3-08c7ff00' == Spawn extension (internal, h, 1) exited non-zero on 'SIP/sipura3-08c7ff00' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"48 Lounge" <1003>' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1003' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1005' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'internal' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sipura3-08c7ff00' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/polycom1-08c8bc88' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 20:38:51' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 20:38:58' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2007-03-19 20:39:00' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '9' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1174336731.4' [Mar 19 20:39:00] DEBUG[17858]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 20:39:00] DEBUG[17858]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sipura3-08c7ff00' [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:3278 sip_hangup: Hangup call SIP/sipura3-08c7ff00, SIP callid d1658d0e-2adf57fc@192.168.48.92) [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:3286 sip_hangup: update_call_counter(sipura3) - decrement call limit counter on hangup [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog 'd1658d0e-2adf57fc@192.168.48.92' in 32000 ms (Method: ACK) [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:5576 reqprep: Strict routing enforced for session d1658d0e-2adf57fc@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=z9hG4bK170e7ebb;rport From: ;tag=as655d511d To: 1003 ;tag=472759e69df03104o0 Call-ID: d1658d0e-2adf57fc@192.168.48.92 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 20:39:00] DEBUG[17858]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1882 [Mar 19 20:39:00] DEBUG[17858]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura3-08c7ff00 [Mar 19 20:39:00] DEBUG[14712]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura3 [Mar 19 20:39:00] DEBUG[14712]: chan_sip.c:15048 sip_devicestate: Checking device state for peer sipura3 [Mar 19 20:39:00] DEBUG[14712]: devicestate.c:287 do_state_change: Changing state for SIP/sipura3 - state 1 (Not in use) [Mar 19 20:39:00] DEBUG[17865]: 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 20:39:00] DEBUG[17866]: 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=472759e69df03104o0 From: ;tag=as655d511d Call-ID: d1658d0e-2adf57fc@192.168.48.92 CSeq: 102 BYE Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK170e7ebb Server: Sipura/SPA2000-3.1.5 Content-Length: 0 <-------------> [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 1: To: 1003 ;tag=472759e69df03104o0 (63) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 2: From: ;tag=as655d511d (49) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 3: Call-ID: d1658d0e-2adf57fc@192.168.48.92 (40) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 4: CSeq: 102 BYE (13) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.48.1:5060;branch=z9hG4bK170e7ebb (57) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 6: Server: Sipura/SPA2000-3.1.5 (28) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 7: Content-Length: 0 (17) [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:4527 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1882 [Mar 19 20:39:00] DEBUG[14746]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd1658d0e-2adf57fc@192.168.48.92' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '2f22a7e142b0e50745e3d5b9385baa52@192.168.48.1' Method: BYE Really destroying SIP dialog 'd1658d0e-2adf57fc@192.168.48.92' Method: ACK