Asterisk SVN-trunk-r39109M, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type '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 'show license' for details. ========================================================================= Connected to Asterisk SVN-trunk-r39109M currently running on foxtrot (pid = 18629) Verbosity is at least 3 foxtrot*CLI> set verbose 50 Verbosity was 3 and is now 50 foxtrot*CLI> set debug 4 Core debug was 0 and is now 4 foxtrot*CLI> sip debug 4 Usage: sip debug Enables dumping of SIP packets for debugging purposes sip debug ip Enables dumping of SIP packets to and from host. sip debug peer Enables dumping of SIP packets to and from host. Require peer to be registered. foxtrot*CLI> sip debug SIP Debugging enabled [Aug 7 08:47:12] DEBUG[18694]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 -- Accepting call from '07803034440' to '444606' on channel 0/1, span 1 [Aug 7 08:47:12] DEBUG[18694]: chan_zap.c:1384 zt_enable_ec: Enabled echo cancellation on channel 1 [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Aug 7 08:47:12] DEBUG[18715]: pbx.c:1675 pbx_extension_helper: Launching 'Goto' -- Executing [444606@isdn10:1] Goto("Zap/1-1", "common|7706|1") in new stack -- Goto (common,7706,1) [Aug 7 08:47:12] DEBUG[18715]: pbx.c:1675 pbx_extension_helper: Launching 'Answer' -- Executing [7706@common:1] Answer("Zap/1-1", "") in new stack [Aug 7 08:47:12] DEBUG[18715]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Aug 7 08:47:12] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x9963df8' [Aug 7 08:47:12] DEBUG[18715]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [7706@common:2] Dial("Zap/1-1", "SIP/7706|120|g") in new stack [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:14629 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:2520 create_addr_from_peer: Setting NAT on RTP to Off [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3608 sip_new: *** Our native formats are 0x2 (gsm) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3609 sip_new: *** Joint capabilities are 0x0 (nothing) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3610 sip_new: *** Our capabilities are 0xf (g723|gsm|ulaw|alaw) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3611 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3613 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:3634 sip_new: This channel will not be able to handle video. [Aug 7 08:47:12] DEBUG[18715]: rtp.c:1384 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-common-7706-2. [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-common-7706-1. [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-1. [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable CALLEDTON. [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable ANI2. [Aug 7 08:47:12] DEBUG[18715]: channel.c:3029 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY. [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:2718 sip_call: Outgoing Call for 7706 [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:5812 add_sdp: ** Our capability: 0xf (g723|gsm|ulaw|alaw) Video flag: False [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:5813 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 10014 Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x1 (g723) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:5965 add_sdp: -- Done with adding codecs to SDP [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:6004 add_sdp: Done building SDP. Settling with this capability: 0xf (g723|gsm|ulaw|alaw) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:7706@192.168.0.200:5060 SIP/2.0 (42) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport (60) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 2: From: "07803034440" ;tag=as11762cff (62) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 3: To: (33) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 4: Contact: (36) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 5: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 9: Date: Mon, 07 Aug 2006 07:47:12 GMT (35) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 11: Supported: replaces (19) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 13: Content-Length: 293 (19) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4332 parse_request: Header 14: (0) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: o=root 18629 18629 IN IP4 90.0.0.62 (35) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: s=session (9) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Aug 7 08:47:12] DEBUG[18716]: app_queue.c:536 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 7 08:47:12] DEBUG[18717]: app_queue.c:536 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: m=audio 10014 RTP/AVP 8 3 0 4 101 (33) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=silenceSupp:off - - - - (25) [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:4364 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 192.168.0.200:5060: INVITE sip:7706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport From: "07803034440" ;tag=as11762cff To: Contact: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 07 Aug 2006 07:47:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 293 v=0 o=root 18629 18629 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 10014 RTP/AVP 8 3 0 4 101 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 7 08:47:12] DEBUG[18715]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 -- Called 7706 [Aug 7 08:47:12] DEBUG[18715]: channel.c:2564 set_format: Set channel SIP/7706-09966a10 to read format slin [Aug 7 08:47:12] DEBUG[18715]: channel.c:2564 set_format: Set channel Zap/1-1 to write format slin [Aug 7 08:47:12] DEBUG[18715]: channel.c:2564 set_format: Set channel Zap/1-1 to read format gsm foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: SIP/2.0 100 Trying Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport From: "07803034440" ;tag=as11762cff To: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 100 Trying (18) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport (60) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "07803034440" ;tag=as11762cff (62) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: (33) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Server: CSCO/7 (14) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:2047 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #13 - INVITE (got response) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:2056 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '17cdac1c6923c87f545e28ce52040093@90.0.0.62' Request 102: Found [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:11160 handle_response_invite: SIP response 100 to standard invite foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport From: "07803034440" ;tag=as11762cff To: ;tag=000785993d3d005c5e91208a-75502a05 Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport (60) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "07803034440" ;tag=as11762cff (62) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=000785993d3d005c5e91208a-75502a05 (71) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Server: CSCO/7 (14) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:2056 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '17cdac1c6923c87f545e28ce52040093@90.0.0.62' Request 102: Found [Aug 7 08:47:12] DEBUG[18697]: chan_sip.c:11160 handle_response_invite: SIP response 180 to standard invite [Aug 7 08:47:12] DEBUG[18697]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09966a10 -- SIP/7706-09966a10 is ringing [Aug 7 08:47:12] DEBUG[18715]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Aug 7 08:47:12] DEBUG[18715]: chan_zap.c:4918 zt_indicate: Requested indication 3 on channel Zap/1-1 [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:12] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:12] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:12] DEBUG[18718]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: REGISTER sip:90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK25a5030a From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 432 REGISTER User-Agent: CSCO/7 Contact: Content-Length: 0 Expires: 3600 [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: REGISTER sip:90.0.0.62 SIP/2.0 (30) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK25a5030a (58) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: sip:7706@90.0.0.62 (24) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: sip:7706@90.0.0.62 (22) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 (58) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 432 REGISTER (18) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Expires: 3600 (13) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 - REGISTER (No RTP) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.0.200 : 5060 (no NAT) Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK25a5030a;received=192.168.0.200 From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 432 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK25a5030a;received=192.168.0.200 From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62;tag=as1c7bded6 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 432 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6c66feb4" Content-Length: 0 --- Scheduling destruction of SIP dialog '00078599-3d3d0009-65a30346-2c41efed@192.168.0.200' in 32000 ms (Method: REGISTER) foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: REGISTER sip:90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0db945b8 From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 433 REGISTER User-Agent: CSCO/7 Contact: Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="41a9ce108a6bbe1dcd9057bb23606e32",nonce="6c66feb4",algorithm=MD5 Content-Length: 0 Expires: 3600 [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: REGISTER sip:90.0.0.62 SIP/2.0 (30) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0db945b8 (58) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: sip:7706@90.0.0.62 (24) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: sip:7706@90.0.0.62 (22) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 (58) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 433 REGISTER (18) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="41a9ce108a6bbe1dcd9057bb23606e32",nonce="6c66feb4",algorithm=MD5 (149) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Content-Length: 0 (17) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Expires: 3600 (13) [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: (0) --- (11 headers 0 lines)--- [Aug 7 08:47:15] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.0.200 : 5060 (no NAT) Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0db945b8;received=192.168.0.200 From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 433 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- -- Saved useragent "CSCO/7" for peer 7706 Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0db945b8;received=192.168.0.200 From: sip:7706@90.0.0.62 To: sip:7706@90.0.0.62;tag=as1c7bded6 Call-ID: 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 CSeq: 433 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 3600 Contact: ;expires=3600 Date: Mon, 07 Aug 2006 07:47:15 GMT Content-Length: 0 --- [Aug 7 08:47:15] DEBUG[18697]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706 Scheduling destruction of SIP dialog '00078599-3d3d0009-65a30346-2c41efed@192.168.0.200' in 15000 ms (Method: REGISTER) [Aug 7 08:47:15] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:15] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:15] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:15] DEBUG[18719]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport From: "07803034440" ;tag=as11762cff To: ;tag=000785993d3d005c5e91208a-75502a05 Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 198 v=0 o=Cisco-SIPUA 23317 6717 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 22822 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK619e72df;rport (60) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "07803034440" ;tag=as11762cff (62) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=000785993d3d005c5e91208a-75502a05 (71) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Server: CSCO/7 (14) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Type: application/sdp (29) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Content-Length: 198 (19) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: (0) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=Cisco-SIPUA 23317 6717 IN IP4 192.168.0.200 (45) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s=SIP Call (10) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 22822 RTP/AVP 0 101 (27) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) --- (10 headers 9 lines)--- [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:1996 __sip_ack: Acked pending invite 102 [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '17cdac1c6923c87f545e28ce52040093@90.0.0.62' of Request 102: Match Not Found [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:11160 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.200:22822 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4837 process_sdp: T38 state changed to 0 on channel SIP/7706-09966a10 Capabilities: us - 0xf (g723|gsm|ulaw|alaw), 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 192.168.0.200:22822 [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4907 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4914 process_sdp: We have an owner, now see if we need to change this call [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:4919 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x4 (ulaw) and not 0x2 (gsm) [Aug 7 08:47:16] DEBUG[18697]: channel.c:2564 set_format: Set channel SIP/7706-09966a10 to read format slin [Aug 7 08:47:16] DEBUG[18697]: channel.c:2564 set_format: Set channel SIP/7706-09966a10 to write format gsm [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:7593 build_route: build_route: Contact hop: list_route: hop: [Aug 7 08:47:16] DEBUG[18697]: chan_sip.c:5343 reqprep: Strict routing enforced for session 17cdac1c6923c87f545e28ce52040093@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Transmitting (no NAT) to 192.168.0.200:5060: ACK sip:7706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK69a62a96;rport From: "07803034440" ;tag=as11762cff To: ;tag=000785993d3d005c5e91208a-75502a05 Contact: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 7 08:47:16] DEBUG[18715]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09966a10 -- SIP/7706-09966a10 answered Zap/1-1 [Aug 7 08:47:16] DEBUG[18715]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Aug 7 08:47:16] DEBUG[18715]: chan_zap.c:4918 zt_indicate: Requested indication -1 on channel Zap/1-1 [Aug 7 08:47:16] DEBUG[18715]: channel.c:2564 set_format: Set channel Zap/1-1 to read format ulaw [Aug 7 08:47:16] DEBUG[18715]: channel.c:2564 set_format: Set channel SIP/7706-09966a10 to write format ulaw [Aug 7 08:47:16] DEBUG[18715]: channel.c:2564 set_format: Set channel SIP/7706-09966a10 to read format alaw [Aug 7 08:47:16] DEBUG[18715]: channel.c:2564 set_format: Set channel Zap/1-1 to write format alaw [Aug 7 08:47:16] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:16] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:16] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:16] DEBUG[18720]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:16] DEBUG[18715]: rtp.c:2343 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:17] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:18] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:18] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Aug 7 08:47:18] DEBUG[18715]: chan_zap.c:4813 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: INVITE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK730921c4 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 193 Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 12530 14785 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 22822 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:07803034440@90.0.0.62:5060 SIP/2.0 (45) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK730921c4 (58) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=000785993d3d005c5e91208a-75502a05 (73) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "07803034440" ;tag=as11762cff (60) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 101 INVITE (16) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Type: application/sdp (29) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Content-Length: 193 (19) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no (106) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: (0) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=Cisco-SIPUA 12530 14785 IN IP4 192.168.0.200 (46) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s=SIP Call (10) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 22822 RTP/AVP 0 101 (27) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 9 lines)--- [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:22822 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4837 process_sdp: T38 state changed to 0 on channel SIP/7706-09966a10 Capabilities: us - 0xf (g723|gsm|ulaw|alaw), 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 0.0.0.0:22822 [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4907 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:4914 process_sdp: We have an owner, now see if we need to change this call [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:12850 handle_request_invite: Got a SIP re-invite for call 17cdac1c6923c87f545e28ce52040093@90.0.0.62 [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:12939 handle_request_invite: SIP/7706-09966a10: This call is UP.... [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:5812 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:5813 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 10014 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:5965 add_sdp: -- Done with adding codecs to SDP [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:6004 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK730921c4;received=192.168.0.200 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 222 v=0 o=root 18629 18630 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 10014 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 7 08:47:21] DEBUG[18697]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #19 [Aug 7 08:47:21] DEBUG[18715]: chan_zap.c:4918 zt_indicate: Requested indication 16 on channel Zap/1-1 -- Started music on hold, class 'default', on Zap/1-1 [Aug 7 08:47:21] DEBUG[18715]: channel.c:1837 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 7 08:47:21] DEBUG[18715]: channel.c:2117 __ast_read: Generator got voice, switching to phase locked mode [Aug 7 08:47:21] DEBUG[18715]: channel.c:1837 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 7 08:47:21] DEBUG[18715]: channel.c:2564 set_format: Set channel Zap/1-1 to write format ulaw [Aug 7 08:47:21] DEBUG[18715]: res_musiconhold.c:252 ast_moh_files_next: Zap/1-1 Opened file 10 '/var/lib/asterisk/sounds/custom/moh/track20' foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: ACK sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK36f24fc7 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 101 ACK User-Agent: CSCO/7 Content-Length: 0 [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: ACK sip:07803034440@90.0.0.62:5060 SIP/2.0 (42) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK36f24fc7 (58) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=000785993d3d005c5e91208a-75502a05 (73) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "07803034440" ;tag=as11762cff (60) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 101 ACK (13) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Content-Length: 0 (17) [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 [Aug 7 08:47:22] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '17cdac1c6923c87f545e28ce52040093@90.0.0.62' of Response 101: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: INVITE sip:7709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK427c7f50 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Expires: 180 Content-Type: application/sdp Content-Length: 247 Accept: application/sdp Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 592 11248 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 22824 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:7709@90.0.0.62 SIP/2.0 (33) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK427c7f50 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: (24) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 101 INVITE (16) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Expires: 180 (12) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Content-Length: 247 (19) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: Accept: application/sdp (23) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 12: Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no (106) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 13: (0) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=Cisco-SIPUA 592 11248 IN IP4 192.168.0.200 (44) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s=SIP Call (10) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 22824 RTP/AVP 0 8 18 101 (32) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 11 lines)--- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 - INVITE (With RTP) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Using INVITE request as basis request - 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:8632 check_user_full: Setting NAT on RTP to Off Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK427c7f50;received=192.168.0.200 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as060e1d3d Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7180598b" Content-Length: 0 --- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #20 Scheduling destruction of SIP dialog '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' in 32000 ms (Method: INVITE) Found user '7706' foxtrot*CLI> <-- SIP read from 192.168.0.200:52648: ACK sip:7709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK427c7f50 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as060e1d3d Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 101 ACK Content-Length: 0 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: ACK sip:7709@90.0.0.62 SIP/2.0 (30) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK427c7f50 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=as060e1d3d (39) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 101 ACK (13) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Content-Length: 0 (17) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: (0) --- (7 headers 0 lines)--- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' of Response 101: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: INVITE sip:7709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK229c32d4 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 102 INVITE User-Agent: CSCO/7 Contact: Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 Expires: 180 Content-Type: application/sdp Content-Length: 247 Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 592 11248 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 22824 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:7709@90.0.0.62 SIP/2.0 (33) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK229c32d4 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: (24) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 (155) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Expires: 180 (12) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Content-Type: application/sdp (29) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: Content-Length: 247 (19) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 12: Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no (106) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 13: (0) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=Cisco-SIPUA 592 11248 IN IP4 192.168.0.200 (44) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s=SIP Call (10) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 22824 RTP/AVP 0 8 18 101 (32) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 11 lines)--- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Using INVITE request as basis request - 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:8632 check_user_full: Setting NAT on RTP to Off Found user '7706' Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.200:22824 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4837 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0xf (g723|gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.200:22824 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4907 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:12802 handle_request_invite: Checking SIP call limits for device 7706 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call Looking for 7709 in from-sip (domain 90.0.0.62) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:3608 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:3609 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:3610 sip_new: *** Our capabilities are 0xf (g723|gsm|ulaw|alaw) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:3611 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:3634 sip_new: This channel will not be able to handle video. [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:7593 build_route: build_route: Contact hop: list_route: hop: [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:12872 handle_request_invite: SIP/7706-09975bd8: New call is still down.... Trying... Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK229c32d4;received=192.168.0.200 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 7 08:47:26] DEBUG[18697]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09975bd8 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:26] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:26] DEBUG[18721]: pbx.c:1675 pbx_extension_helper: Launching 'Answer' -- Executing [7709@from-sip:1] Answer("SIP/7706-09975bd8", "") in new stack [Aug 7 08:47:26] DEBUG[18721]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09975bd8 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:26] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:3319 sip_answer: SIP answering channel: SIP/7706-09975bd8 [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:5812 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:5813 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 12460 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:5965 add_sdp: -- Done with adding codecs to SDP [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:6004 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK229c32d4;received=192.168.0.200 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as4a241784 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 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: 246 v=0 o=root 18629 18629 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 12460 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 7 08:47:26] DEBUG[18721]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #22 [Aug 7 08:47:26] DEBUG[18721]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [7709@from-sip:2] Dial("SIP/7706-09975bd8", "Local/7710@from-sip/n") in new stack [Aug 7 08:47:26] DEBUG[18721]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/7710@from-sip-6e45,2 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 7710@from-sip [Aug 7 08:47:26] DEBUG[18686]: chan_local.c:140 local_devicestate: Checking if extension 7710@from-sip exists (devicestate) [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Local/7710@from-sip - state 2 (In use) [Aug 7 08:47:26] DEBUG[18721]: rtp.c:1377 ast_rtp_make_compatible: Channel 'Local/7710@from-sip-6e45,1' has no RTP, not doing anything [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-from-sip-7709-2. [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-from-sip-7709-1. [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 7 08:47:26] DEBUG[18721]: channel.c:3029 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 7710@from-sip/n [Aug 7 08:47:26] DEBUG[18722]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18723]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18724]: app_queue.c:536 changethread: Device 'Local/7710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18725]: pbx.c:1675 pbx_extension_helper: Launching 'Answer' -- Executing [7710@from-sip:1] Answer("Local/7710@from-sip-6e45,2", "") in new stack [Aug 7 08:47:26] DEBUG[18721]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/7710@from-sip-6e45,1 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 7710@from-sip [Aug 7 08:47:26] DEBUG[18686]: chan_local.c:140 local_devicestate: Checking if extension 7710@from-sip exists (devicestate) [Aug 7 08:47:26] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' -- Local/7710@from-sip-6e45,1 answered SIP/7706-09975bd8 [Aug 7 08:47:26] DEBUG[18721]: rtp.c:1317 ast_rtp_early_bridge: Channel 'Local/7710@from-sip-6e45,1' has no RTP, not doing anything [Aug 7 08:47:26] DEBUG[18725]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/7710@from-sip-6e45,2 [Aug 7 08:47:26] DEBUG[18725]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [7710@from-sip:2] Dial("Local/7710@from-sip-6e45,2", "SIP/7710|120|g") in new stack [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:14629 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:2520 create_addr_from_peer: Setting NAT on RTP to Off [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3608 sip_new: *** Our native formats are 0x2 (gsm) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3609 sip_new: *** Joint capabilities are 0x0 (nothing) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3610 sip_new: *** Our capabilities are 0xf (g723|gsm|ulaw|alaw) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3611 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3613 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:3634 sip_new: This channel will not be able to handle video. [Aug 7 08:47:26] DEBUG[18725]: rtp.c:1384 ast_rtp_make_compatible: Channel 'Local/7710@from-sip-6e45,2' has no RTP, not doing anything [Aug 7 08:47:26] DEBUG[18725]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-from-sip-7710-2. [Aug 7 08:47:26] DEBUG[18725]: channel.c:3029 ast_channel_inherit_variables: Not copying variable STACK-from-sip-7710-1. [Aug 7 08:47:26] DEBUG[18725]: channel.c:3029 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:2718 sip_call: Outgoing Call for 7710 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Local/7710@from-sip - state 2 (In use) [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 7710@from-sip [Aug 7 08:47:26] DEBUG[18686]: chan_local.c:140 local_devicestate: Checking if extension 7710@from-sip exists (devicestate) [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Local/7710@from-sip - state 2 (In use) [Aug 7 08:47:26] DEBUG[18726]: app_queue.c:536 changethread: Device 'Local/7710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18727]: app_queue.c:536 changethread: Device 'Local/7710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:5812 add_sdp: ** Our capability: 0xf (g723|gsm|ulaw|alaw) Video flag: False [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:5813 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 90.0.0.62 port 16276 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x1 (g723) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:5965 add_sdp: -- Done with adding codecs to SDP [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:6004 add_sdp: Done building SDP. Settling with this capability: 0xf (g723|gsm|ulaw|alaw) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:7710@192.168.0.12:54978;rinstance=301ef85bba12dd44 SIP/2.0 (69) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport (60) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 2: From: "7706" ;tag=as72564a0f (57) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 3: To: (60) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 4: Contact: (38) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 5: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 (51) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 9: Date: Mon, 07 Aug 2006 07:47:26 GMT (35) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 11: Supported: replaces (19) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 13: Content-Length: 293 (19) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4332 parse_request: Header 14: (0) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: o=root 18629 18629 IN IP4 90.0.0.62 (35) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: s=session (9) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: m=audio 16276 RTP/AVP 0 3 8 4 101 (33) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=silenceSupp:off - - - - (25) [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:4364 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 192.168.0.12:54978: INVITE sip:7710@192.168.0.12:54978;rinstance=301ef85bba12dd44 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport From: "7706" ;tag=as72564a0f To: Contact: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 07 Aug 2006 07:47:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 293 v=0 o=root 18629 18629 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 16276 RTP/AVP 0 3 8 4 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 7 08:47:26] DEBUG[18725]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #23 -- Called 7710 [Aug 7 08:47:26] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to read format slin [Aug 7 08:47:26] DEBUG[18725]: channel.c:2564 set_format: Set channel Local/7710@from-sip-6e45,2 to write format slin [Aug 7 08:47:26] DEBUG[18725]: channel.c:2564 set_format: Set channel Local/7710@from-sip-6e45,2 to read format slin [Aug 7 08:47:26] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to write format slin RTCP SR transmission error, rtcp halted Interrupted system call [Aug 7 08:47:26] NOTICE[18697]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 18! <-- SIP read from 192.168.0.12:54978: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport=5060 Contact: To: ;tag=316aba05 From: "7706";tag=as72564a0f Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 102 INVITE User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 0 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport=5060 (65) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: Contact: (65) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=316aba05 (73) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: From: "7706";tag=as72564a0f (56) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 (51) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2047 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #23 - INVITE (got response) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2056 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '600bcc6f6ac629a12f07e13e420bf602@90.0.0.62' Request 102: Found [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:11160 handle_response_invite: SIP response 180 to standard invite [Aug 7 08:47:26] DEBUG[18697]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7710-0997f900 -- SIP/7710-0997f900 is ringing [Aug 7 08:47:26] DEBUG[18725]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Local/7710@from-sip-6e45,2' has no RTP, not doing anything [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7710 [Aug 7 08:47:26] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7710 [Aug 7 08:47:26] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7710 - state 1 (Not in use) [Aug 7 08:47:26] DEBUG[18721]: channel.c:3521 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel Local/7710@from-sip-6e45,1 [Aug 7 08:47:26] DEBUG[18721]: channel.c:3793 ast_channel_bridge: Bridge stops bridging channels SIP/7706-09975bd8 and Local/7710@from-sip-6e45,1 [Aug 7 08:47:26] DEBUG[18721]: channel.c:2216 ast_indicate_data: Driver for channel 'SIP/7706-09975bd8' does not support indication 3, emulating it [Aug 7 08:47:26] DEBUG[18721]: channel.c:2564 set_format: Set channel SIP/7706-09975bd8 to write format slin [Aug 7 08:47:26] DEBUG[18721]: channel.c:1837 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 7 08:47:26] DEBUG[18728]: app_queue.c:536 changethread: Device 'SIP/7710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:26] DEBUG[18721]: rtp.c:2343 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 7 08:47:26] DEBUG[18721]: rtp.c:639 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Aug 7 08:47:26] DEBUG[18721]: rtp.c:639 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Aug 7 08:47:26] DEBUG[18721]: rtp.c:639 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Aug 7 08:47:26] DEBUG[18721]: channel.c:2117 __ast_read: Generator got voice, switching to phase locked mode [Aug 7 08:47:26] DEBUG[18721]: channel.c:1837 ast_settimeout: Scheduling timer at 0 sample intervals <-- SIP read from 192.168.0.200:52464: ACK sip:7709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6a97d99e From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as4a241784 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 102 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 Content-Length: 0 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: ACK sip:7709@90.0.0.62:5060 SIP/2.0 (35) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6a97d99e (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=as4a241784 (39) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 ACK (13) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 (155) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22 [Aug 7 08:47:26] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' of Response 102: Match Not Found [Aug 7 08:47:30] DEBUG[18697]: chan_sip.c:1943 __sip_autodestruct: Auto destroying call '00078599-3d3d0009-65a30346-2c41efed@192.168.0.200' [Aug 7 08:47:30] DEBUG[18697]: chan_sip.c:2985 sip_destroy: Destroying SIP dialog 00078599-3d3d0009-65a30346-2c41efed@192.168.0.200 Really destroying SIP dialog '00078599-3d3d0009-65a30346-2c41efed@192.168.0.200' Method: REGISTER foxtrot*CLI> <-- SIP read from 192.168.0.12:54978: [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: (0) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: (0) --- (0 headers 1 lines)--- [Aug 7 08:47:32] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 132 bytes foxtrot*CLI> <-- SIP read from 192.168.0.12:54978: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport=5060 Contact: To: ;tag=316aba05 From: "7706";tag=as72564a0f Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 243 v=0 o=- 9 2 IN IP4 192.168.0.12 s= c=IN IP4 192.168.0.12 t=0 0 m=audio 50190 RTP/AVP 0 3 8 101 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv a=x-rtp-session-id:B7839669B7A54E00BA10040900B3F109 [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK135afe04;rport=5060 (65) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: Contact: (65) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=316aba05 (73) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: From: "7706";tag=as72564a0f (56) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 (51) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Type: application/sdp (29) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Content-Length: 243 (19) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: (0) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=- 9 2 IN IP4 192.168.0.12 (27) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s= (27) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 192.168.0.12 (21) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 50190 RTP/AVP 0 3 8 101 (31) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=sendrecv (10) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=x-rtp-session-id:B7839669B7A54E00BA10040900B3F109 (51) --- (11 headers 10 lines)--- [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:1996 __sip_ack: Acked pending invite 102 [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '600bcc6f6ac629a12f07e13e420bf602@90.0.0.62' of Request 102: Match Not Found [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:11160 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 3 Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.12:50190 Got unsupported a:fmtp in SDP offer Found description format telephone-event for ID 101 [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4837 process_sdp: T38 state changed to 0 on channel SIP/7710-0997f900 Capabilities: us - 0xf (g723|gsm|ulaw|alaw), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.12:50190 [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4907 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:4914 process_sdp: We have an owner, now see if we need to change this call [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:7593 build_route: build_route: Contact hop: list_route: hop: [Aug 7 08:47:32] DEBUG[18697]: chan_sip.c:5343 reqprep: Strict routing enforced for session 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.12, port 54978 Transmitting (no NAT) to 192.168.0.12:54978: ACK sip:7710@192.168.0.12:54978;rinstance=301ef85bba12dd44 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK5a964a1a;rport From: "7706" ;tag=as72564a0f To: ;tag=316aba05 Contact: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 7 08:47:32] DEBUG[18725]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7710-0997f900 -- SIP/7710-0997f900 answered Local/7710@from-sip-6e45,2 [Aug 7 08:47:32] DEBUG[18725]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Local/7710@from-sip-6e45,2' has no RTP, not doing anything [Aug 7 08:47:32] DEBUG[18721]: channel.c:3521 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/7710@from-sip-6e45,1 [Aug 7 08:47:32] DEBUG[18721]: channel.c:3793 ast_channel_bridge: Bridge stops bridging channels SIP/7706-09975bd8 and Local/7710@from-sip-6e45,1 [Aug 7 08:47:32] DEBUG[18721]: channel.c:2564 set_format: Set channel SIP/7706-09975bd8 to write format ulaw [Aug 7 08:47:32] DEBUG[18721]: channel.c:1837 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 7 08:47:32] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7710 [Aug 7 08:47:32] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7710 [Aug 7 08:47:32] DEBUG[18725]: rtp.c:2343 ast_rtp_write: Ooh, format changed from unknown to gsm [Aug 7 08:47:32] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7710 - state 1 (Not in use) [Aug 7 08:47:32] DEBUG[18729]: app_queue.c:536 changethread: Device 'SIP/7710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:33] DEBUG[18725]: chan_sip.c:3894 sip_rtp_read: Oooh, format changed to 4 [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to read format slin [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to write format slin [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel Local/7710@from-sip-6e45,2 to read format ulaw [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to write format ulaw [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel SIP/7710-0997f900 to read format ulaw [Aug 7 08:47:33] DEBUG[18725]: channel.c:2564 set_format: Set channel Local/7710@from-sip-6e45,2 to write format ulaw [Aug 7 08:47:33] DEBUG[18725]: rtp.c:2343 ast_rtp_write: Ooh, format changed from gsm to ulaw [Aug 7 08:47:35] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:39] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:42] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: INVITE sip:7709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4dafb19e From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as4a241784 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 103 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 242 Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 v=0 o=Cisco-SIPUA 9738 13042 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 22824 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: INVITE sip:7709@90.0.0.62:5060 SIP/2.0 (38) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4dafb19e (58) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=as4a241784 (39) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 103 INVITE (16) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Type: application/sdp (29) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Content-Length: 242 (19) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no (106) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 (155) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 12: (0) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: v=0 (3) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: o=Cisco-SIPUA 9738 13042 IN IP4 192.168.0.200 (45) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: s=SIP Call (10) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: t=0 0 (5) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: m=audio 22824 RTP/AVP 0 8 18 101 (32) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: a=fmtp:101 0-15 (15) --- (12 headers 11 lines)--- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:22824 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4837 process_sdp: T38 state changed to 0 on channel SIP/7706-09975bd8 Capabilities: us - 0xf (g723|gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 0.0.0.0:22824 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4907 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4914 process_sdp: We have an owner, now see if we need to change this call [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12850 handle_request_invite: Got a SIP re-invite for call 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12939 handle_request_invite: SIP/7706-09975bd8: This call is UP.... [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:5812 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:5813 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 12460 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:5965 add_sdp: -- Done with adding codecs to SDP [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:6004 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4dafb19e;received=192.168.0.200 From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as4a241784 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 246 v=0 o=root 18629 18630 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 12460 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #27 -- Started music on hold, class 'default', on SIP/7710-0997f900 [Aug 7 08:47:43] DEBUG[18725]: channel.c:1837 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 7 08:47:43] DEBUG[18725]: channel.c:2117 __ast_read: Generator got voice, switching to phase locked mode [Aug 7 08:47:43] DEBUG[18725]: channel.c:1837 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 7 08:47:43] DEBUG[18725]: res_musiconhold.c:252 ast_moh_files_next: SIP/7710-0997f900 Opened file 5 '/var/lib/asterisk/sounds/custom/moh/track19' [Aug 7 08:47:43] DEBUG[18725]: rtp.c:2242 ast_rtp_raw_write: Difference is 1032, ms is 149 foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: ACK sip:7709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK17c967bf From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 To: ;tag=as4a241784 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 103 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 Content-Length: 0 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: ACK sip:7709@90.0.0.62:5060 SIP/2.0 (35) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK17c967bf (58) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (74) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=as4a241784 (39) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 103 ACK (13) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Proxy-Authorization: Digest username="7706",realm="asterisk",uri="sip:90.0.0.62",response="f492a012e926b12b375023f9a342723a",nonce="7180598b",algorithm=MD5 (155) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #27 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' of Response 103: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: REFER sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3e3d1ee0 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 REFER User-Agent: CSCO/7 Contact: Content-Length: 0 Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no Refer-To: Referred-By: [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: REFER sip:07803034440@90.0.0.62:5060 SIP/2.0 (44) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3e3d1ee0 (58) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=000785993d3d005c5e91208a-75502a05 (73) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "07803034440" ;tag=as11762cff (60) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 REFER (15) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Contact: (38) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: Remote-Party-ID: "foxtrot" ;party=calling;id-type=subscriber;privacy=off;screen=no (106) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 10: Refer-To: (165) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 11: Referred-By: (42) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 12: (0) --- (12 headers 0 lines)--- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received REFER (9) - Command in SIP REFER Call 17cdac1c6923c87f545e28ce52040093@90.0.0.62 got a SIP call transfer from callee: (REFER)! [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:8292 get_refer_info: Attended transfer: Will use Replace-Call-ID : 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (No check of from/to tags) SIP transfer to extension 7709@from-sip by 7706@192.168.0.200:5060 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13340 handle_request_refer: SIP attended transfer: Transferer channel SIP/7706-09966a10, transferee channel Zap/1-1 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13356 handle_request_refer: Got SIP transfer, applying to bridged peer 'Zap/1-1' [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:8148 get_sip_pvt_byid_locked: Looking for callid 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (fromtag 000785993d3d005d1a59380b-60c9cdb5 totag as4a241784) [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:8172 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 000785993d3d005d1a59380b-60c9cdb5 Our tag is as4a241784 Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3e3d1ee0;received=192.168.0.200 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 102 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13112 local_attended_transfer: SIP attended transfer: trying to bridge SIP/7706-09975bd8 and Zap/1-1 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12153 attempt_transfer: Sip transfer:-------------------- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12155 attempt_transfer: -- Transferer to PBX channel: SIP/7706-09966a10 State Up [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12159 attempt_transfer: -- Transferer to PBX second channel (target): SIP/7706-09975bd8 State Up [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12163 attempt_transfer: -- Bridged call to transferee: Zap/1-1 State Up [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12167 attempt_transfer: -- Bridged call to transfer target: Local/7710@from-sip-6e45,1 State Up [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12170 attempt_transfer: -- END Sip transfer:-------------------- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12178 attempt_transfer: SIP transfer: Four channels to handle -- Stopped music on hold on Zap/1-1 [Aug 7 08:47:43] DEBUG[18697]: channel.c:2564 set_format: Set channel Zap/1-1 to write format alaw [Aug 7 08:47:43] DEBUG[18697]: channel.c:1837 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12209 attempt_transfer: SIP transfer: trying to masquerade Zap/1-1 into SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18697]: channel.c:2963 ast_channel_masquerade: Planning to masquerade channel Zap/1-1 into the structure of SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18697]: channel.c:2976 ast_channel_masquerade: Done planning to masquerade channel Zap/1-1 into the structure of SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:12214 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:5343 reqprep: Strict routing enforced for session 17cdac1c6923c87f545e28ce52040093@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Reliably Transmitting (no NAT) to 192.168.0.200:5060: NOTIFY sip:7706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK6703d5df;rport From: "07803034440" ;tag=as11762cff To: ;tag=000785993d3d005c5e91208a-75502a05 Contact: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=102 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 OK --- [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #28 [Aug 7 08:47:43] DEBUG[18697]: chan_sip.c:13139 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18715]: chan_zap.c:4918 zt_indicate: Requested indication 17 on channel Zap/1-1 [Aug 7 08:47:43] DEBUG[18721]: channel.c:3091 ast_do_masquerade: Actually Masquerading Zap/1-1(6) into the structure of SIP/7706-09975bd8(6) [Aug 7 08:47:43] DEBUG[18721]: channel.c:3103 ast_do_masquerade: Got clone lock for masquerade on 'Zap/1-1' at 0x9963e70 [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:3436 sip_fixup: SIP Fixup: New owner for dialogue 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200: Zap/1-1 (Old parent: Zap/1-1) [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:3180 sip_hangup: Hangup call Zap/1-1, SIP callid 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200) [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:3188 sip_hangup: update_call_counter(7706) - decrement call limit counter on hangup [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:5343 reqprep: Strict routing enforced for session 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Reliably Transmitting (no NAT) to 192.168.0.200:5060: BYE sip:7706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK25814a81;rport From: ;tag=as4a241784 To: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 Contact: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 7 08:47:43] DEBUG[18721]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #29 [Aug 7 08:47:43] DEBUG[18721]: channel.c:2564 set_format: Set channel Zap/1-1 to write format ulaw [Aug 7 08:47:43] DEBUG[18721]: channel.c:2564 set_format: Set channel Zap/1-1 to read format ulaw [Aug 7 08:47:43] DEBUG[18721]: channel.c:3278 ast_do_masquerade: Putting channel Zap/1-1 in 4/4 formats [Aug 7 08:47:43] DEBUG[18721]: chan_zap.c:3354 zt_fixup: New owner for channel 1 is Zap/1-1 [Aug 7 08:47:43] DEBUG[18721]: chan_zap.c:1353 update_conf: Updated conferencing on 1, with 0 conference users [Aug 7 08:47:43] DEBUG[18721]: chan_zap.c:1353 update_conf: Updated conferencing on 1, with 0 conference users [Aug 7 08:47:43] DEBUG[18721]: channel.c:3313 ast_do_masquerade: Released clone lock on 'SIP/7706-09975bd8' [Aug 7 08:47:43] DEBUG[18721]: channel.c:3323 ast_do_masquerade: Done Masquerading Zap/1-1 (6) [Aug 7 08:47:43] DEBUG[18721]: channel.c:2564 set_format: Set channel Local/7710@from-sip-6e45,1 to read format alaw [Aug 7 08:47:43] DEBUG[18721]: channel.c:2564 set_format: Set channel Zap/1-1 to write format alaw [Aug 7 08:47:43] DEBUG[18715]: channel.c:3499 ast_generic_bridge: Didn't get a frame from channel: SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18715]: channel.c:3793 ast_channel_bridge: Bridge stops bridging channels SIP/7706-09975bd8 and SIP/7706-09966a10 [Aug 7 08:47:43] DEBUG[18715]: channel.c:1537 ast_hangup: Hanging up channel 'SIP/7706-09966a10' [Aug 7 08:47:43] DEBUG[18715]: chan_sip.c:3166 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 17cdac1c6923c87f545e28ce52040093@90.0.0.62. Scheduling destruction of SIP dialog '17cdac1c6923c87f545e28ce52040093@90.0.0.62' in 32000 ms (Method: REFER) [Aug 7 08:47:43] DEBUG[18715]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09966a10 [Aug 7 08:47:43] DEBUG[18715]: rtp.c:1317 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Aug 7 08:47:43] DEBUG[18715]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 7 08:47:43] DEBUG[18715]: pbx.c:2271 __ast_pbx_run: Spawn extension (common,7706,2) exited non-zero on 'SIP/7706-09975bd8' [Aug 7 08:47:43] DEBUG[18715]: channel.c:1542 ast_hangup: Hanging up zombie 'SIP/7706-09975bd8' [Aug 7 08:47:43] DEBUG[18715]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-09975bd8 [Aug 7 08:47:43] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:43] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:43] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:43] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7706 [Aug 7 08:47:43] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7706 [Aug 7 08:47:43] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) [Aug 7 08:47:43] DEBUG[18730]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:43] DEBUG[18731]: app_queue.c:536 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <-- SIP read from 192.168.0.200:52649: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK6703d5df;rport From: "07803034440" ;tag=as11762cff To: ;tag=000785993d3d005c5e91208a-75502a05 Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 NOTIFY Content-Length: 0 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK6703d5df;rport (60) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: "07803034440" ;tag=as11762cff (62) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=000785993d3d005c5e91208a-75502a05 (71) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 103 NOTIFY (16) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Content-Length: 0 (17) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: (0) --- (7 headers 0 lines)--- [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #28 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '17cdac1c6923c87f545e28ce52040093@90.0.0.62' of Request 103: Match Not Found Really destroying SIP dialog '17cdac1c6923c87f545e28ce52040093@90.0.0.62' Method: REFER <-- SIP read from 192.168.0.200:52464: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK25814a81;rport From: ;tag=as4a241784 To: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 CSeq: 102 BYE Server: CSCO/7 Content-Length: 0 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK25814a81;rport (60) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=as4a241784 (41) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "foxtrot" ;tag=000785993d3d005d1a59380b-60c9cdb5 (72) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200 (58) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 102 BYE (13) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: Server: CSCO/7 (14) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Content-Length: 0 (17) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #29 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '00078599-3d3d0043-6d56da5e-535eae96@192.168.0.200' Method: ACK foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 BYE User-Agent: CSCO/7 Content-Length: 0 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 (42) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4 (58) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=000785993d3d005c5e91208a-75502a05 (73) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "07803034440" ;tag=as11762cff (60) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 103 BYE (13) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Content-Length: 0 (17) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for 17cdac1c6923c87f545e28ce52040093@90.0.0.62 - BYE (No RTP) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.0.200 : 5060 (no NAT) Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4;received=192.168.0.200 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- Really destroying SIP dialog '17cdac1c6923c87f545e28ce52040093@90.0.0.62' Method: BYE foxtrot*CLI> <-- SIP read from 192.168.0.200:52464: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 BYE User-Agent: CSCO/7 Content-Length: 0 [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 (42) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4 (58) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: From: ;tag=000785993d3d005c5e91208a-75502a05 (73) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: "07803034440" ;tag=as11762cff (60) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 (51) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: CSeq: 103 BYE (13) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: User-Agent: CSCO/7 (18) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: Content-Length: 0 (17) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:4112 sip_alloc: Allocating new SIP dialog for 17cdac1c6923c87f545e28ce52040093@90.0.0.62 - BYE (No RTP) [Aug 7 08:47:44] DEBUG[18697]: chan_sip.c:13989 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.0.200 : 5060 (no NAT) Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4c22b3a4;received=192.168.0.200 From: ;tag=000785993d3d005c5e91208a-75502a05 To: "07803034440" ;tag=as11762cff Call-ID: 17cdac1c6923c87f545e28ce52040093@90.0.0.62 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- Really destroying SIP dialog '17cdac1c6923c87f545e28ce52040093@90.0.0.62' Method: BYE [Aug 7 08:47:45] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:48] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:51] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:54] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes [Aug 7 08:47:57] DEBUG[18725]: rtp.c:778 ast_rtcp_read: Got RTCP report of 176 bytes -- Channel 0/1, span 1 got hangup request [Aug 7 08:47:59] DEBUG[18721]: channel.c:3499 ast_generic_bridge: Didn't get a frame from channel: Zap/1-1 [Aug 7 08:47:59] DEBUG[18721]: channel.c:3793 ast_channel_bridge: Bridge stops bridging channels Zap/1-1 and Local/7710@from-sip-6e45,1 [Aug 7 08:47:59] DEBUG[18721]: channel.c:1537 ast_hangup: Hanging up channel 'Local/7710@from-sip-6e45,1' [Aug 7 08:47:59] DEBUG[18721]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/7710@from-sip-6e45,1 [Aug 7 08:47:59] DEBUG[18721]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Aug 7 08:47:59] DEBUG[18721]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 7 08:47:59] DEBUG[18721]: pbx.c:2271 __ast_pbx_run: Spawn extension (from-sip,7709,2) exited non-zero on 'Zap/1-1' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("Zap/1-1", "++++ HANGUP FROM-SIP ++++ [ANSWER/16]") in new stack [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@from-sip:2] GotoIf("Zap/1-1", "1?end") in new stack -- Goto (from-sip,h,6) [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Zap/1-1", "EndOfCall") in new stack [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '07803034440' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '07803034440' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'h' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'SIP/7706-09975bd8' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'Local/7710@from-sip-6e45,1' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:26' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:26' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:59' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '33' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '33' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154936846.2' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Aug 7 08:47:59] DEBUG[18725]: channel.c:3499 ast_generic_bridge: Didn't get a frame from channel: Local/7710@from-sip-6e45,2 [Aug 7 08:47:59] DEBUG[18725]: channel.c:3793 ast_channel_bridge: Bridge stops bridging channels Local/7710@from-sip-6e45,2 and SIP/7710-0997f900 -- Stopped music on hold on SIP/7710-0997f900 [Aug 7 08:47:59] DEBUG[18725]: channel.c:1537 ast_hangup: Hanging up channel 'SIP/7710-0997f900' [Aug 7 08:47:59] DEBUG[18725]: chan_sip.c:3180 sip_hangup: Hangup call SIP/7710-0997f900, SIP callid 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62) [Aug 7 08:47:59] DEBUG[18725]: chan_sip.c:3188 sip_hangup: update_call_counter(7710) - decrement call limit counter on hangup [Aug 7 08:47:59] DEBUG[18725]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 7 08:47:59] DEBUG[18725]: chan_sip.c:5343 reqprep: Strict routing enforced for session 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.12, port 54978 Reliably Transmitting (no NAT) to 192.168.0.12:54978: BYE sip:7710@192.168.0.12:54978;rinstance=301ef85bba12dd44 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK03ce835d;rport From: "7706" ;tag=as72564a0f To: ;tag=316aba05 Contact: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 7 08:47:59] DEBUG[18725]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #31 [Aug 7 08:47:59] DEBUG[18725]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7710-0997f900 [Aug 7 08:47:59] DEBUG[18725]: rtp.c:1309 ast_rtp_early_bridge: Channel 'Local/7710@from-sip-6e45,2' has no RTP, not doing anything [Aug 7 08:47:59] DEBUG[18725]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 7 08:47:59] DEBUG[18725]: pbx.c:2271 __ast_pbx_run: Spawn extension (from-sip,7710,2) exited non-zero on 'Local/7710@from-sip-6e45,2' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("Local/7710@from-sip-6e45,2", "++++ HANGUP FROM-SIP ++++ [ANSWER/16]") in new stack [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@from-sip:2] GotoIf("Local/7710@from-sip-6e45,2", "1?end") in new stack -- Goto (from-sip,h,6) [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Local/7710@from-sip-6e45,2", "EndOfCall") in new stack [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 7710@from-sip [Aug 7 08:47:59] DEBUG[18686]: chan_local.c:140 local_devicestate: Checking if extension 7710@from-sip exists (devicestate) [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:885 channel_find_locked: Avoiding initial deadlock for channel '0x997eca0' [Aug 7 08:47:59] DEBUG[18686]: channel.c:895 channel_find_locked: Failure, could not lock '0x997eca0' after 10 retries! [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Local/7710@from-sip - state 1 (Not in use) [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7710 [Aug 7 08:47:59] DEBUG[18686]: chan_sip.c:14573 sip_devicestate: Checking device state for peer 7710 [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for SIP/7710 - state 1 (Not in use) [Aug 7 08:47:59] DEBUG[18732]: app_queue.c:536 changethread: Device 'Local/7710@from-sip' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 7 08:47:59] DEBUG[18733]: app_queue.c:536 changethread: Device 'SIP/7710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. > cdr_odbc: Query Successful! [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '07803034440' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '07803034440' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'h' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'Zap/1-1' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'SIP/7706-09966a10' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:12' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:12' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:59' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '47' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '47' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154936832.0' [Aug 7 08:47:59] DEBUG[18721]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' > cdr_odbc: Query Successful! [Aug 7 08:47:59] DEBUG[18721]: channel.c:1537 ast_hangup: Hanging up channel 'Zap/1-1' [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2342 zt_hangup: zt_hangup(Zap/1-1) [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2886 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1 [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2375 zt_hangup: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1 [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2529 zt_hangup: Not yet hungup... Calling hangup once with icause, and clearing call [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:1416 zt_disable_ec: disabled echo cancellation on channel 1 [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2803 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:1353 update_conf: Updated conferencing on 1, with 0 conference users [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:2882 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1 [Aug 7 08:47:59] DEBUG[18721]: chan_zap.c:1416 zt_disable_ec: disabled echo cancellation on channel 1 -- Hungup 'Zap/1-1' [Aug 7 08:47:59] DEBUG[18721]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '"7706" ' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'Extension7706' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'h' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'Local/7710@from-sip-6e45,2' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'SIP/7710-0997f900' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:26' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:26' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '2006-08-07 08:47:59' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '33' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '33' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154936846.4' [Aug 7 08:47:59] DEBUG[18725]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '' [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown) [Aug 7 08:47:59] DEBUG[18734]: app_queue.c:536 changethread: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. > cdr_odbc: Query Successful! [Aug 7 08:47:59] DEBUG[18725]: channel.c:1537 ast_hangup: Hanging up channel 'Local/7710@from-sip-6e45,2' [Aug 7 08:47:59] DEBUG[18725]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/7710@from-sip-6e45,2 [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 7710@from-sip [Aug 7 08:47:59] DEBUG[18686]: chan_local.c:140 local_devicestate: Checking if extension 7710@from-sip exists (devicestate) [Aug 7 08:47:59] DEBUG[18686]: devicestate.c:287 do_state_change: Changing state for Local/7710@from-sip - state 1 (Not in use) [Aug 7 08:47:59] DEBUG[18735]: app_queue.c:536 changethread: Device 'Local/7710@from-sip' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <-- SIP read from 192.168.0.12:54978: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK03ce835d;rport=5060 Contact: To: ;tag=316aba05 From: "7706";tag=as72564a0f Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 CSeq: 103 BYE User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 0 [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK03ce835d;rport=5060 (65) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 2: Contact: (65) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 3: To: ;tag=316aba05 (73) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 4: From: "7706";tag=as72564a0f (56) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 5: Call-ID: 600bcc6f6ac629a12f07e13e420bf602@90.0.0.62 (51) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 6: CSeq: 103 BYE (13) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 7: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 8: Content-Length: 0 (17) [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #31 [Aug 7 08:48:00] DEBUG[18697]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '600bcc6f6ac629a12f07e13e420bf602@90.0.0.62' of Request 103: Match Not Found Really destroying SIP dialog '600bcc6f6ac629a12f07e13e420bf602@90.0.0.62' Method: INVITE foxtrot*CLI> <-- SIP read from 192.168.0.12:54978: [Aug 7 08:48:02] DEBUG[18697]: chan_sip.c:4332 parse_request: Header 0: (0) [Aug 7 08:48:02] DEBUG[18697]: chan_sip.c:4364 parse_request: Line: (0) --- (0 headers 1 lines)--- foxtrot*CLI>