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