<--- SIP read from UDP:192.168.17.141:5060 ---> INVITE sip:1203mobilep@mydomain.org;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK224b649abbedede063905072b7e799a5;rport From: "Cordless 1" ;tag=956840114 To: Call-ID: 4161371945@192_168_17_141 CSeq: 2 INVITE Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Supported: replaces Allow-Events: message-summary, refer, ua-profile Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 384 v=0 o=111 5014 19 IN IP4 192.168.17.141 s=Mapping c=IN IP4 192.168.17.141 t=0 0 m=audio 5014 RTP/AVP 9 0 8 96 97 2 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 G726-32/8000 a=rtpmap:97 AAL2-G726-32/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 56]: INVITE sip:1203mobilep@mydomain.org;user=phone SIP/2.0 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK224b649abbedede063905072b7e799a5;rport [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 1" ;tag=956840114 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 47]: To: [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 4161371945@192_168_17_141 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 19]: Supported: replaces [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 48]: Allow-Events: message-summary, refer, ua-profile [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 13 [ 19]: Content-Length: 384 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 14 [ 0]: [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 0 [ 3]: v=0 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 1 [ 35]: o=111 5014 19 IN IP4 192.168.17.141 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 2 [ 9]: s=Mapping [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 3 [ 23]: c=IN IP4 192.168.17.141 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 4 [ 5]: t=0 0 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 5 [ 41]: m=audio 5014 RTP/AVP 9 0 8 96 97 2 18 101 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 9 [ 24]: a=rtpmap:96 G726-32/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 10 [ 29]: a=rtpmap:97 AAL2-G726-32/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 11 [ 23]: a=rtpmap:2 G726-32/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 12 [ 21]: a=rtpmap:18 G729/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 13 [ 19]: a=fmtp:18 annexb=no [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Body 15 [ 15]: a=fmtp:101 0-16 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8558 parse_request: Body 16 [ 10]: a=ptime:20 --- (14 headers 17 lines) --- [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 4161371945@192_168_17_141 (Checking From) --From tag 956840114 --To-tag [Sep 23 11:49:27] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 4161371945@192_168_17_141 - INVITE (No RTP) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Sep 23 11:49:27] DEBUG[840]: sip/reqresp_parser.c:1550 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Sep 23 11:49:27] DEBUG[840]: sip/reqresp_parser.c:1566 parse_sip_options: Found SIP option: -replaces- [Sep 23 11:49:27] DEBUG[840]: sip/reqresp_parser.c:1574 parse_sip_options: Matched SIP option: replaces [Sep 23 11:49:27] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:27] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:22643 handle_request_invite: Initializing initreq for method INVITE - callid 4161371945@192_168_17_141 Using INVITE request as basis request - 4161371945@192_168_17_141 [Sep 23 11:49:27] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:27] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. Found peer '111' for '111' from 192.168.17.141:5060 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8895400' [Sep 23 11:49:27] DEBUG[840]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 16596 for RTP instance '0x8895400' [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x8895400' is setup and ready to go [Sep 23 11:49:27] DEBUG[840]: res_rtp_asterisk.c:2523 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8895400' == Using SIP RTP CoS mark 5 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:5093 do_setnat: Setting NAT on RTP to On [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP o=111 5014 19 IN IP4 192.168.17.141... UNSUPPORTED OR FAILED. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP s=Mapping... UNSUPPORTED OR FAILED. [Sep 23 11:49:27] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141' into... [Sep 23 11:49:27] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port ''. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP c=IN IP4 192.168.17.141... OK. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 9 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 9 based on m type on 0x41503e70 Found RTP audio format 0 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x41503e70 Found RTP audio format 8 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x41503e70 Found RTP audio format 96 Found RTP audio format 97 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 97 based on m type on 0x41503e70 Found RTP audio format 2 Found RTP audio format 18 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x41503e70 Found RTP audio format 101 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x41503e70 Found audio description format G722 for ID 9 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. Found audio description format PCMU for ID 0 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format PCMA for ID 8 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format G726-32 for ID 96 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:96 G726-32/8000... OK. Found audio description format AAL2-G726-32 for ID 97 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:97 AAL2-G726-32/8000... OK. Found audio description format G726-32 for ID 2 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. Found audio description format G729 for ID 18 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED OR FAILED. Found audio description format telephone-event for ID 101 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 2 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 9 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 96 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 97 on 0x41503e70 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x41503e70 Capabilities: us - 0x1104 (ulaw|g729|g722), peer - audio=0x191c (ulaw|alaw|g726|g729|g726aal2|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x1104 (ulaw|g729|g722) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Sep 23 11:49:27] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8895400' Peer audio RTP is at port 192.168.17.141:5014 [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 2 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 96 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 97 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x41503e70 to 0x88955ac [Sep 23 11:49:27] DEBUG[840]: res_rtp_asterisk.c:2489 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x8895400' [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:9424 process_sdp: We're settling with these formats: 0x1104 (ulaw|g729|g722) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:22780 handle_request_invite: Checking SIP call limits for device 111 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:5905 update_call_counter: Updating call counter for incoming call [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:6010 update_call_counter: Call from peer '111' is 1 out of 10 [Sep 23 11:49:27] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:27] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:27] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:27] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. Looking for 1203mobilep in DialPlanSLA (domain mydomain.org) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7091 sip_new: *** Our native formats are 0x1000 (g722) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7092 sip_new: *** Joint capabilities are 0x1104 (ulaw|g729|g722) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7093 sip_new: *** Our capabilities are 0x1104 (ulaw|g729|g722) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7094 sip_new: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:7124 sip_new: This channel will not be able to handle video. [Sep 23 11:49:27] DEBUG[840]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:49:27] DEBUG[840]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:23081 handle_request_invite: SIP/111-00000006: New call is still down.... Trying... <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK224b649abbedede063905072b7e799a5;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=956840114 To: Call-ID: 4161371945@192_168_17_141 CSeq: 2 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:49:27] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:27] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:27] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:49:27] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:49:27] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:27] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:27] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:49:27] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:49:27] DEBUG[1672]: pbx.c:4247 pbx_extension_helper: Launching 'NoOp' -- Executing [1203mobilep@DialPlanSLA:1] NoOp("SIP/111-00000006", "SLA Dialplan") in new stack [Sep 23 11:49:27] DEBUG[1672]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '1203mobilep' [Sep 23 11:49:27] DEBUG[1672]: pbx.c:4247 pbx_extension_helper: Launching 'Set' -- Executing [1203mobilep@DialPlanSLA:2] Set("SIP/111-00000006", "_SLA_EXTEN=1203mobilep") in new stack [Sep 23 11:49:27] DEBUG[1672]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1672]: pbx.c:4247 pbx_extension_helper: Launching 'SLAStation' -- Executing [1203mobilep@DialPlanSLA:3] SLAStation("SIP/111-00000006", "SLAphone111") in new stack [Sep 23 11:49:27] DEBUG[1672]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '2' [Sep 23 11:49:27] DEBUG[1672]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '2' [Sep 23 11:49:27] DEBUG[1673]: channel.c:6141 ast_channel_inherit_variables: Copying soft-transferable variable SLA_EXTEN. [Sep 23 11:49:27] DEBUG[1673]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Sep 23 11:49:27] DEBUG[1673]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Sep 23 11:49:27] DEBUG[1673]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called s@OutboundSLA [Sep 23 11:49:27] DEBUG[823]: app_queue.c:1585 extension_state_cb: Extension 'SLAphone111_SLAtrunk1@DialPlanSLA' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[823]: app_queue.c:1585 extension_state_cb: Extension 'SLAphone112_SLAtrunk1@DialPlanSLA' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone111_SLAtrunk1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone112_SLAtrunk1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'NoOp' -- Executing [s@OutboundSLA:1] NoOp("Local/s@OutboundSLA-de33;2", "SLA Outbound context") in new stack [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'SLA_EXTEN' is '1203mobilep' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'SLA_EXTEN' is '1203mobilep' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@OutboundSLA:2] GotoIf("Local/s@OutboundSLA-de33;2", "1?1203mobilep,1") in new stack -- Goto (OutboundSLA,1203mobilep,1) [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'vitel-outbound' is 'SIP/vitel-outbound' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '1203mobilep' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'voipcheap' is 'SIP/voipcheap' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '1203mobilep' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Macro' -- Executing [1203mobilep@OutboundSLA:1] Macro("Local/s@OutboundSLA-de33;2", "trunkdial-failover,SIP/vitel-outbound/1203mobilep,SIP/voipcheap/001203mobilep,vitel-outbound,voipcheap") in new stack [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-trunkdial-failover:1] NoOp("Local/s@OutboundSLA-de33;2", "trunk dial by 111") in new stack [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: NoOp [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-trunkdial-failover:2] ExecIf("Local/s@OutboundSLA-de33;2", "1?Set(VOLUME(RX)=10)") in new stack [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: ExecIf [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3842 ast_str_substitute_variables_full: Evaluating 'CALLERID(num)' (from 'CALLERID(num)}"="111"' len 13) [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3876 ast_str_substitute_variables_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3934 ast_str_substitute_variables_full: Expression result is '1' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-trunkdial-failover:3] ExecIf("Local/s@OutboundSLA-de33;2", "0?Set(VOLUME(RX)=10)") in new stack [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: ExecIf [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3842 ast_str_substitute_variables_full: Evaluating 'CALLERID(num)' (from 'CALLERID(num)}"="112"' len 13) [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3876 ast_str_substitute_variables_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3934 ast_str_substitute_variables_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3253 ast_str_retrieve_variable: Result of 'FMCIDNUM' is NULL [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:4] GotoIf("Local/s@OutboundSLA-de33;2", "0?1-fmsetcid,1") in new stack [Sep 23 11:49:27] DEBUG[1674]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'GLOBAL_OUTBOUNDCIDNAME' is '' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:5] GotoIf("Local/s@OutboundSLA-de33;2", "0?1-setgbobname,1") in new stack [Sep 23 11:49:27] DEBUG[1674]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3253 ast_str_retrieve_variable: Result of 'CID_111' is NULL [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3253 ast_str_retrieve_variable: Result of 'CID_111' is NULL [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-trunkdial-failover:6] Set("Local/s@OutboundSLA-de33;2", "CALLERID(num)=111") in new stack [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: Set [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '3' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:7] GotoIf("Local/s@OutboundSLA-de33;2", "0?1-dial,1") in new stack [Sep 23 11:49:27] DEBUG[1674]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG3' is 'vitel-outbound' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'CID_vitel-outbound' is '203homepho' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '10' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG3' is 'vitel-outbound' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'CID_vitel-outbound' is '203homepho' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'GLOBAL_OUTBOUNDCID' is '203homepho' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '203homepho' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-trunkdial-failover:8] Set("Local/s@OutboundSLA-de33;2", "CALLERID(num)=203homepho") in new stack [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: Set [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Goto' -- Executing [s@macro-trunkdial-failover:9] Goto("Local/s@OutboundSLA-de33;2", "1-dial,1") in new stack -- Goto (macro-trunkdial-failover,1-dial,1) [Sep 23 11:49:27] DEBUG[1674]: app_macro.c:435 _macro_exec: Executed application: Goto [Sep 23 11:49:27] DEBUG[1674]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG1' is 'SIP/vitel-outbound/1203mobilep' [Sep 23 11:49:27] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Dial' -- Executing [1-dial@macro-trunkdial-failover:1] Dial("Local/s@OutboundSLA-de33;2", "SIP/vitel-outbound/1203mobilep,,rT") in new stack [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:26659 sip_request_call: Asked to create a SIP channel with formats: 0x1000 (g722) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 52b1f59b50d8f44322c38389380a7ef0@192.168.17.1:5060 - INVITE (No RTP) [Sep 23 11:49:27] DEBUG[1674]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x88b3a28' [Sep 23 11:49:27] DEBUG[1674]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 16516 for RTP instance '0x88b3a28' [Sep 23 11:49:27] DEBUG[1674]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x88b3a28' is setup and ready to go [Sep 23 11:49:27] DEBUG[1674]: res_rtp_asterisk.c:2523 ast_rtp_prop_set: Setup RTCP on RTP instance '0x88b3a28' == Using SIP RTP CoS mark 5 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:5093 do_setnat: Setting NAT on RTP to On [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:3146 obproxy_get: OBPROXY: Not applying OBproxy to this call [Sep 23 11:49:27] DEBUG[1674]: acl.c:736 ast_ouraddrfor: For destination '64.2.142.187', our source address is '24.128.119.26'. [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 24.128.119.26:5060 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7091 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7092 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7093 sip_new: *** Our capabilities are 0x104 (ulaw|g729) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7094 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7096 sip_new: *** Our preferred formats from the incoming channel are 0x1000 (g722) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:7124 sip_new: This channel will not be able to handle video. [Sep 23 11:49:27] DEBUG[1674]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:49:27] DEBUG[1674]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG4. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG3. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG2. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG1. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Sep 23 11:49:27] DEBUG[1674]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SLA_EXTEN. [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:5638 sip_call: Outgoing Call for 1203mobilep [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:6010 update_call_counter: Call to peer 'vitel-outbound' is 1 out of 2147483647 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:11413 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: False Text flag: False [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x1000 (g722) Audio is at 16516 Adding codec 0x4 (ulaw) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:11709 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729) [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method INVITE - callid 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 0 [ 52]: INVITE sip:1203mobilep@outbound.vitelity.net SIP/2.0 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK71ba83ad;rport [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 4 [ 43]: To: [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 5 [ 39]: Contact: [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 6 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:49:27 GMT [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 12 [ 96]: Remote-Party-ID: "Cordless 1" ;party=calling;privacy=off;screen=no [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:8521 parse_request: Header 13 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 64.2.142.187:5060: INVITE sip:1203mobilep@outbound.vitelity.net SIP/2.0 Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK71ba83ad;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as62129ab2 To: Contact: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:49:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Remote-Party-ID: "Cordless 1" ;party=calling;privacy=off;screen=no Content-Type: application/sdp Content-Length: 286 v=0 o=root 1207017261 1207017261 IN IP4 24.128.119.26 s=Asterisk PBX 1.8.15.0 c=IN IP4 24.128.119.26 t=0 0 m=audio 16516 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #196 [Sep 23 11:49:27] DEBUG[1674]: chan_sip.c:3346 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 64.2.142.187:5060 -- Called SIP/vitel-outbound/1203mobilep <--- SIP read from UDP:64.2.142.187:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK71ba83ad;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as127c9587 Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 102 INVITE User-Agent: packetrino Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="46beaeb7" Content-Length: 0 <-------------> [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 41]: SIP/2.0 407 Proxy Authentication Required [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK71ba83ad;received=24.128.119.26;rport=5060 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as127c9587 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 76]: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="46beaeb7" [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 (Checking To) --From tag as62129ab2 --To-tag as127c9587 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3992 __sip_ack: Acked pending invite 102 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #196 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '635106f711855fca44343c30555feaf9@24.128.119.26:5060' of Request 102: Match Found [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 407 to standard invite Transmitting (NAT) to 64.2.142.187:5060: ACK sip:1203mobilep@outbound.vitelity.net SIP/2.0 Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK71ba83ad;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as127c9587 Contact: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 --- [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'ACK sip:120' onto UDP socket destined for 64.2.142.187:5060 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:19239 do_proxy_auth: Auth attempt 1 on INVITE [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:11413 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: False Text flag: False [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x1000 (g722) Audio is at 16516 Adding codec 0x4 (ulaw) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:11709 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729) Reliably Transmitting (NAT) to 64.2.142.187:5060: INVITE sip:1203mobilep@outbound.vitelity.net SIP/2.0 Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as62129ab2 To: Contact: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 103 INVITE User-Agent: Asterisk PBX 1.8.15.0 Proxy-Authorization: Digest username="myuserid", realm="asterisk", algorithm=MD5, uri="sip:1203mobilep@outbound.vitelity.net", nonce="46beaeb7", response="49e658a1dde474bfeb745b4455b2169b" Date: Sun, 23 Sep 2012 15:49:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Remote-Party-ID: "Cordless 1" ;party=calling;privacy=off;screen=no Content-Type: application/sdp Content-Length: 286 v=0 o=root 1207017261 1207017262 IN IP4 24.128.119.26 s=Asterisk PBX 1.8.15.0 c=IN IP4 24.128.119.26 t=0 0 m=audio 16516 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #198 [Sep 23 11:49:27] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 64.2.142.187:5060 [Sep 23 11:49:27] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:27] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:27] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 6 (Ringing) [Sep 23 11:49:27] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '6' [Sep 23 11:49:27] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:49:27] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:49:27] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:49:27] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' -- Local/s@OutboundSLA-de33;1 is ringing <--- SIP read from UDP:64.2.142.187:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as62129ab2 To: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 103 INVITE User-Agent: packetrino Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 43]: To: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 (Checking To) --From tag as62129ab2 --To-tag [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:4064 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #198 - INVITE (got response) [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:4071 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '635106f711855fca44343c30555feaf9@24.128.119.26:5060' Request 103: Found [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 100 to standard invite [Sep 23 11:49:28] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Sep 23 11:49:28] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'Local/s@OutboundSLA' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:192.168.17.141:5060 ---> REGISTER sip:mydomain.org SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK173a50e077ee54bd85109c581abdb4;rport From: "Cordless 2" ;tag=398215349 To: "Cordless 2" Call-ID: 2422681758@192_168_17_141 CSeq: 1739 REGISTER Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Expires: 180 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 35]: REGISTER sip:mydomain.org SIP/2.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK173a50e077ee54bd85109c581abdb4;rport [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 2" ;tag=398215349 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 41]: To: "Cordless 2" [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 2422681758@192_168_17_141 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 19]: CSeq: 1739 REGISTER [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 12]: Expires: 180 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 2422681758@192_168_17_141 (Checking From) --From tag 398215349 --To-tag [Sep 23 11:49:28] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 2422681758@192_168_17_141 - REGISTER (No RTP) [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:25083 handle_request_register: Initializing initreq for method REGISTER - callid 2422681758@192_168_17_141 [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK173a50e077ee54bd85109c581abdb4;received=192.168.17.141;rport=5060 From: "Cordless 2" ;tag=398215349 To: "Cordless 2" ;tag=as117cfa9b Call-ID: 2422681758@192_168_17_141 CSeq: 1739 REGISTER Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="3629a213" Content-Length: 0 <------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.17.141:5060 Scheduling destruction of SIP dialog '2422681758@192_168_17_141' in 32000 ms (Method: REGISTER) <--- SIP read from UDP:192.168.17.141:5060 ---> REGISTER sip:mydomain.org SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK29eeac11a044639ba2b4e7aa71dba7e4;rport From: "Cordless 2" ;tag=398215349 To: "Cordless 2" Call-ID: 2422681758@192_168_17_141 CSeq: 1740 REGISTER Contact: Authorization: Digest username="112", realm="asterisk", algorithm=MD5, uri="sip:mydomain.org", nonce="3629a213", response="4f5b9a8ea977d4ec6f0b73de49e35338" Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Expires: 180 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 35]: REGISTER sip:mydomain.org SIP/2.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK29eeac11a044639ba2b4e7aa71dba7e4;rport [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 2" ;tag=398215349 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 41]: To: "Cordless 2" [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 2422681758@192_168_17_141 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 19]: CSeq: 1740 REGISTER [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [158]: Authorization: Digest username="112", realm="asterisk", algorithm=MD5, uri="sip:mydomain.org", nonce="3629a213", response="4f5b9a8ea977d4ec6f0b73de49e35338" [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 12]: Expires: 180 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 2422681758@192_168_17_141 (Checking From) --From tag 398215349 --To-tag [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:25083 handle_request_register: Initializing initreq for method REGISTER - callid 2422681758@192_168_17_141 [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:28] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:28] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:14154 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 4798a053017f684701e6d5fb64fe478d@192.168.17.1:5060 - OPTIONS (No RTP) [Sep 23 11:49:28] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method OPTIONS - callid 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 43]: OPTIONS sip:112@192.168.17.141:5060 SIP/2.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK277d5369;rport [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as6f011bc2 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:49:28 GMT [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 192.168.17.141:5060: OPTIONS sip:112@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK277d5369;rport Max-Forwards: 70 From: "asterisk" ;tag=as6f011bc2 To: Contact: Call-ID: 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:49:28 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #201 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.17.141:5060 <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK29eeac11a044639ba2b4e7aa71dba7e4;received=192.168.17.141;rport=5060 From: "Cordless 2" ;tag=398215349 To: "Cordless 2" ;tag=as117cfa9b Call-ID: 2422681758@192_168_17_141 CSeq: 1740 REGISTER Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 180 Contact: ;expires=180 Date: Sun, 23 Sep 2012 15:49:28 GMT Content-Length: 0 <------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 573593aa2255b0167b74de2c76c8e6fd@192.168.17.1:5060 - NOTIFY (No RTP) [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3146 obproxy_get: OBPROXY: Not applying OBproxy to this call [Sep 23 11:49:28] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 Scheduling destruction of SIP dialog '34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060' in 6400 ms (Method: NOTIFY) [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method NOTIFY - callid 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 42]: NOTIFY sip:112@192.168.17.141:5060 SIP/2.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as5fb3632e [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: CSeq: 102 NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 22]: Event: message-summary [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 48]: Content-Type: application/simple-message-summary Reliably Transmitting (NAT) to 192.168.17.141:5060: NOTIFY sip:112@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport Max-Forwards: 70 From: "asterisk" ;tag=as5fb3632e To: Contact: Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 1.8.15.0 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@192.168.17.1 Voice-Message: 0/0 (0/0) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #204 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.17.141:5060 Scheduling destruction of SIP dialog '2422681758@192_168_17_141' in 32000 ms (Method: REGISTER) [Sep 23 11:49:28] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 112 [Sep 23 11:49:28] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 112 [Sep 23 11:49:28] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/112 - state 1 (Not in use) [Sep 23 11:49:28] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/112' state '1' <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK277d5369;rport=5060 From: "asterisk" ;tag=as6f011bc2 To: ;tag=ar7g100cb3 Call-ID: 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 CSeq: 102 OPTIONS Supported: replaces User-Agent: C610A IP/42.072.00.000.000 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Accept: application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag Accept-Encoding: identity Accept-Language: en Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK277d5369;rport=5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as6f011bc2 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 48]: To: ;tag=ar7g100cb3 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 19]: Supported: replaces [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 97]: Accept: application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 25]: Accept-Encoding: identity [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 19]: Accept-Language: en [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 (Checking To) --From tag as6f011bc2 --To-tag ar7g100cb3 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #201 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3585 retrans_pkt: SIP TIMER: Rescheduling retransmission #204 (1) NOTIFY - 4 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3605 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #204)) Retransmitting #1 (NAT) to 192.168.17.141:5060: NOTIFY sip:112@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport Max-Forwards: 70 From: "asterisk" ;tag=as5fb3632e To: Contact: Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 1.8.15.0 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@192.168.17.1 Voice-Message: 0/0 (0/0) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060 Really destroying SIP dialog '32dea65116e339261e4dab774c2fca4f@192.168.17.1:5060' Method: OPTIONS <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport=5060 From: "asterisk" ;tag=as5fb3632e To: ;tag=ar4gc2723d Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport=5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as5fb3632e [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 48]: To: ;tag=ar4gc2723d [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 102 NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 (Checking To) --From tag as5fb3632e --To-tag ar4gc2723d [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #204 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:20560 handle_response_notify: Got 200 accepted on NOTIFY 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 Really destroying SIP dialog '34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060' Method: NOTIFY <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport=5060 From: "asterisk" ;tag=as5fb3632e To: ;tag=ar4gc2723d Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK0226c153;rport=5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as5fb3632e [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 48]: To: ;tag=ar4gc2723d [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 102 NOTIFY [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 (Checking To) --From tag as5fb3632e --To-tag ar4gc2723d [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:8234 find_call: That's odd... Got a response on a call we don't know about. Callid 34fac1f260e8518d334693233b3dd9e2@192.168.17.1:5060 [Sep 23 11:49:28] DEBUG[840]: chan_sip.c:25507 handle_request_do: Invalid SIP message - rejected , no callid, len 327 [Sep 23 11:49:28] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/112' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:64.2.142.187:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as31347f48 Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 103 INVITE User-Agent: packetrino Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <-------------> [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as31347f48 [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 (Checking To) --From tag as62129ab2 --To-tag as31347f48 [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:4071 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '635106f711855fca44343c30555feaf9@24.128.119.26:5060' Request 103: Found [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 180 to standard invite [Sep 23 11:49:30] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: -- SIP/vitel-outbound-00000007 is ringing [Sep 23 11:49:30] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:30] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:30] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 6 (Ringing) [Sep 23 11:49:30] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '6' -- Local/s@OutboundSLA-de33;1 is ringing [Sep 23 11:49:30] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 6b41377625d74df113e21bca0f6e0e41@192.168.17.1:5060 - OPTIONS (No RTP) [Sep 23 11:49:37] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method OPTIONS - callid 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 43]: OPTIONS sip:111@192.168.17.141:5060 SIP/2.0 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7263a941;rport [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as1e154d66 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:49:37 GMT [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 192.168.17.141:5060: OPTIONS sip:111@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7263a941;rport Max-Forwards: 70 From: "asterisk" ;tag=as1e154d66 To: Contact: Call-ID: 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:49:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #207 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.17.141:5060 <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7263a941;rport=5060 From: "asterisk" ;tag=as1e154d66 To: Call-ID: 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 21]: SIP/2.0 486 Busy Here [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7263a941;rport=5060 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as1e154d66 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 33]: To: [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 (Checking To) --From tag as1e154d66 --To-tag [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #207 [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:49:37] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060 Really destroying SIP dialog '50efdb7f5d6e7d7a148255bb546cd938@192.168.17.1:5060' Method: OPTIONS <--- SIP read from UDP:64.2.142.187:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as31347f48 Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 103 INVITE User-Agent: packetrino Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Type: application/sdp Content-Length: 287 v=0 o=root 15558 15558 IN IP4 64.2.142.187 s=session c=IN IP4 64.2.142.187 t=0 0 m=audio 14970 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK4027035a;received=24.128.119.26;rport=5060 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as31347f48 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 19]: Content-Length: 287 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 0]: [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 0 [ 3]: v=0 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 1 [ 38]: o=root 15558 15558 IN IP4 64.2.142.187 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 2 [ 9]: s=session [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 3 [ 21]: c=IN IP4 64.2.142.187 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 4 [ 5]: t=0 0 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 5 [ 30]: m=audio 14970 RTP/AVP 0 18 101 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Body 12 [ 10]: a=ptime:20 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8558 parse_request: Body 13 [ 10]: a=sendrecv --- (12 headers 14 lines) --- [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 (Checking To) --From tag as62129ab2 --To-tag as31347f48 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3992 __sip_ack: Acked pending invite 103 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '635106f711855fca44343c30555feaf9@24.128.119.26:5060' of Request 103: Match Found [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 200 to standard invite [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP o=root 15558 15558 IN IP4 64.2.142.187... UNSUPPORTED OR FAILED. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP s=session... UNSUPPORTED OR FAILED. [Sep 23 11:49:43] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187' into... [Sep 23 11:49:43] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '64.2.142.187' and port ''. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP c=IN IP4 64.2.142.187... OK. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 0 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x41504490 Found RTP audio format 18 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x41504490 Found RTP audio format 101 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x41504490 Found audio description format PCMU for ID 0 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format G729 for ID 18 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED OR FAILED. Found audio description format telephone-event for ID 101 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x41504490 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0x41504490 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x41504490 Capabilities: us - 0x104 (ulaw|g729), peer - audio=0x104 (ulaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x104 (ulaw|g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Sep 23 11:49:43] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x88b3a28' Peer audio RTP is at port 64.2.142.187:14970 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x41504490 to 0x88b3bd4 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x41504490 to 0x88b3bd4 [Sep 23 11:49:43] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x41504490 to 0x88b3bd4 [Sep 23 11:49:43] DEBUG[840]: res_rtp_asterisk.c:2489 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x88b3a28' [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9424 process_sdp: We're settling with these formats: 0x104 (ulaw|g729) [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:9429 process_sdp: We have an owner, now see if we need to change this call [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:10397 reqprep: Strict routing enforced for session 635106f711855fca44343c30555feaf9@24.128.119.26:5060 set_destination: Parsing for address/port to send to [Sep 23 11:49:43] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187' into... [Sep 23 11:49:43] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '64.2.142.187' and port ''. set_destination: set destination to 64.2.142.187:5060 Transmitting (NAT) to 64.2.142.187:5060: ACK sip:1203mobilep@64.2.142.187 SIP/2.0 Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK0b2c2f92;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as31347f48 Contact: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 103 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 --- [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'ACK sip:120' onto UDP socket destined for 64.2.142.187:5060 -- SIP/vitel-outbound-00000007 answered Local/s@OutboundSLA-de33;2 [Sep 23 11:49:43] DEBUG[1674]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-de33;2 to read format slin [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000007 to write format slin [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000007 to read format slin [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-de33;2 to write format slin [Sep 23 11:49:43] DEBUG[1674]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:49:43] DEBUG[1674]: features.c:4012 ast_bridge_call: bridge answer set, chan answer set [Sep 23 11:49:43] DEBUG[1674]: features.c:3854 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/vitel-outbound-00000007 since we're bridging [Sep 23 11:49:43] DEBUG[1674]: res_rtp_asterisk.c:828 ast_rtp_update_source: Setting the marker bit due to a source update [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:43] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '2' [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:43] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '2' [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:49:43] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' -- Local/s@OutboundSLA-de33;1 answered [Sep 23 11:49:43] DEBUG[1673]: chan_dahdi.c:13646 dahdi_request: Using channel -2 [Sep 23 11:49:43] DEBUG[1673]: channel.c:5175 set_format: Set channel DAHDI/pseudo-983607609 to read format slin [Sep 23 11:49:43] DEBUG[1673]: channel.c:5175 set_format: Set channel DAHDI/pseudo-983607609 to write format slin -- Created MeetMe conference 1023 for conference 'SLA_SLAtrunk1' [Sep 23 11:49:43] DEBUG[1673]: devicestate.c:440 devstate_event: device 'meetme:SLA_SLAtrunk1' state '2' [Sep 23 11:49:43] DEBUG[1673]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:49:43] DEBUG[1673]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-de33;1 to write format slin [Sep 23 11:49:43] DEBUG[1673]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-de33;1 to read format slin [Sep 23 11:49:43] DEBUG[1673]: app_meetme.c:2683 conf_run: Placed channel Local/s@OutboundSLA-de33;1 in DAHDI conf 1023 [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:49:43] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for DAHDI/pseudo - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo' state '2' [Sep 23 11:49:43] DEBUG[1673]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:49:43] DEBUG[1673]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:49:43] DEBUG[1674]: channel.c:5954 __ast_channel_masquerade: Planning to masquerade channel SIP/vitel-outbound-00000007 into the structure of Local/s@OutboundSLA-de33;1 [Sep 23 11:49:43] DEBUG[1674]: channel.c:5964 __ast_channel_masquerade: Done planning to masquerade channel SIP/vitel-outbound-00000007 into the structure of Local/s@OutboundSLA-de33;1 [Sep 23 11:49:43] DEBUG[1674]: chan_local.c:557 check_bridge: Masquerading Local/s@OutboundSLA-de33;1 <- SIP/vitel-outbound-00000007 [Sep 23 11:49:43] DEBUG[1674]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:49:43] DEBUG[1674]: channel.c:6539 ast_do_masquerade: Actually Masquerading SIP/vitel-outbound-00000007(6) into the structure of Local/s@OutboundSLA-de33;1(6) [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000007 to write format slin [Sep 23 11:49:43] DEBUG[1674]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000007 to read format slin [Sep 23 11:49:43] DEBUG[1674]: channel.c:6743 ast_do_masquerade: Putting channel SIP/vitel-outbound-00000007 in slin/slin formats [Sep 23 11:49:43] DEBUG[1674]: chan_sip.c:6645 sip_fixup: SIP Fixup: New owner for dialogue 635106f711855fca44343c30555feaf9@24.128.119.26:5060: SIP/vitel-outbound-00000007 (Old parent: Local/s@OutboundSLA-de33;1) [Sep 23 11:49:43] DEBUG[1674]: channel.c:6819 ast_do_masquerade: Done Masquerading SIP/vitel-outbound-00000007 (6) [Sep 23 11:49:43] DEBUG[1674]: res_rtp_asterisk.c:840 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Sep 23 11:49:43] DEBUG[1674]: chan_local.c:654 local_write: Not posting to 'Local/s@OutboundSLA-de33;2' queue since already masqueraded out [Sep 23 11:49:43] DEBUG[1674]: channel.c:7488 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=Local/s@OutboundSLA-de33;2, c1=Local/s@OutboundSLA-de33;1, flags: No,Yes,Yes,Yes [Sep 23 11:49:43] DEBUG[1674]: channel.c:7595 ast_channel_bridge: Bridge stops bridging channels Local/s@OutboundSLA-de33;2 and Local/s@OutboundSLA-de33;1 [Sep 23 11:49:43] DEBUG[1674]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'Local/s@OutboundSLA-de33;2' [Sep 23 11:49:43] DEBUG[1674]: pbx.c:4247 pbx_extension_helper: Launching 'Hangup' -- Executing [h@OutboundSLA:1] Hangup("Local/s@OutboundSLA-de33;2", "") in new stack [Sep 23 11:49:43] DEBUG[1674]: features.c:4393 ast_bridge_call: Spawn extension (OutboundSLA,h,1) exited non-zero on 'Local/s@OutboundSLA-de33;2' == Spawn extension (OutboundSLA, h, 1) exited non-zero on 'Local/s@OutboundSLA-de33;2' [Sep 23 11:49:43] DEBUG[1674]: channel.c:2850 ast_hangup: Hanging up zombie 'Local/s@OutboundSLA-de33;1' [Sep 23 11:49:43] DEBUG[1674]: app_dial.c:3027 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 23 11:49:43] DEBUG[1674]: app_macro.c:429 _macro_exec: Spawn extension (macro-trunkdial-failover,1-dial,1) exited non-zero on 'Local/s@OutboundSLA-de33;2' in macro 'trunkdial-failover' == Spawn extension (macro-trunkdial-failover, 1-dial, 1) exited non-zero on 'Local/s@OutboundSLA-de33;2' in macro 'trunkdial-failover' [Sep 23 11:49:43] DEBUG[1674]: pbx.c:5064 __ast_pbx_run: Spawn extension (OutboundSLA,1203mobilep,1) exited non-zero on 'Local/s@OutboundSLA-de33;2' == Spawn extension (OutboundSLA, 1203mobilep, 1) exited non-zero on 'Local/s@OutboundSLA-de33;2' [Sep 23 11:49:43] DEBUG[1674]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'Local/s@OutboundSLA-de33;2' [Sep 23 11:49:43] DEBUG[1674]: channel.c:2844 ast_hangup: Hanging up channel 'Local/s@OutboundSLA-de33;2' [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'Local/s@OutboundSLA' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'meetme:SLA_SLAtrunk1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[1673]: app_meetme.c:3127 conf_run: Ooh, something swapped out under us, starting over [Sep 23 11:49:43] DEBUG[1673]: app_meetme.c:2683 conf_run: Placed channel SIP/vitel-outbound-00000007 in DAHDI conf 1023 [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:6492 sip_answer: SIP answering channel: SIP/111-00000006 [Sep 23 11:49:43] DEBUG[1672]: res_rtp_asterisk.c:828 ast_rtp_update_source: Setting the marker bit due to a source update [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:11814 transmit_response_with_sdp: Setting framing from config on incoming call [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:11413 add_sdp: ** Our capability: 0x1104 (ulaw|g729|g722) Video flag: True Text flag: True [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 16596 Adding codec 0x1000 (g722) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:11709 add_sdp: Done building SDP. Settling with this capability: 0x1104 (ulaw|g729|g722) <--- Reliably Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK224b649abbedede063905072b7e799a5;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 2 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 306 v=0 o=root 858197171 858197171 IN IP4 192.168.17.1 s=Asterisk PBX 1.8.15.0 c=IN IP4 192.168.17.1 t=0 0 m=audio 16596 RTP/AVP 9 0 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #211 [Sep 23 11:49:43] DEBUG[1672]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:49:43] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 1 (Not in use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '1' [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:43] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'Local/s@OutboundSLA' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'DAHDI/pseudo' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[1673]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:49:43] DEBUG[1673]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:49:43] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:49:43] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 1 (Not in use) [Sep 23 11:49:43] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '1' [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'Local/s@OutboundSLA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'Local/s@OutboundSLA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:43] DEBUG[1673]: res_rtp_asterisk.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 23 11:49:43] DEBUG[1673]: res_rtp_asterisk.c:1390 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [Sep 23 11:49:43] DEBUG[1672]: channel.c:5175 set_format: Set channel SIP/111-00000006 to write format slin [Sep 23 11:49:43] DEBUG[1672]: channel.c:5175 set_format: Set channel SIP/111-00000006 to read format slin [Sep 23 11:49:43] DEBUG[1672]: app_meetme.c:2683 conf_run: Placed channel SIP/111-00000006 in DAHDI conf 1023 [Sep 23 11:49:43] DEBUG[1672]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:49:43] DEBUG[1672]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:49:43] DEBUG[1672]: res_rtp_asterisk.c:1359 ast_rtp_write: Ooh, format changed from unknown to g722 [Sep 23 11:49:43] DEBUG[1672]: res_rtp_asterisk.c:1390 ast_rtp_write: Created smoother: format: g722 ms: 20 len: 160 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3585 retrans_pkt: SIP TIMER: Rescheduling retransmission #211 (1) SIP/2.0 - 1 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3605 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #211)) Retransmitting #1 (NAT) to 192.168.17.141:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK224b649abbedede063905072b7e799a5;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 2 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 306 v=0 o=root 858197171 858197171 IN IP4 192.168.17.1 s=Asterisk PBX 1.8.15.0 c=IN IP4 192.168.17.1 t=0 0 m=audio 16596 RTP/AVP 9 0 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.17.141:5060 <--- SIP read from UDP:192.168.17.141:5060 ---> ACK sip:1203mobilep@192.168.17.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK4cb1a1d22ba0f106aaa7ca61ffb91e0a;rport From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 2 ACK Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 45]: ACK sip:1203mobilep@192.168.17.1:5060 SIP/2.0 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK4cb1a1d22ba0f106aaa7ca61ffb91e0a;rport [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 1" ;tag=956840114 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 62]: To: ;tag=as4f089d84 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 4161371945@192_168_17_141 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 11]: CSeq: 2 ACK [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 -- (10 headers 0 lines) --- [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 4161371945@192_168_17_141 (Checking From) --From tag 956840114 --To-tag as4f089d84 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #211 [Sep 23 11:49:43] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '4161371945@192_168_17_141' of Response 2: Match Found <--- SIP read from UDP:192.168.17.141:5060 ---> ACK sip:1203mobilep@192.168.17.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKac5491171e2ae3eeea2fbed2f413ee8;rport From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 2 ACK Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 45]: ACK sip:1203mobilep@192.168.17.1:5060 SIP/2.0 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKac5491171e2ae3eeea2fbed2f413ee8;rport [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 1" ;tag=956840114 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 62]: To: ;tag=as4f089d84 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 4161371945@192_168_17_141 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 11]: CSeq: 2 ACK [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 4161371945@192_168_17_141 (Checking From) --From tag 956840114 --To-tag as4f089d84 [Sep 23 11:49:44] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received ACK (6) - Command in SIP ACK <--- SIP read from UDP:192.168.17.141:5060 ---> BYE sip:1203mobilep@192.168.17.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK1d121940c2773bf2d3fd3ace2b7759d8;rport From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 3 BYE Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 45]: BYE sip:1203mobilep@192.168.17.1:5060 SIP/2.0 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK1d121940c2773bf2d3fd3ace2b7759d8;rport [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 57]: From: "Cordless 1" ;tag=956840114 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 62]: To: ;tag=as4f089d84 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 4161371945@192_168_17_141 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 11]: CSeq: 3 BYE [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 4161371945@192_168_17_141 (Checking From) --From tag 956840114 --To-tag as4f089d84 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:23954 handle_request_bye: Initializing initreq for method BYE - callid 4161371945@192_168_17_141 [Sep 23 11:49:48] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:48] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:3088 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4161371945@192_168_17_141 [Sep 23 11:49:48] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8895400' Scheduling destruction of SIP dialog '4161371945@192_168_17_141' in 6400 ms (Method: BYE) [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:24056 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK1d121940c2773bf2d3fd3ace2b7759d8;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=956840114 To: ;tag=as4f089d84 Call-ID: 4161371945@192_168_17_141 CSeq: 3 BYE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.17.141:5060 == Setting global variable 'MEETMEADMINSTATUS' to 'OK' [Sep 23 11:49:48] DEBUG[1672]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '1' [Sep 23 11:49:48] DEBUG[1672]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '1' [Sep 23 11:49:48] DEBUG[1672]: pbx.c:5039 __ast_pbx_run: Extension 1203mobilep, priority 3 returned normally even though call was hung up [Sep 23 11:49:48] DEBUG[1672]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/111-00000006' [Sep 23 11:49:48] DEBUG[1672]: pbx.c:4247 pbx_extension_helper: Launching 'Hangup' -- Executing [h@DialPlanSLA:1] Hangup("SIP/111-00000006", "") in new stack [Sep 23 11:49:48] DEBUG[1672]: pbx.c:5243 __ast_pbx_run: Spawn extension (DialPlanSLA,h,1) exited non-zero on 'SIP/111-00000006' == Spawn extension (DialPlanSLA, h, 1) exited non-zero on 'SIP/111-00000006' [Sep 23 11:49:48] DEBUG[1672]: channel.c:2844 ast_hangup: Hanging up channel 'SIP/111-00000006' [Sep 23 11:49:48] DEBUG[1672]: chan_sip.c:6287 sip_hangup: Hangup call SIP/111-00000006, SIP callid 4161371945@192_168_17_141 [Sep 23 11:49:48] DEBUG[1672]: chan_sip.c:6292 sip_hangup: update_call_counter(111) - decrement call limit counter on hangup [Sep 23 11:49:48] DEBUG[1672]: chan_sip.c:5905 update_call_counter: Updating call counter for incoming call [Sep 23 11:49:48] DEBUG[1672]: chan_sip.c:5976 update_call_counter: Call from peer '111' removed from call limit 10 [Sep 23 11:49:48] DEBUG[1672]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8895400' [Sep 23 11:49:48] DEBUG[1673]: devicestate.c:440 devstate_event: device 'meetme:SLA_SLAtrunk1' state '1' [Sep 23 11:49:48] DEBUG[1673]: channel.c:2844 ast_hangup: Hanging up channel 'DAHDI/pseudo-983607609' [Sep 23 11:49:48] DEBUG[1673]: chan_dahdi.c:6149 dahdi_hangup: dahdi_hangup(DAHDI/pseudo-983607609) [Sep 23 11:49:48] DEBUG[1673]: chan_dahdi.c:6316 dahdi_hangup: Hangup: channel: -2 index = 0, normal = 39, callwait = -1, thirdcall = -1 [Sep 23 11:49:48] DEBUG[1673]: chan_dahdi.c:6757 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/pseudo-983607609 [Sep 23 11:49:48] DEBUG[1673]: chan_dahdi.c:4874 update_conf: Updated conferencing on -2, with 0 conference users -- Hungup 'DAHDI/pseudo-983607609' [Sep 23 11:49:48] DEBUG[1673]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '1' [Sep 23 11:49:48] DEBUG[1673]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '1' [Sep 23 11:49:48] DEBUG[1673]: channel.c:2844 ast_hangup: Hanging up channel 'SIP/vitel-outbound-00000007' [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:6287 sip_hangup: Hangup call SIP/vitel-outbound-00000007, SIP callid 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:6292 sip_hangup: update_call_counter(1203mobilep) - decrement call limit counter on hangup [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:5976 update_call_counter: Call to peer 'vitel-outbound' removed from call limit 2147483647 [Sep 23 11:49:48] DEBUG[1673]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x88b3a28' Scheduling destruction of SIP dialog '635106f711855fca44343c30555feaf9@24.128.119.26:5060' in 6400 ms (Method: INVITE) [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:10397 reqprep: Strict routing enforced for session 635106f711855fca44343c30555feaf9@24.128.119.26:5060 set_destination: Parsing for address/port to send to [Sep 23 11:49:48] DEBUG[1673]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187' into... [Sep 23 11:49:48] DEBUG[1673]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '64.2.142.187' and port ''. set_destination: set destination to 64.2.142.187:5060 Reliably Transmitting (NAT) to 64.2.142.187:5060: BYE sip:1203mobilep@64.2.142.187 SIP/2.0 Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK5b1c289b;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as31347f48 Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 104 BYE User-Agent: Asterisk PBX 1.8.15.0 Proxy-Authorization: Digest username="myuserid", realm="asterisk", algorithm=MD5, uri="sip:1203mobilep@64.2.142.187", nonce="46beaeb7", response="dc214262c814666bfcb10af32ca85796" X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode: 0 Content-Length: 0 --- [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #215 [Sep 23 11:49:48] DEBUG[1673]: chan_sip.c:3346 __sip_xmit: Trying to put 'BYE sip:120' onto UDP socket destined for 64.2.142.187:5060 [Sep 23 11:49:48] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:48] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:48] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 1 (Not in use) [Sep 23 11:49:48] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '1' [Sep 23 11:49:48] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:48] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:48] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 1 (Not in use) [Sep 23 11:49:48] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '1' [Sep 23 11:49:48] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo [Sep 23 11:49:48] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for DAHDI/pseudo - state 0 (Unknown) [Sep 23 11:49:48] DEBUG[822]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo' state '0' [Sep 23 11:49:48] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:48] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:48] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 1 (Not in use) [Sep 23 11:49:48] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '1' [Sep 23 11:49:48] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:49:48] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:49:48] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 1 (Not in use) [Sep 23 11:49:48] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '1' [Sep 23 11:49:48] DEBUG[823]: app_queue.c:1585 extension_state_cb: Extension 'SLAphone111_SLAtrunk1@DialPlanSLA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[823]: app_queue.c:1585 extension_state_cb: Extension 'SLAphone112_SLAtrunk1@DialPlanSLA' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone111_SLAtrunk1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone112_SLAtrunk1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'meetme:SLA_SLAtrunk1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone111_SLAtrunk1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SLA:SLAphone112_SLAtrunk1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'DAHDI/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 23 11:49:48] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/vitel-outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:64.2.142.187:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK5b1c289b;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as62129ab2 To: ;tag=as31347f48 Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 CSeq: 104 BYE User-Agent: packetrino Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <-------------> [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK5b1c289b;received=24.128.119.26;rport=5060 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as62129ab2 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as31347f48 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 13]: CSeq: 104 BYE [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 635106f711855fca44343c30555feaf9@24.128.119.26:5060 (Checking To) --From tag as62129ab2 --To-tag as31347f48 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #215 [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '635106f711855fca44343c30555feaf9@24.128.119.26:5060' of Request 104: Match Found [Sep 23 11:49:48] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 635106f711855fca44343c30555feaf9@24.128.119.26:5060 Really destroying SIP dialog '635106f711855fca44343c30555feaf9@24.128.119.26:5060' Method: INVITE [Sep 23 11:49:48] DEBUG[840]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x88b3a28' <--- SIP read from UDP:192.168.17.141:5060 ---> REGISTER sip:mydomain.org SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK3c8b75fc70082884dd3629ba4aede7e9;rport From: "Cordless 1" ;tag=2257326627 To: "Cordless 1" Call-ID: 2660979324@192_168_17_141 CSeq: 1745 REGISTER Contact: Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Expires: 180 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 35]: REGISTER sip:mydomain.org SIP/2.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK3c8b75fc70082884dd3629ba4aede7e9;rport [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 58]: From: "Cordless 1" ;tag=2257326627 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 41]: To: "Cordless 1" [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 2660979324@192_168_17_141 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 19]: CSeq: 1745 REGISTER [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 12]: Expires: 180 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 2660979324@192_168_17_141 (Checking From) --From tag 2257326627 --To-tag [Sep 23 11:49:52] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 2660979324@192_168_17_141 - REGISTER (No RTP) [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:25083 handle_request_register: Initializing initreq for method REGISTER - callid 2660979324@192_168_17_141 [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK3c8b75fc70082884dd3629ba4aede7e9;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=2257326627 To: "Cordless 1" ;tag=as70b969fb Call-ID: 2660979324@192_168_17_141 CSeq: 1745 REGISTER Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5776f422" Content-Length: 0 <------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.17.141:5060 Scheduling destruction of SIP dialog '2660979324@192_168_17_141' in 32000 ms (Method: REGISTER) <--- SIP read from UDP:192.168.17.141:5060 ---> REGISTER sip:mydomain.org SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKca15e2e82ce3a9048b741a894ec5476c;rport From: "Cordless 1" ;tag=2257326627 To: "Cordless 1" Call-ID: 2660979324@192_168_17_141 CSeq: 1746 REGISTER Contact: Authorization: Digest username="111", realm="asterisk", algorithm=MD5, uri="sip:mydomain.org", nonce="5776f422", response="888e891588bcb19c676aeed4e085fa0b" Max-Forwards: 70 User-Agent: C610A IP/42.072.00.000.000 Expires: 180 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 35]: REGISTER sip:mydomain.org SIP/2.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKca15e2e82ce3a9048b741a894ec5476c;rport [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 58]: From: "Cordless 1" ;tag=2257326627 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 41]: To: "Cordless 1" [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 2660979324@192_168_17_141 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 19]: CSeq: 1746 REGISTER [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [158]: Authorization: Digest username="111", realm="asterisk", algorithm=MD5, uri="sip:mydomain.org", nonce="5776f422", response="888e891588bcb19c676aeed4e085fa0b" [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 12]: Expires: 180 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 2660979324@192_168_17_141 (Checking From) --From tag 2257326627 --To-tag [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:25083 handle_request_register: Initializing initreq for method REGISTER - callid 2660979324@192_168_17_141 [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. Sending to 192.168.17.141:5060 (NAT) [Sep 23 11:49:52] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:49:52] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:14154 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 6b6a785c4d7d130f202f08aa7107fcee@192.168.17.1:5060 - OPTIONS (No RTP) [Sep 23 11:49:52] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method OPTIONS - callid 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 43]: OPTIONS sip:111@192.168.17.141:5060 SIP/2.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK3589c415;rport [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as75f06fd9 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:49:52 GMT [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 192.168.17.141:5060: OPTIONS sip:111@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK3589c415;rport Max-Forwards: 70 From: "asterisk" ;tag=as75f06fd9 To: Contact: Call-ID: 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:49:52 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #218 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.17.141:5060 <--- Transmitting (NAT) to 192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKca15e2e82ce3a9048b741a894ec5476c;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=2257326627 To: "Cordless 1" ;tag=as70b969fb Call-ID: 2660979324@192_168_17_141 CSeq: 1746 REGISTER Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 180 Contact: ;expires=180 Date: Sun, 23 Sep 2012 15:49:52 GMT Content-Length: 0 <------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 4d00f8a42260e39e27216ecc6f130df9@192.168.17.1:5060 - NOTIFY (No RTP) [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3146 obproxy_get: OBPROXY: Not applying OBproxy to this call [Sep 23 11:49:52] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 Scheduling destruction of SIP dialog '04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060' in 6784 ms (Method: NOTIFY) [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method NOTIFY - callid 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 42]: NOTIFY sip:111@192.168.17.141:5060 SIP/2.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK77475caa;rport [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as08ccbc74 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: CSeq: 102 NOTIFY [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 22]: Event: message-summary [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 48]: Content-Type: application/simple-message-summary Reliably Transmitting (NAT) to 192.168.17.141:5060: NOTIFY sip:111@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK77475caa;rport Max-Forwards: 70 From: "asterisk" ;tag=as08ccbc74 To: Contact: Call-ID: 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 1.8.15.0 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@192.168.17.1 Voice-Message: 0/0 (0/0) --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #221 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.17.141:5060 Scheduling destruction of SIP dialog '2660979324@192_168_17_141' in 32000 ms (Method: REGISTER) [Sep 23 11:49:52] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:49:52] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:49:52] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 1 (Not in use) [Sep 23 11:49:52] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '1' [Sep 23 11:49:52] DEBUG[859]: app_queue.c:1490 handle_statechange: Device 'SIP/111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK3589c415;rport=5060 From: "asterisk" ;tag=as75f06fd9 To: ;tag=ar64g17ge8 Call-ID: 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 CSeq: 102 OPTIONS Supported: replaces User-Agent: C610A IP/42.072.00.000.000 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Accept: application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag Accept-Encoding: identity Accept-Language: en Content-Length: 0 <-------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK3589c415;rport=5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as75f06fd9 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 48]: To: ;tag=ar64g17ge8 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 19]: Supported: replaces [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 97]: Accept: application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 25]: Accept-Encoding: identity [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 19]: Accept-Language: en [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 (Checking To) --From tag as75f06fd9 --To-tag ar64g17ge8 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #218 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060 Really destroying SIP dialog '13cb80774bd5ff6703d97ad42119c310@192.168.17.1:5060' Method: OPTIONS <--- SIP read from UDP:192.168.17.141:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK77475caa;rport=5060 From: "asterisk" ;tag=as08ccbc74 To: ;tag=ar19bbcb65 Call-ID: 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 CSeq: 102 NOTIFY User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK77475caa;rport=5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as08ccbc74 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 48]: To: ;tag=ar19bbcb65 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 102 NOTIFY [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 (Checking To) --From tag as08ccbc74 --To-tag ar19bbcb65 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #221 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:20560 handle_response_notify: Got 200 accepted on NOTIFY 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 [Sep 23 11:49:52] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060 Really destroying SIP dialog '04b6359a3653b6916718ab637895a5ff@192.168.17.1:5060' Method: NOTIFY [Sep 23 11:49:54] DEBUG[840]: chan_sip.c:3886 __sip_autodestruct: Auto destroying SIP dialog '4161371945@192_168_17_141' [Sep 23 11:49:54] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 4161371945@192_168_17_141 Really destroying SIP dialog '4161371945@192_168_17_141' Method: BYE [Sep 23 11:49:54] DEBUG[840]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x8895400' pbx*CLI>