Script started on Thu 16 Nov 2006 12:28:59 GMT [root@asterisk1 asterisk]# /usr/sbin/asterisk -vvvvvvvvvvddddddddddnc Asterisk SVN-trunk-r47654, 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. ========================================================================= << snip initialisation >> Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'asterisk1' (pid 1955)*CLI> sipsip dset debug ip 10.69.255.248 SIP Debugging Enabled for IP: 10.69.255.248 *CLI> <--- SIP read from 10.69.255.248:5060 ---> INVITE sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403" Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb97a-3a2cd2c1 Max-Forwards: 70 Supported: replaces Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL Contact: Content-Type: application/sdp Content-Length: 193 v=0 o=rtp 1163680612 1163680612 IN IP4 10.69.255.248 s=- c=IN IP4 10.69.255.248 t=0 0 m=audio 5004 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 55]: INVITE sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 94]: From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 37]: To: "403" [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 72]: Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 14]: CSeq: 1 INVITE [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb97a-3a2cd2c1 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 19]: Supported: replaces [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 46]: Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 54]: Contact: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 11 [ 19]: Content-Length: 193 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 12 [ 0]: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 1 [ 48]: o=rtp 1163680612 1163680612 IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 2 [ 3]: s=- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 3 [ 22]: c=IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 5 [ 26]: m=audio 5004 RTP/AVP 0 101 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 --- (12 headers 9 lines) --- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to Off [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2661 do_setnat: Setting NAT on UDPTL to Off [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4337 sip_alloc: Allocating new SIP dialog for 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 - INVITE (With RTP) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:14546 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:1689 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:1697 parse_sip_options: Found SIP option: -replaces- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:1703 parse_sip_options: Matched SIP option: replaces Sending to 10.69.255.248 : 5060 (NAT) Using INVITE request as basis request - 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Found user 'tulip1' for 'tulip1' [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to Off [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2661 do_setnat: Setting NAT on UDPTL to Off <--- Reliably Transmitting (no NAT) to 10.69.255.248:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.69.255.248:5060;branch=z9hG4bK-455c5987-f0bdb97a-3a2cd2c1;received=10.69.255.248;rport=5060 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as6b897270 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="inspiredbroadcast.net", nonce="1b1b9c6d" Content-Length: 0 <------------> [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 Scheduling destruction of SIP dialog '100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248' in 32000 ms (Method: INVITE) <--- SIP read from 10.69.255.248:5060 ---> ACK sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as6b897270 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 1 ACK Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb97a-3a2cd2c1 Max-Forwards: 70 Contact: Content-Length: 0 <-------------> [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 52]: ACK sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 94]: From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 52]: To: "403";tag=as6b897270 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 72]: Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb97a-3a2cd2c1 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 54]: Contact: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 17]: Content-Length: 0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Their Tag 100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 Our tag: as6b897270 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:14546 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2078 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2088 __sip_ack: Stopping retransmission on '100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248' of Response 1: Match Found <--- SIP read from 10.69.255.248:5060 ---> INVITE sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403" Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 2 INVITE Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb9b8-48b38f19 Max-Forwards: 70 Supported: replaces Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL Contact: Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251:5060;transport=UDP",response="f9c46dc659e4169e07d0b8672627da5a",algorithm=MD5 Content-Type: application/sdp Content-Length: 193 v=0 o=rtp 1163680612 1163680612 IN IP4 10.69.255.248 s=- c=IN IP4 10.69.255.248 t=0 0 m=audio 5004 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 55]: INVITE sip:403@10.69.255.251:5060;transport=UDP SIP/2.0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 94]: From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 37]: To: "403" [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 72]: Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 14]: CSeq: 2 INVITE [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c5987-f0bdb9b8-48b38f19 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 19]: Supported: replaces [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 46]: Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 54]: Contact: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [191]: Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251:5060;transport=UDP",response="f9c46dc659e4169e07d0b8672627da5a",algorithm=MD5 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 12 [ 19]: Content-Length: 193 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 13 [ 0]: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 1 [ 48]: o=rtp 1163680612 1163680612 IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 2 [ 3]: s=- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 3 [ 22]: c=IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 5 [ 26]: m=audio 5004 RTP/AVP 0 101 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 --- (13 headers 9 lines) --- [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Their Tag 100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 Our tag: as6b897270 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:14546 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.69.255.248 : 5060 (NAT) Using INVITE request as basis request - 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Found user 'tulip1' for 'tulip1' [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to Off [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2661 do_setnat: Setting NAT on UDPTL to Off Found RTP audio format 0 Found RTP audio format 101 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4889 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 10.69.255.248:5004 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:5119 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0xeae (gsm|ulaw|alaw|g726|adpcm|lpc10|speex|ilbc), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.69.255.248:5004 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:5196 process_sdp: We're settling with these formats: 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:13345 handle_request_invite: Checking SIP call limits for device tulip1 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3071 update_call_counter: Updating call counter for incoming call Looking for 403 in from-sip (domain 10.69.255.251) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3846 sip_new: *** Our native formats are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3847 sip_new: *** Joint capabilities are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3848 sip_new: *** Our capabilities are 0xeae (gsm|ulaw|alaw|g726|adpcm|lpc10|speex|ilbc) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3849 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:3872 sip_new: This channel will not be able to handle video. [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:7909 build_route: build_route: Contact hop: list_route: hop: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:13418 handle_request_invite: SIP/tulip1-09226120: New call is still down.... Trying... <--- Transmitting (no NAT) to 10.69.255.248:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.69.255.248:5060;branch=z9hG4bK-455c5987-f0bdb9b8-48b38f19;received=10.69.255.248;rport=5060 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403" Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 12:29:35] DEBUG[1962]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip1-09226120 [Nov 16 12:29:35] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip1 [Nov 16 12:29:35] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip1 [Nov 16 12:29:35] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip1 - state 1 (Not in use) [Nov 16 12:29:35] DEBUG[1963]: pbx.c:1685 pbx_extension_helper: Launching 'Macro' -- Executing [403@from-sip:1] Macro("SIP/tulip1-09226120", "ext|SIP/tulip3") in new stack [Nov 16 12:29:35] DEBUG[1963]: pbx.c:1685 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-ext:1] Dial("SIP/tulip1-09226120", "SIP/tulip3|15") in new stack [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:15194 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4337 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:2697 create_addr_from_peer: Our T38 capability (3840) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:2651 do_setnat: Setting NAT on RTP to Off [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:2661 do_setnat: Setting NAT on UDPTL to Off [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3846 sip_new: *** Our native formats are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3847 sip_new: *** Joint capabilities are 0x0 (nothing) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3848 sip_new: *** Our capabilities are 0xeae (gsm|ulaw|alaw|g726|adpcm|lpc10|speex|ilbc) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3849 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3851 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3872 sip_new: This channel will not be able to handle video. [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:16777 sip_set_rtp_peer: Early remote bridge setting SIP '628fd59c54e377883de5f18f06d2f1fa@10.69.255.251' - Sending media to 10.69.255.248 [Nov 16 12:29:35] DEBUG[1963]: rtp.c:1589 ast_rtp_make_compatible: Seeded SDP of 'SIP/tulip3-09238b38' with that of 'SIP/tulip1-09226120' [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable STACK-macro-ext-s-1. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable ARG1. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable STACK-from-sip-403-1. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Nov 16 12:29:35] DEBUG[1963]: channel.c:3191 ast_channel_inherit_variables: Not copying variable SIPURI. [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:2898 sip_call: Outgoing Call for tulip3 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:3071 update_call_counter: Updating call counter for outgoing call [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:2915 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:6190 add_sdp: ** Our capability: 0xcae (gsm|ulaw|alaw|g726|adpcm|lpc10|ilbc) Video flag: False [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:6191 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:6316 add_sdp: -- Done with adding codecs to SDP [Nov 16 12:29:35] DEBUG[1963]: channel.c:2275 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=20) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:6360 add_sdp: Done building SDP. Settling with this capability: 0xcae (gsm|ulaw|alaw|g726|adpcm|lpc10|ilbc) [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:1637 initialize_initreq: Initializing initreq for method INVITE - callid 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 0 [ 44]: INVITE sip:tulip3@10.69.255.247:5060 SIP/2.0 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 10.69.255.251:5060;branch=z9hG4bK5acceafb;rport [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 3 [ 63]: From: "Tulip ATA port 1" ;tag=as3ae4a53f [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 4 [ 35]: To: [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 5 [ 32]: Contact: [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 6 [ 55]: Call-ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 8 [ 24]: User-Agent: Asterisk PBX [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 9 [ 35]: Date: Thu, 16 Nov 2006 12:29:35 GMT [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 11 [ 19]: Supported: replaces [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 13 [ 19]: Content-Length: 409 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Header 14 [ 0]: [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 1 [ 37]: o=root 1955 1955 IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 2 [ 9]: s=session [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 3 [ 22]: c=IN IP4 10.69.255.248 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 5 [ 41]: m=audio 5004 RTP/AVP 0 8 3 111 97 7 5 101 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 8 [ 19]: a=rtpmap:3 GSM/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 9 [ 25]: a=rtpmap:111 G726-32/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 10 [ 21]: a=rtpmap:97 iLBC/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 11 [ 17]: a=fmtp:97 mode=30 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 12 [ 19]: a=rtpmap:7 LPC/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 13 [ 20]: a=rtpmap:5 DVI4/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 15 [ 15]: a=fmtp:101 0-16 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 16 [ 25]: a=silenceSupp:off - - - - [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 17 [ 10]: a=ptime:20 [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:4602 parse_request: Body 18 [ 10]: a=sendrecv [Nov 16 12:29:35] DEBUG[1963]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #17 -- Called tulip3 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 62]: From: "Tulip ATA port 1";tag=as3ae4a53f [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 89]: To: ;tag=100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 55]: Call-ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 69]: Via: SIP/2.0/UDP 10.69.255.251:5060;rport=5060;branch=z9hG4bK5acceafb [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 19]: Supported: replaces [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 46]: Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 40]: Contact: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [ 0]: [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 Their Tag Our tag: as3ae4a53f [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #17 - INVITE (got response) [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '628fd59c54e377883de5f18f06d2f1fa@10.69.255.251' Request 102: Found [Nov 16 12:29:35] DEBUG[1962]: chan_sip.c:11659 handle_response_invite: SIP response 180 to standard invite [Nov 16 12:29:35] DEBUG[1962]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip3-09238b38 -- SIP/tulip3-09238b38 is ringing [Nov 16 12:29:35] DEBUG[1963]: rtp.c:1524 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/tulip1-09226120' with that of 'SIP/tulip3-09238b38' [Nov 16 12:29:35] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip3 [Nov 16 12:29:35] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip3 [Nov 16 12:29:35] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip3 - state 1 (Not in use) <--- Transmitting (no NAT) to 10.69.255.248:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.69.255.248:5060;branch=z9hG4bK-455c5987-f0bdb9b8-48b38f19;received=10.69.255.248;rport=5060 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as210cb2b9 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 62]: From: "Tulip ATA port 1";tag=as3ae4a53f [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 89]: To: ;tag=100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 55]: Call-ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 69]: Via: SIP/2.0/UDP 10.69.255.251:5060;rport=5060;branch=z9hG4bK5acceafb [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 19]: Supported: replaces [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 46]: Allow: INVITE, ACK, BYE, REFER, NOTIFY, CANCEL [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 40]: Contact: [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [ 19]: Content-Length: 196 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 11 [ 0]: [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 0 [ 3]: v=0 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 1 [ 48]: o=rtp 1163680164 1163680164 IN IP4 10.69.255.247 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 2 [ 3]: s=- [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 3 [ 22]: c=IN IP4 10.69.255.247 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 4 [ 5]: t=0 0 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 5 [ 26]: m=audio 5004 RTP/AVP 2 101 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 6 [ 23]: a=rtpmap:2 g726-32/8000 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 Their Tag 100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 Our tag: as3ae4a53f [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:2073 __sip_ack: Acked pending invite 102 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:2088 __sip_ack: Stopping retransmission on '628fd59c54e377883de5f18f06d2f1fa@10.69.255.251' of Request 102: Match Found [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:11659 handle_response_invite: SIP response 200 to standard invite [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:5119 process_sdp: T38 state changed to 0 on channel SIP/tulip3-09238b38 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:5196 process_sdp: We're settling with these formats: 0x800 (g726) [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:5203 process_sdp: We have an owner, now see if we need to change this call [Nov 16 12:29:39] DEBUG[1962]: channel.c:2735 set_format: Set channel SIP/tulip3-09238b38 to read format ulaw [Nov 16 12:29:39] DEBUG[1962]: channel.c:2735 set_format: Set channel SIP/tulip3-09238b38 to write format ulaw [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:3071 update_call_counter: Updating call counter for outgoing call --- set_address_from_contact host '10.69.255.247' [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:7909 build_route: build_route: Contact hop: [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:5626 reqprep: Strict routing enforced for session 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:39] DEBUG[1963]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip3-09238b38 -- SIP/tulip3-09238b38 answered SIP/tulip1-09226120 [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:16777 sip_set_rtp_peer: Early remote bridge setting SIP '100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248' - Sending media to 10.69.255.247 [Nov 16 12:29:39] DEBUG[1963]: rtp.c:1524 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/tulip1-09226120' with that of 'SIP/tulip3-09238b38' [Nov 16 12:29:39] DEBUG[1963]: channel.c:2735 set_format: Set channel SIP/tulip1-09226120 to read format slin [Nov 16 12:29:39] DEBUG[1963]: channel.c:2735 set_format: Set channel SIP/tulip3-09238b38 to write format slin [Nov 16 12:29:39] DEBUG[1963]: channel.c:2735 set_format: Set channel SIP/tulip3-09238b38 to read format slin [Nov 16 12:29:39] DEBUG[1963]: channel.c:2735 set_format: Set channel SIP/tulip1-09226120 to write format slin [Nov 16 12:29:39] DEBUG[1963]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip1-09226120 [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:3514 sip_answer: SIP answering channel: SIP/tulip1-09226120 [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:6415 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:6190 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:6191 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.69.255.251 port 9760 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:6316 add_sdp: -- Done with adding codecs to SDP [Nov 16 12:29:39] DEBUG[1963]: channel.c:2275 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=16) [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:6360 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (no NAT) to 10.69.255.248:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.69.255.248:5060;branch=z9hG4bK-455c5987-f0bdb9b8-48b38f19;received=10.69.255.248;rport=5060 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as210cb2b9 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 239 v=0 o=root 1955 1955 IN IP4 10.69.255.247 s=session c=IN IP4 10.69.255.247 t=0 0 m=audio 5004 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 16 12:29:39] DEBUG[1963]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #19 [Nov 16 12:29:39] DEBUG[1963]: rtp.c:3175 ast_rtp_bridge: Channel codec0 = 4 is not codec1 = 2048, cannot native bridge in RTP. [Nov 16 12:29:39] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip3 [Nov 16 12:29:39] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip3 [Nov 16 12:29:39] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip3 - state 1 (Not in use) [Nov 16 12:29:39] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip1 [Nov 16 12:29:39] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip1 [Nov 16 12:29:39] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip1 - state 1 (Not in use) <--- SIP read from 10.69.255.248:5060 ---> ACK sip:403@10.69.255.251 SIP/2.0 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as210cb2b9 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 2 ACK Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c598b-f0bdca96-5146caf7 Max-Forwards: 70 Contact: Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251:5060;transport=UDP",response="f9c46dc659e4169e07d0b8672627da5a",algorithm=MD5 Content-Length: 0 <-------------> [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 33]: ACK sip:403@10.69.255.251 SIP/2.0 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 94]: From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 52]: To: "403";tag=as210cb2b9 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 72]: Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c598b-f0bdca96-5146caf7 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 54]: Contact: [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [191]: Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251:5060;transport=UDP",response="f9c46dc659e4169e07d0b8672627da5a",algorithm=MD5 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4401 find_call: = No match Their Call ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 Their Tag 100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 Our tag: as3ae4a53f [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Their Tag 100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 Our tag: as210cb2b9 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:14546 handle_request: **** Received ACK (6) - Command in SIP ACK [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:2078 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 [Nov 16 12:29:39] DEBUG[1962]: chan_sip.c:2088 __sip_ack: Stopping retransmission on '100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248' of Response 2: Match Found <--- SIP read from 10.69.255.248:5060 ---> BYE sip:403@10.69.255.251 SIP/2.0 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as210cb2b9 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 3 BYE Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c599e-f0be137d-62b5b547 Max-Forwards: 70 Supported: replaces Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251",response="a8e4ee022ea5752d706ba9af592a900f",algorithm=MD5 Content-Length: 0 <-------------> [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 33]: BYE sip:403@10.69.255.251 SIP/2.0 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 94]: From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 52]: To: "403";tag=as210cb2b9 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 72]: Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 11]: CSeq: 3 BYE [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 10.69.255.248:5060;rport;branch=z9hG4bK-455c599e-f0be137d-62b5b547 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 19]: Supported: replaces [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [172]: Authorization: Digest username="tulip1",realm="inspiredbroadcast.net",nonce="1b1b9c6d",uri="sip:403@10.69.255.251",response="a8e4ee022ea5752d706ba9af592a900f",algorithm=MD5 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 9 [ 17]: Content-Length: 0 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4401 find_call: = No match Their Call ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 Their Tag 100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 Our tag: as3ae4a53f [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 Their Tag 100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 Our tag: as210cb2b9 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:14546 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.69.255.248 : 5060 (NAT) [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:14127 handle_request_bye: Received bye, issuing owner hangup . <--- Transmitting (NAT) to 10.69.255.248:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.69.255.248:5060;branch=z9hG4bK-455c599e-f0be137d-62b5b547;received=10.69.255.248;rport=5060 From: "Line 1";tag=100c3d28-f8ff450a-13c4-455c5987-41950fcb-455c5987 To: "403";tag=as210cb2b9 Call-ID: 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 16 12:29:58] DEBUG[1963]: channel.c:3690 ast_generic_bridge: Didn't get a frame from channel: SIP/tulip1-09226120 [Nov 16 12:29:58] DEBUG[1963]: channel.c:4011 ast_channel_bridge: Bridge stops bridging channels SIP/tulip1-09226120 and SIP/tulip3-09238b38 [Nov 16 12:29:58] DEBUG[1963]: channel.c:1603 ast_hangup: Hanging up channel 'SIP/tulip3-09238b38' [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3369 sip_hangup: Hangup call SIP/tulip3-09238b38, SIP callid 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251) [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3377 sip_hangup: update_call_counter(tulip3) - decrement call limit counter on hangup [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3071 update_call_counter: Updating call counter for outgoing call [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:5626 reqprep: Strict routing enforced for session 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:1979 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #21 [Nov 16 12:29:58] DEBUG[1963]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip3-09238b38 [Nov 16 12:29:58] DEBUG[1963]: rtp.c:1485 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Nov 16 12:29:58] DEBUG[1963]: app_dial.c:1668 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Nov 16 12:29:58] DEBUG[1963]: app_macro.c:257 _macro_exec: Spawn extension (macro-ext,s,1) exited non-zero on 'SIP/tulip1-09226120' in macro 'ext' [Nov 16 12:29:58] DEBUG[1963]: pbx.c:2281 __ast_pbx_run: Spawn extension (macro-ext,s,1) exited non-zero on 'SIP/tulip1-09226120' == Spawn extension (macro-ext, s, 1) exited non-zero on 'SIP/tulip1-09226120' [Nov 16 12:29:58] DEBUG[1963]: channel.c:1603 ast_hangup: Hanging up channel 'SIP/tulip1-09226120' [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3369 sip_hangup: Hangup call SIP/tulip1-09226120, SIP callid 100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248) [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3377 sip_hangup: update_call_counter(tulip1) - decrement call limit counter on hangup [Nov 16 12:29:58] DEBUG[1963]: chan_sip.c:3071 update_call_counter: Updating call counter for incoming call [Nov 16 12:29:58] DEBUG[1963]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/tulip1-09226120 [Nov 16 12:29:58] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip3 [Nov 16 12:29:58] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip3 [Nov 16 12:29:58] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip3 - state 1 (Not in use) [Nov 16 12:29:58] DEBUG[1958]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - tulip1 [Nov 16 12:29:58] DEBUG[1958]: chan_sip.c:15136 sip_devicestate: Checking device state for peer tulip1 [Nov 16 12:29:58] DEBUG[1958]: devicestate.c:287 do_state_change: Changing state for SIP/tulip1 - state 1 (Not in use) [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 1 [ 62]: From: "Tulip ATA port 1";tag=as3ae4a53f [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 2 [ 89]: To: ;tag=100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 3 [ 55]: Call-ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 4 [ 13]: CSeq: 103 BYE [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 5 [ 69]: Via: SIP/2.0/UDP 10.69.255.251:5060;rport=5060;branch=z9hG4bK6467549f [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 6 [ 19]: Supported: replaces [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 7 [ 17]: Content-Length: 0 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4602 parse_request: Header 8 [ 0]: [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:4401 find_call: = Found Their Call ID: 628fd59c54e377883de5f18f06d2f1fa@10.69.255.251 Their Tag 100c3460-f7ff450a-13c4-455c5988-55b2c980-455c5988 Our tag: as3ae4a53f [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:2078 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #21 [Nov 16 12:29:58] DEBUG[1962]: chan_sip.c:2088 __sip_ack: Stopping retransmission on '628fd59c54e377883de5f18f06d2f1fa@10.69.255.251' of Request 103: Match Found Really destroying SIP dialog '628fd59c54e377883de5f18f06d2f1fa@10.69.255.251' Method: INVITE Really destroying SIP dialog '100c5fe8-f8ff450a-13c4-455c5987-73bd11eb-455c5987@10.69.255.248' Method: BYE Beginning asterisk shutdown.... Executing last minute cleanups == Destroying musiconhold processes Asterisk cleanly ending (2). [Nov 16 12:30:02] DEBUG[1955]: asterisk.c:1144 quit_handler: Asterisk ending (2). ]0;root@asterisk1:~/src/asterisk[root@asterisk1 asterisk]# Script done on Thu 16 Nov 2006 12:30:04 GMT