-- Executing [s@macro-dial:7] Dial("SIP/1000-00000001", "SIP/2000&SIP/1050,15,trTwW") in new stack [May 12 21:39:09] DEBUG[15358]: chan_sip.c:25362 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:7384 sip_alloc: Allocating new SIP dialog for 255b2eb3106d64cb7e48f42d2e71d025@voip.mydomain.com - INVITE (No RTP) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:25470 sip_request_call: Cant create SIP call - target device not registered [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5764 sip_destroy: Destroying SIP dialog 255b2eb3106d64cb7e48f42d2e71d025@voip.mydomain.com Really destroying SIP dialog '255b2eb3106d64cb7e48f42d2e71d025@voip.mydomain.com' Method: INVITE [May 12 21:39:09] WARNING[15358]: app_dial.c:2041 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Unknown) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:25362 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:7384 sip_alloc: Allocating new SIP dialog for 16332ea260251f627f82adf514b27cc3@voip.mydomain.com - INVITE (No RTP) [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xb0b52598' [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 10022 for RTP instance '0xb0b52598' [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0xb0b52598' is setup and ready to go [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0xb0b52598' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:4845 do_setnat: Setting NAT on RTP to On [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3055 obproxy_get: OBPROXY: Not applying OBproxy to this call [May 12 21:39:09] DEBUG[15358]: acl.c:725 ast_ouraddrfor: For destination '10.10.1.149', our source address is '10.10.1.17'. [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3404 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.1.17:5060 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6723 sip_new: *** Our native formats are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6724 sip_new: *** Joint capabilities are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6725 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6726 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6728 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6756 sip_new: This channel will not be able to handle video. [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:1446 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'SIP/1050-00000002' with that of 'SIP/1000-00000001' [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AGISTATUS. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ds. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [May 12 21:39:09] DEBUG[15358]: channel.c:5914 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG3. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG2. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG1. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DB_RESULT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable RT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable CFBEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable CFUEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable EXTTOCALL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable VMBOX. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [May 12 21:39:09] DEBUG[15358]: channel.c:5914 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSERCID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSER. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPURI. [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5374 sip_call: Outgoing Call for 1050 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5616 update_call_counter: Updating call counter for outgoing call [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5721 update_call_counter: Call to peer '1050' is 1 out of 50 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10824 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10825 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 5060 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10934 add_sdp: -- Done with adding codecs to SDP [May 12 21:39:09] DEBUG[15358]: chan_sip.c:11073 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [May 12 21:39:09] DEBUG[15317]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 1050 [May 12 21:39:09] DEBUG[15317]: chan_sip.c:25260 sip_devicestate: Checking device state for peer 1050 [May 12 21:39:09] DEBUG[15317]: devicestate.c:458 do_state_change: Changing state for SIP/1050 - state 6 (Ringing) [May 12 21:39:09] DEBUG[15317]: devicestate.c:438 devstate_event: device 'SIP/1050' state '6' [May 12 21:39:09] DEBUG[15358]: chan_sip.c:2984 initialize_initreq: Initializing initreq for method INVITE - callid 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 0 [ 40]: INVITE sip:1050@10.10.1.149:5061 SIP/2.0 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 1 [ 61]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 3 [ 67]: From: "User 1" ;tag=as07221eae [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 4 [ 31]: To: [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 5 [ 35]: Contact: [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 6 [ 64]: Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 8 [ 29]: User-Agent: FPBX-2.7.0(1.8.4) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 9 [ 35]: Date: Fri, 13 May 2011 01:39:09 GMT [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 11 [ 26]: Supported: replaces, timer [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 12 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 10.10.1.149:5061: INVITE sip:1050@10.10.1.149:5061 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport Max-Forwards: 70 From: "User 1" ;tag=as07221eae To: Contact: Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com CSeq: 102 INVITE User-Agent: FPBX-2.7.0(1.8.4) Date: Fri, 13 May 2011 01:39:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 252 v=0 o=root 489611281 489611281 IN IP4 10.10.1.17 s=Asterisk PBX 1.8.4 c=IN IP4 10.10.1.17 t=0 0 m=audio 10022 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=ptime:20 a=sendrecv --- [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3706 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #110 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3250 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.10.1.149:5061 [May 12 21:39:09] DEBUG[15310]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x84291e8) called (obj->txf = (nil)) -- Called 1050 <--- Transmitting (NAT) to 10.10.1.143:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.1.143:5060;branch=z9hG4bK-6870a3a7;received=10.10.1.143;rport=5060 From: ;tag=e34e4d71fc1cdb6bo0 To: ;tag=as31b475ac Call-ID: 13fe4269-8648aad3@10.10.1.143 CSeq: 102 INVITE Server: FPBX-2.7.0(1.8.4) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Remote-Party-ID: "User 2" ;party=called;id-type=subscriber;screen=yes;privacy=off Content-Length: 0 <------------> [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3250 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.10.1.143:5060 [May 12 21:39:09] DEBUG[15310]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x84291e8) called (obj->txf = (nil)) [May 12 21:39:09] DEBUG[15318]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 2000 [May 12 21:39:09] DEBUG[15318]: chan_sip.c:25260 sip_devicestate: Checking device state for peer 2000 [May 12 21:39:09] DEBUG[15318]: app_queue.c:1586 extension_state_cb: Extension '2000@ext-local' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 12 21:39:09] DEBUG[15348]: app_queue.c:1491 handle_statechange: Device 'SIP/1050' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. <--- SIP read from UDP:10.10.1.149:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport From: "User 1" ;tag=as07221eae To: "User 2" ;tag=F87BC97A-2C37C297 CSeq: 102 INVITE Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com Contact: User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.3.1.0769 Accept-Language: en Content-Length: 0 <-------------> [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 1 [ 61]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 2 [ 67]: From: "User 1" ;tag=as07221eae [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 3 [ 68]: To: "User 2" ;tag=F87BC97A-2C37C297 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 5 [ 64]: Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 6 [ 36]: Contact: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.3.1.0769 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 8 [ 19]: Accept-Language: en [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3976 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #110 - INVITE (got response) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3983 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com' Request 102: Found [May 12 21:39:09] DEBUG[15339]: chan_sip.c:19076 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP:10.10.1.149:5061 ---> SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport From: "User 1" ;tag=as07221eae To: "User 2" ;tag=F87BC97A-2C37C297 CSeq: 102 INVITE Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com Contact: User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.3.1.0769 Accept-Language: en Diversion: "User 2" ;reason=deflection Content-Length: 0 <-------------> [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 0 [ 29]: SIP/2.0 302 Moved Temporarily [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 1 [ 61]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 2 [ 67]: From: "User 1" ;tag=as07221eae [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 3 [ 68]: To: "User 2" ;tag=F87BC97A-2C37C297 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 5 [ 64]: Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 6 [ 47]: Contact: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_550-UA/3.3.1.0769 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 8 [ 19]: Accept-Language: en [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 9 [ 71]: Diversion: "User 2" ;reason=deflection [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3904 __sip_ack: Acked pending invite 102 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3942 __sip_ack: Stopping retransmission on '7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com' of Request 102: Match Found -- Got SIP response 302 "Moved Temporarily" back from 10.10.1.149:5061 [May 12 21:39:09] DEBUG[15339]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb0b52598' RDNIS for this call is 1050 (reason deflection) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:18823 parse_moved_contact: Found promiscuous redirection to 'SIP/2002::::UDP@voip.mydomain.com:5060' [May 12 21:39:09] DEBUG[15339]: chan_sip.c:18730 change_redirecting_information: Got redirecting from number 1050 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:18737 change_redirecting_information: Got redirecting from name User 2 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:18750 change_redirecting_information: Got redirecting to number 2002 Transmitting (NAT) to 10.10.1.149:5061: ACK sip:1050@10.10.1.149:5061 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK49febc7a;rport Max-Forwards: 70 From: "User 1" ;tag=as07221eae To: ;tag=F87BC97A-2C37C297 Contact: Call-ID: 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com CSeq: 102 ACK User-Agent: FPBX-2.7.0(1.8.4) Content-Length: 0 --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3250 __sip_xmit: Trying to put 'ACK sip:105' onto UDP socket destined for 10.10.1.149:5061 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:2997 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com -- Now forwarding SIP/1000-00000001 to 'SIP/2002::::UDP@voip.mydomain.com:5060' (thanks to SIP/1050-00000002) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:25362 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:7384 sip_alloc: Allocating new SIP dialog for 3a410f4c32fe87af512dc3c275c368af@voip.mydomain.com - INVITE (No RTP) [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:344 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x85eaa68' [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:472 ast_rtp_new: Allocated port 10118 for RTP instance '0x85eaa68' [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:353 ast_rtp_instance_new: RTP instance '0x85eaa68' is setup and ready to go [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:2370 ast_rtp_prop_set: Setup RTCP on RTP instance '0x85eaa68' == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:4845 do_setnat: Setting NAT on RTP to Off [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3055 obproxy_get: OBPROXY: Not applying OBproxy to this call [May 12 21:39:09] DEBUG[15358]: acl.c:725 ast_ouraddrfor: For destination '10.10.1.17', our source address is '10.10.1.17'. [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3404 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.1.17:5060 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6723 sip_new: *** Our native formats are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6724 sip_new: *** Joint capabilities are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6725 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6726 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6728 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6756 sip_new: This channel will not be able to handle video. [May 12 21:39:09] DEBUG[15358]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [May 12 21:39:09] DEBUG[15358]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ~HASH~SIP_CAUSE~SIP/1050-00000002~. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AGISTATUS. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ds. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable FILTERED_DIAL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DIALSTATUS_CW. [May 12 21:39:09] DEBUG[15358]: channel.c:5914 ast_channel_inherit_variables: Copying hard-transferable variable KEEPCID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG3. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG2. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable ARG1. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [May 12 21:39:09] DEBUG[15310]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x84291e8) called (obj->txf = (nil)) [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable DB_RESULT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable RT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable CFBEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable CFUEXT. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable EXTTOCALL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable VMBOX. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable RingGroupMethod. [May 12 21:39:09] DEBUG[15358]: channel.c:5914 ast_channel_inherit_variables: Copying hard-transferable variable TTL. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSERCID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable AMPUSER. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 12 21:39:09] DEBUG[15358]: channel.c:5918 ast_channel_inherit_variables: Not copying variable SIPURI. [May 12 21:39:09] NOTICE[15358]: app_dial.c:844 do_forward: Not accepting call completion offers from call-forward recipient SIP/voip.mydomain.com:5060-00000003 [May 12 21:39:09] DEBUG[15358]: rtp_engine.c:1446 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'SIP/voip.mydomain.com:5060-00000003' with that of 'SIP/1000-00000001' <--- Transmitting (NAT) to 10.10.1.143:5060 ---> SIP/2.0 181 Call is being forwarded Via: SIP/2.0/UDP 10.10.1.143:5060;branch=z9hG4bK-6870a3a7;received=10.10.1.143;rport=5060 From: ;tag=e34e4d71fc1cdb6bo0 To: ;tag=as31b475ac Call-ID: 13fe4269-8648aad3@10.10.1.143 CSeq: 102 INVITE Server: FPBX-2.7.0(1.8.4) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Diversion: "User 2" ;reason=deflection Content-Length: 0 <------------> [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3250 __sip_xmit: Trying to put 'SIP/2.0 181' onto UDP socket destined for 10.10.1.143:5060 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5374 sip_call: Outgoing Call for 2002 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5616 update_call_counter: Updating call counter for outgoing call [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10824 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10825 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 5060 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 12 21:39:09] DEBUG[15358]: chan_sip.c:10934 add_sdp: -- Done with adding codecs to SDP [May 12 21:39:09] DEBUG[15358]: chan_sip.c:11073 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:2984 initialize_initreq: Initializing initreq for method INVITE - callid 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 0 [ 51]: INVITE sip:2002@voip.mydomain.com:5060 SIP/2.0 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 1 [ 55]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 3 [ 67]: From: "User 1" ;tag=as5861daf6 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 4 [ 42]: To: [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 5 [ 35]: Contact: [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 6 [ 64]: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 8 [ 29]: User-Agent: FPBX-2.7.0(1.8.4) [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 9 [ 35]: Date: Fri, 13 May 2011 01:39:09 GMT [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 11 [ 26]: Supported: replaces, timer [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 12 [ 65]: Diversion: "User 2" ;reason=deflection [May 12 21:39:09] DEBUG[15358]: chan_sip.c:8049 parse_request: Header 13 [ 29]: Content-Type: application/sdp Reliably Transmitting (no NAT) to 10.10.1.17:5060: INVITE sip:2002@voip.mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e Max-Forwards: 70 rom: "User 1" ;tag=as5861daf6 To: Contact: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 INVITE User-Agent: FPBX-2.7.0(1.8.4) Date: Fri, 13 May 2011 01:39:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Diversion: "User 2" ;reason=deflection Content-Type: application/sdp Content-Length: 252 v=0 o=root 761089980 761089980 IN IP4 10.10.1.17 s=Asterisk PBX 1.8.4 c=IN IP4 10.10.1.17 t=0 0 m=audio 10118 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=ptime:20 a=sendrecv --- [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3706 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #112 [May 12 21:39:09] DEBUG[15358]: chan_sip.c:3250 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 10.10.1.17:5060 <--- SIP read from UDP:10.10.1.17:5060 ---> INVITE sip:2002@voip.mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e Max-Forwards: 70 From: "User 1" ;tag=as5861daf6 To: Contact: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 INVITE User-Agent: FPBX-2.7.0(1.8.4) Date: Fri, 13 May 2011 01:39:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Diversion: "User 2" ;reason=deflection Content-Type: application/sdp Content-Length: 252 v=0 o=root 761089980 761089980 IN IP4 10.10.1.17 s=Asterisk PBX 1.8.4 c=IN IP4 10.10.1.17 t=0 0 m=audio 10118 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=ptime:20 a=sendrecv <-------------> [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 0 [ 51]: INVITE sip:2002@voip.mydomain.com:5060 SIP/2.0 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 1 [ 55]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 3 [ 67]: From: "User 1" ;tag=as5861daf6 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 4 [ 42]: To: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 5 [ 35]: Contact: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 6 [ 64]: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 8 [ 29]: User-Agent: FPBX-2.7.0(1.8.4) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 9 [ 35]: Date: Fri, 13 May 2011 01:39:09 GMT [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 11 [ 26]: Supported: replaces, timer [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 12 [ 65]: Diversion: "User 2" ;reason=deflection [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 13 [ 29]: Content-Type: application/sdp [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 14 [ 19]: Content-Length: 252 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 15 [ 0]: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 0 [ 3]: v=0 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 1 [ 44]: o=root 761089980 761089980 IN IP4 10.10.1.17 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 2 [ 20]: s=Asterisk PBX 1.8.4 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 3 [ 19]: c=IN IP4 10.10.1.17 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 4 [ 5]: t=0 0 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 5 [ 29]: m=audio 10118 RTP/AVP 0 8 101 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 9 [ 15]: a=fmtp:101 0-16 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Body 10 [ 10]: a=ptime:20 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8086 parse_request: Body 11 [ 10]: a=sendrecv --- (15 headers 12 lines) --- [May 12 21:39:09] DEBUG[15358]: channel.c:2758 ast_hangup: Hanging up channel 'SIP/1050-00000002' [May 12 21:39:09] DEBUG[15339]: acl.c:725 ast_ouraddrfor: For destination '10.10.1.17', our source address is '10.10.1.17'. [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5989 sip_hangup: Hangup call SIP/1050-00000002, SIP callid 7d6c70502f2701f127c0edf209fe082c@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3404 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.1.17:5060 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:7384 sip_alloc: Allocating new SIP dialog for 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com - INVITE (No RTP) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:23935 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 12 21:39:09] DEBUG[15339]: sip/reqresp_parser.c:1584 parse_sip_options: Begin: parsing SIP "Supported: replaces, timer" [May 12 21:39:09] DEBUG[15339]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -replaces- [May 12 21:39:09] DEBUG[15339]: sip/reqresp_parser.c:1608 parse_sip_options: Matched SIP option: replaces [May 12 21:39:09] DEBUG[15339]: sip/reqresp_parser.c:1600 parse_sip_options: Found SIP option: -timer- [May 12 21:39:09] DEBUG[15339]: sip/reqresp_parser.c:1608 parse_sip_options: Matched SIP option: timer Sending to 10.10.1.17:5060 (no NAT) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:21454 handle_request_invite: Initializing initreq for method INVITE - callid 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com Using INVITE request as basis request - 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com Found peer '2028' for '2028' from 10.10.1.17:5060 <--- Reliably Transmitting (NAT) to 10.10.1.17:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e;received=10.10.1.17;rport=5060 From: "User 1" ;tag=as5861daf6 To: ;tag=as380320f7 Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 INVITE Server: FPBX-2.7.0(1.8.4) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="56fd80c0" Content-Length: 0 <------------> [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5994 sip_hangup: update_call_counter(1050) - decrement call limit counter on hangup [May 12 21:39:09] DEBUG[15310]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x84291e8) called (obj->txf = (nil)) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3706 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #114 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3250 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.10.1.17:5060 Scheduling destruction of SIP dialog '0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com' in 32000 ms (Method: INVITE) <--- SIP read from UDP:10.10.1.17:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e;received=10.10.1.17;rport=5060 From: "User 1" ;tag=as5861daf6 To: ;tag=as380320f7 Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 INVITE Server: FPBX-2.7.0(1.8.4) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="56fd80c0" Content-Length: 0 <-------------> [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 1 [ 86]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e;received=10.10.1.17;rport=5060 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 2 [ 67]: From: "User 1" ;tag=as5861daf6 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 3 [ 57]: To: ;tag=as380320f7 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 4 [ 64]: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 6 [ 25]: Server: FPBX-2.7.0(1.8.4) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 7 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 8 [ 26]: Supported: replaces, timer [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 9 [ 74]: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="56fd80c0" [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3904 __sip_ack: Acked pending invite 102 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3909 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #112 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3942 __sip_ack: Stopping retransmission on '0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com' of Request 102: Match Found [May 12 21:39:09] DEBUG[15339]: chan_sip.c:19076 handle_response_invite: SIP response 401 to standard invite Transmitting (no NAT) to 10.10.1.17:5060: ACK sip:2002@voip.mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e Max-Forwards: 70 From: "User 1" ;tag=as5861daf6 To: ;tag=as380320f7 Contact: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 ACK User-Agent: FPBX-2.7.0(1.8.4) Content-Length: 0 --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3250 __sip_xmit: Trying to put 'ACK sip:200' onto UDP socket destined for 10.10.1.17:5060 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:18285 do_proxy_auth: Auth attempt 1 on INVITE [May 12 21:39:09] NOTICE[15339]: chan_sip.c:19355 handle_response_invite: Failed to authenticate on INVITE to '"User 1" ;tag=as5861daf6' [May 12 21:39:09] DEBUG[15339]: chan_sip.c:2997 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com <--- SIP read from UDP:10.10.1.17:5060 ---> ACK sip:2002@voip.mydomain.com:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e Max-Forwards: 70 From: "User 1" ;tag=as5861daf6 To: ;tag=as380320f7 Contact: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com CSeq: 102 ACK User-Agent: FPBX-2.7.0(1.8.4) Content-Length: 0 <-------------> [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 0 [ 48]: ACK sip:2002@voip.mydomain.com:5060 SIP/2.0 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 1 [ 55]: Via: SIP/2.0/UDP 10.10.1.17:5060;branch=z9hG4bK6a96681e [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 2 [ 16]: Max-Forwards: 70 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 3 [ 67]: From: "User 1" ;tag=as5861daf6 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 4 [ 57]: To: ;tag=as380320f7 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 5 [ 35]: Contact: [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 6 [ 64]: Call-ID: 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 7 [ 13]: CSeq: 102 ACK [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 8 [ 29]: User-Agent: FPBX-2.7.0(1.8.4) [May 12 21:39:09] DEBUG[15339]: chan_sip.c:8049 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [May 12 21:39:09] DEBUG[15339]: chan_sip.c:23935 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3909 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #114 [May 12 21:39:09] DEBUG[15339]: chan_sip.c:3942 __sip_ack: Stopping retransmission on '0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com' of Response 102: Match Found [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5616 update_call_counter: Updating call counter for outgoing call [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5687 update_call_counter: Call to peer '1050' removed from call limit 50 [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb0b52598' -- SIP/voip.mydomain.com:5060-00000003 is circuit-busy [May 12 21:39:09] DEBUG[15317]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 1050 [May 12 21:39:09] DEBUG[15358]: channel.c:2758 ast_hangup: Hanging up channel 'SIP/voip.mydomain.com:5060-00000003' [May 12 21:39:09] DEBUG[15358]: chan_sip.c:5989 sip_hangup: Hangup call SIP/voip.mydomain.com:5060-00000003, SIP callid 0d6c809244e28bc81cf48ffd3cda5b1f@voip.mydomain.com [May 12 21:39:09] DEBUG[15358]: chan_sip.c:6008 sip_hangup: Hanging up channel in state Down (not UP) [May 12 21:39:09] DEBUG[15317]: chan_sip.c:25260 sip_devicestate: Checking device state for peer 1050 [May 12 21:39:09] DEBUG[15358]: res_rtp_asterisk.c:2391 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x85eaa68' [May 12 21:39:09] DEBUG[15317]: devicestate.c:458 do_state_change: Changing state for SIP/1050 - state 1 (Not in use) [May 12 21:39:09] DEBUG[15310]: res_odbc.c:1034 odbc_release_obj2: odbc_release_obj2(0x84291e8) called (obj->txf = (nil)) [May 12 21:39:09] DEBUG[15317]: devicestate.c:438 devstate_event: device 'SIP/1050' state '1' [May 12 21:39:09] DEBUG[15317]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 1050 [May 12 21:39:09] DEBUG[15317]: chan_sip.c:25260 sip_devicestate: Checking device state for peer 1050 [May 12 21:39:09] DEBUG[15317]: devicestate.c:458 do_state_change: Changing state for SIP/1050 - state 1 (Not in use) [May 12 21:39:09] DEBUG[15317]: devicestate.c:438 devstate_event: device 'SIP/1050' state '1' == Everyone is busy/congested at this time (2:0/1/1) [May 12 21:39:09] DEBUG[15358]: app_dial.c:2725 dial_exec_full: Exiting with DIALSTATUS=CONGESTION.