<--- SIP read from UDP:192.168.17.141:5060 ---> INVITE sip:*1@mydomain.org;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK47dcb4afcdcc86d7ce6db91e0a3bcbe;rport From: "Cordless 1" ;tag=3057794908 To: Call-ID: 1888579549@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 5016 20 IN IP4 192.168.17.141 s=Mapping c=IN IP4 192.168.17.141 t=0 0 m=audio 5016 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:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 47]: INVITE sip:*1@mydomain.org;user=phone SIP/2.0 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bK47dcb4afcdcc86d7ce6db91e0a3bcbe;rport [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 58]: From: "Cordless 1" ;tag=3057794908 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 38]: To: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 1888579549@192_168_17_141 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 19]: Supported: replaces [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 48]: Allow-Events: message-summary, refer, ua-profile [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 13 [ 19]: Content-Length: 384 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 14 [ 0]: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 0 [ 3]: v=0 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 1 [ 35]: o=111 5016 20 IN IP4 192.168.17.141 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 2 [ 9]: s=Mapping [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 3 [ 23]: c=IN IP4 192.168.17.141 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 4 [ 5]: t=0 0 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 5 [ 41]: m=audio 5016 RTP/AVP 9 0 8 96 97 2 18 101 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 9 [ 24]: a=rtpmap:96 G726-32/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 10 [ 29]: a=rtpmap:97 AAL2-G726-32/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 11 [ 23]: a=rtpmap:2 G726-32/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 12 [ 21]: a=rtpmap:18 G729/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 13 [ 19]: a=fmtp:18 annexb=no [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Body 15 [ 15]: a=fmtp:101 0-16 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8558 parse_request: Body 16 [ 10]: a=ptime:20 --- (14 headers 17 lines) --- [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 1888579549@192_168_17_141 (Checking From) --From tag 3057794908 --To-tag [Sep 23 11:50:45] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.141', our source address is '192.168.17.1'. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 1888579549@192_168_17_141 - INVITE (No RTP) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Sep 23 11:50:45] DEBUG[840]: sip/reqresp_parser.c:1550 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Sep 23 11:50:45] DEBUG[840]: sip/reqresp_parser.c:1566 parse_sip_options: Found SIP option: -replaces- [Sep 23 11:50:45] DEBUG[840]: sip/reqresp_parser.c:1574 parse_sip_options: Matched SIP option: replaces [Sep 23 11:50:45] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:50:45] 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:50:45] DEBUG[840]: chan_sip.c:22643 handle_request_invite: Initializing initreq for method INVITE - callid 1888579549@192_168_17_141 Using INVITE request as basis request - 1888579549@192_168_17_141 [Sep 23 11:50:45] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:50:45] 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:50:45] DEBUG[840]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8895f68' [Sep 23 11:50:45] DEBUG[840]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 16564 for RTP instance '0x8895f68' [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x8895f68' is setup and ready to go [Sep 23 11:50:45] DEBUG[840]: res_rtp_asterisk.c:2523 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8895f68' == Using SIP RTP CoS mark 5 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:5093 do_setnat: Setting NAT on RTP to On [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP o=111 5016 20 IN IP4 192.168.17.141... UNSUPPORTED OR FAILED. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP s=Mapping... UNSUPPORTED OR FAILED. [Sep 23 11:50:45] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141' into... [Sep 23 11:50:45] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port ''. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP c=IN IP4 192.168.17.141... OK. [Sep 23 11:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Sep 23 11:50:45] 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:50:45] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 2 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 9 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 96 on 0x41503e70 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 97 on 0x41503e70 [Sep 23 11:50:45] 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:50:45] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8895f68' Peer audio RTP is at port 192.168.17.141:5016 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 2 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 9 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 96 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 97 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x41503e70 to 0x8896114 [Sep 23 11:50:45] DEBUG[840]: res_rtp_asterisk.c:2489 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x8895f68' [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:9424 process_sdp: We're settling with these formats: 0x1104 (ulaw|g729|g722) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:22780 handle_request_invite: Checking SIP call limits for device 111 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:5905 update_call_counter: Updating call counter for incoming call [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:6010 update_call_counter: Call from peer '111' is 1 out of 10 [Sep 23 11:50:45] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:50:45] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. [Sep 23 11:50:45] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'mydomain.org' into... [Sep 23 11:50:45] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'mydomain.org' and port ''. Looking for *1 in DialPlanSLA (domain mydomain.org) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7091 sip_new: *** Our native formats are 0x1000 (g722) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7092 sip_new: *** Joint capabilities are 0x1104 (ulaw|g729|g722) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7093 sip_new: *** Our capabilities are 0x1104 (ulaw|g729|g722) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7094 sip_new: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:7124 sip_new: This channel will not be able to handle video. [Sep 23 11:50:45] DEBUG[840]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:50:45] DEBUG[840]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:23081 handle_request_invite: SIP/111-00000008: 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=z9hG4bK47dcb4afcdcc86d7ce6db91e0a3bcbe;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=3057794908 To: Call-ID: 1888579549@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:50:45] 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:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:50:45] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:50:45] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:50:45] DEBUG[1760]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:45] DEBUG[1760]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '*1' [Sep 23 11:50:45] DEBUG[1760]: pbx.c:4247 pbx_extension_helper: Launching 'SLAStation' -- Executing [*1@DialPlanSLA:1] SLAStation("SIP/111-00000008", "SLAphone111_SLAtrunk1") in new stack [Sep 23 11:50:45] DEBUG[1760]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '2' [Sep 23 11:50:45] DEBUG[1760]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '2' [Sep 23 11:50:45] DEBUG[1761]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Sep 23 11:50:45] DEBUG[1761]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Sep 23 11:50:45] DEBUG[1761]: channel.c:6152 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called s@OutboundSLA [Sep 23 11:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'NoOp' -- Executing [s@OutboundSLA:1] NoOp("Local/s@OutboundSLA-60de;2", "SLA Outbound context") in new stack [Sep 23 11:50:45] DEBUG[1762]: pbx.c:3253 ast_str_retrieve_variable: Result of 'SLA_EXTEN' is NULL [Sep 23 11:50:45] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:45] DEBUG[1762]: pbx.c:3253 ast_str_retrieve_variable: Result of 'SLA_EXTEN' is NULL [Sep 23 11:50:45] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@OutboundSLA:2] GotoIf("Local/s@OutboundSLA-60de;2", "0?,1") in new stack [Sep 23 11:50:45] DEBUG[1762]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:50:45] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'DISA' -- Executing [s@OutboundSLA:3] DISA("Local/s@OutboundSLA-60de;2", "no-password,OutboundSLA") in new stack [Sep 23 11:50:45] DEBUG[1762]: app_disa.c:173 disa_exec: Digittimeout: 5000 [Sep 23 11:50:45] DEBUG[1762]: app_disa.c:174 disa_exec: Responsetimeout: 10000 [Sep 23 11:50:45] DEBUG[1762]: app_disa.c:192 disa_exec: Mailbox: [Sep 23 11:50:45] DEBUG[1762]: chan_local.c:760 local_indicate: Blocked indication -1 -- Local/s@OutboundSLA-60de;1 answered [Sep 23 11:50:45] DEBUG[1761]: chan_dahdi.c:13646 dahdi_request: Using channel -2 [Sep 23 11:50:45] DEBUG[1761]: channel.c:5175 set_format: Set channel DAHDI/pseudo-1633340121 to read format slin [Sep 23 11:50:45] DEBUG[1761]: channel.c:5175 set_format: Set channel DAHDI/pseudo-1633340121 to write format slin -- Created MeetMe conference 1023 for conference 'SLA_SLAtrunk1' [Sep 23 11:50:45] DEBUG[1761]: devicestate.c:440 devstate_event: device 'meetme:SLA_SLAtrunk1' state '2' [Sep 23 11:50:45] DEBUG[1761]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:50:45] DEBUG[1761]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;1 to write format slin [Sep 23 11:50:45] DEBUG[1761]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;1 to read format slin [Sep 23 11:50:45] DEBUG[1761]: app_meetme.c:2683 conf_run: Placed channel Local/s@OutboundSLA-60de;1 in DAHDI conf 1023 [Sep 23 11:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:50:45] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' [Sep 23 11:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:50:45] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' [Sep 23 11:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for DAHDI/pseudo - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo' state '2' [Sep 23 11:50:45] DEBUG[1761]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:50:45] DEBUG[1761]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:50:45] 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:50:45] 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:50:45] 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:50:45] 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:50:45] DEBUG[1760]: chan_sip.c:6492 sip_answer: SIP answering channel: SIP/111-00000008 [Sep 23 11:50:45] DEBUG[1760]: res_rtp_asterisk.c:828 ast_rtp_update_source: Setting the marker bit due to a source update [Sep 23 11:50:45] DEBUG[1760]: chan_sip.c:11814 transmit_response_with_sdp: Setting framing from config on incoming call [Sep 23 11:50:45] DEBUG[1760]: chan_sip.c:11413 add_sdp: ** Our capability: 0x1104 (ulaw|g729|g722) Video flag: True Text flag: True [Sep 23 11:50:45] DEBUG[1760]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 16564 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:50:45] DEBUG[1760]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:50:45] DEBUG[1760]: 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=z9hG4bK47dcb4afcdcc86d7ce6db91e0a3bcbe;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=3057794908 To: ;tag=as01c5d3a5 Call-ID: 1888579549@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 953270011 953270011 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 16564 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:50:45] DEBUG[1760]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #234 [Sep 23 11:50:45] DEBUG[1760]: 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:50:45] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:50:45] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:50:45] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 2 (In use) [Sep 23 11:50:45] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '2' [Sep 23 11:50:45] 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:50:45] DEBUG[1762]: app_disa.c:201 disa_exec: Context: OutboundSLA [Sep 23 11:50:45] DEBUG[1762]: app_disa.c:205 disa_exec: DISA no-password login success [Sep 23 11:50:45] DEBUG[1762]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;2 to write format slin [Sep 23 11:50:45] DEBUG[1762]: channel.c:3516 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Sep 23 11:50:45] DEBUG[1760]: channel.c:5175 set_format: Set channel SIP/111-00000008 to write format slin [Sep 23 11:50:45] DEBUG[1760]: channel.c:5175 set_format: Set channel SIP/111-00000008 to read format slin [Sep 23 11:50:45] DEBUG[1760]: app_meetme.c:2683 conf_run: Placed channel SIP/111-00000008 in DAHDI conf 1023 [Sep 23 11:50:45] DEBUG[1760]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:50:45] DEBUG[1760]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:50:45] DEBUG[1760]: res_rtp_asterisk.c:1359 ast_rtp_write: Ooh, format changed from unknown to g722 [Sep 23 11:50:45] DEBUG[1760]: res_rtp_asterisk.c:1390 ast_rtp_write: Created smoother: format: g722 ms: 20 len: 160 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:3585 retrans_pkt: SIP TIMER: Rescheduling retransmission #234 (1) SIP/2.0 - 1 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:3605 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #234)) 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=z9hG4bK47dcb4afcdcc86d7ce6db91e0a3bcbe;received=192.168.17.141;rport=5060 From: "Cordless 1" ;tag=3057794908 To: ;tag=as01c5d3a5 Call-ID: 1888579549@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 953270011 953270011 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 16564 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:50:45] 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:*1@192.168.17.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKed49be04840fb4f6a9f2d385cf17cccc;rport From: "Cordless 1" ;tag=3057794908 To: ;tag=as01c5d3a5 Call-ID: 1888579549@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:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 36]: ACK sip:*1@192.168.17.1:5060 SIP/2.0 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 89]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKed49be04840fb4f6a9f2d385cf17cccc;rport [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 58]: From: "Cordless 1" ;tag=3057794908 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 53]: To: ;tag=as01c5d3a5 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 1888579549@192_168_17_141 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 11]: CSeq: 2 ACK [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 1888579549@192_168_17_141 (Checking From) --From tag 3057794908 --To-tag as01c5d3a5 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #234 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '1888579549@192_168_17_141' of Response 2: Match Found <--- SIP read from UDP:192.168.17.141:5060 ---> ACK sip:*1@192.168.17.1:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKae74d8306a5024eb8da38063da3dbc;rport From: "Cordless 1" ;tag=3057794908 To: ;tag=as01c5d3a5 Call-ID: 1888579549@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:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 36]: ACK sip:*1@192.168.17.1:5060 SIP/2.0 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 192.168.17.141:5060;branch=z9hG4bKae74d8306a5024eb8da38063da3dbc;rport [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 58]: From: "Cordless 1" ;tag=3057794908 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 53]: To: ;tag=as01c5d3a5 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 1888579549@192_168_17_141 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 11]: CSeq: 2 ACK [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 1888579549@192_168_17_141 (Checking From) --From tag 3057794908 --To-tag as01c5d3a5 [Sep 23 11:50:45] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Sep 23 11:50:46] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:46] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 49 (1), at 192.168.17.141:5016 [Sep 23 11:50:46] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 49 (1), at 192.168.17.141:5016 [Sep 23 11:50:47] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1762]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;2 to write format g722 [Sep 23 11:50:47] DEBUG[1762]: channel.c:3516 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:47] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:47] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 48 (0), at 192.168.17.141:5016 [Sep 23 11:50:47] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 48 (0), at 192.168.17.141:5016 [Sep 23 11:50:47] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:47] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 51 (3), at 192.168.17.141:5016 [Sep 23 11:50:48] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 51 (3), at 192.168.17.141:5016 [Sep 23 11:50:48] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:48] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 55 (7), at 192.168.17.141:5016 [Sep 23 11:50:49] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 55 (7), at 192.168.17.141:5016 [Sep 23 11:50:49] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 55 (7), at 192.168.17.141:5016 [Sep 23 11:50:49] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 55 (7), at 192.168.17.141:5016 [Sep 23 11:50:49] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:49] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 48 (0), at 192.168.17.141:5016 [Sep 23 11:50:50] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 48 (0), at 192.168.17.141:5016 [Sep 23 11:50:50] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 51 (3), at 192.168.17.141:5016 [Sep 23 11:50:50] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:50] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 51 (3), at 192.168.17.141:5016 [Sep 23 11:50:50] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:51] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:51] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 57 (9), at 192.168.17.141:5016 [Sep 23 11:50:51] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 57 (9), at 192.168.17.141:5016 [Sep 23 11:50:51] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:51] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000009 (len = 4) [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:52] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 40ac38d70e294be62e5854901f60517e@192.168.17.1:5060 - OPTIONS (No RTP) [Sep 23 11:50: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:50:52] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method OPTIONS - callid 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 [Sep 23 11:50: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:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK68ba3455;rport [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as5541c07a [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 33]: To: [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:50:52 GMT [Sep 23 11:50: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:50: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=z9hG4bK68ba3455;rport ax-Forwards: 70 From: "asterisk" ;tag=as5541c07a To: Contact: Call-ID: 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:50:52 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #236 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) <--- 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=z9hG4bK68ba3455;rport=5060 From: "asterisk" ;tag=as5541c07a To: Call-ID: 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: C610A IP/42.072.00.000.000 Content-Length: 0 <-------------> [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 21]: SIP/2.0 486 Busy Here [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK68ba3455;rport=5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as5541c07a [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 33]: To: [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 59]: Call-ID: 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 (Checking To) --From tag as5541c07a --To-tag [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #236 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060 Really destroying SIP dialog '332bd1f57f01d15c02db4c3023f50f41@192.168.17.1:5060' Method: OPTIONS [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1498 create_dtmf_frame: Sending dtmf: 50 (2), at 192.168.17.141:5016 [Sep 23 11:50:52] DEBUG[1760]: channel.c:4856 ast_write: Thread 1101241200 Blocking 'Local/s@OutboundSLA-60de;1', already blocked by thread 1100258160 in procedure ast_waitfor_nandfds [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'vitel-outbound' is 'SIP/vitel-outbound' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '1203mobilep' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'voipcheap' is 'SIP/voipcheap' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'EXTEN' is '1203mobilep' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Macro' -- Executing [1203mobilep@OutboundSLA:1] Macro("Local/s@OutboundSLA-60de;2", "trunkdial-failover,SIP/vitel-outbound/1203mobilep,SIP/voipcheap/001203mobilep,vitel-outbound,voipcheap") in new stack [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-trunkdial-failover:1] NoOp("Local/s@OutboundSLA-60de;2", "trunk dial by 111") in new stack [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: NoOp [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-trunkdial-failover:2] ExecIf("Local/s@OutboundSLA-60de;2", "1?Set(VOLUME(RX)=10)") in new stack [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: ExecIf [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3842 ast_str_substitute_variables_full: Evaluating 'CALLERID(num)' (from 'CALLERID(num)}"="111"' len 13) [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3876 ast_str_substitute_variables_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3934 ast_str_substitute_variables_full: Expression result is '1' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-trunkdial-failover:3] ExecIf("Local/s@OutboundSLA-60de;2", "0?Set(VOLUME(RX)=10)") in new stack [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: ExecIf [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3842 ast_str_substitute_variables_full: Evaluating 'CALLERID(num)' (from 'CALLERID(num)}"="112"' len 13) [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3876 ast_str_substitute_variables_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3934 ast_str_substitute_variables_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3253 ast_str_retrieve_variable: Result of 'FMCIDNUM' is NULL [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:4] GotoIf("Local/s@OutboundSLA-60de;2", "0?1-fmsetcid,1") in new stack [Sep 23 11:50:52] DEBUG[1762]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'GLOBAL_OUTBOUNDCIDNAME' is '' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:5] GotoIf("Local/s@OutboundSLA-60de;2", "0?1-setgbobname,1") in new stack [Sep 23 11:50:52] DEBUG[1762]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3253 ast_str_retrieve_variable: Result of 'CID_111' is NULL [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3253 ast_str_retrieve_variable: Result of 'CID_111' is NULL [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-trunkdial-failover:6] Set("Local/s@OutboundSLA-60de;2", "CALLERID(num)=111") in new stack [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: Set [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '111' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '3' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-trunkdial-failover:7] GotoIf("Local/s@OutboundSLA-60de;2", "0?1-dial,1") in new stack [Sep 23 11:50:52] DEBUG[1762]: pbx.c:10179 pbx_builtin_gotoif: Not taking any branch [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: GotoIf [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG3' is 'vitel-outbound' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'CID_vitel-outbound' is '203homepho' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '10' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4143 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG3' is 'vitel-outbound' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'CID_vitel-outbound' is '203homepho' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'GLOBAL_OUTBOUNDCID' is '203homepho' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4075 pbx_substitute_variables_helper_full: Function result is '203homepho' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-trunkdial-failover:8] Set("Local/s@OutboundSLA-60de;2", "CALLERID(num)=203homepho") in new stack [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: Set [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Goto' -- Executing [s@macro-trunkdial-failover:9] Goto("Local/s@OutboundSLA-60de;2", "1-dial,1") in new stack -- Goto (macro-trunkdial-failover,1-dial,1) [Sep 23 11:50:52] DEBUG[1762]: app_macro.c:435 _macro_exec: Executed application: Goto [Sep 23 11:50:52] DEBUG[1762]: pbx.c:3256 ast_str_retrieve_variable: Result of 'ARG1' is 'SIP/vitel-outbound/1203mobilep' [Sep 23 11:50:52] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Dial' -- Executing [1-dial@macro-trunkdial-failover:1] Dial("Local/s@OutboundSLA-60de;2", "SIP/vitel-outbound/1203mobilep,,rT") in new stack [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:26659 sip_request_call: Asked to create a SIP channel with formats: 0x1000 (g722) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 050076b727615a554e82c9223d95d71b@192.168.17.1:5060 - INVITE (No RTP) [Sep 23 11:50:52] DEBUG[1762]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x88d2450' [Sep 23 11:50:52] DEBUG[1762]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 16432 for RTP instance '0x88d2450' [Sep 23 11:50:52] DEBUG[1762]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x88d2450' is setup and ready to go [Sep 23 11:50:52] DEBUG[1762]: res_rtp_asterisk.c:2523 ast_rtp_prop_set: Setup RTCP on RTP instance '0x88d2450' == Using SIP RTP CoS mark 5 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:5093 do_setnat: Setting NAT on RTP to On [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:3146 obproxy_get: OBPROXY: Not applying OBproxy to this call [Sep 23 11:50:52] DEBUG[1762]: acl.c:736 ast_ouraddrfor: For destination '64.2.142.187', our source address is '24.128.119.26'. [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 24.128.119.26:5060 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7091 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7092 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7093 sip_new: *** Our capabilities are 0x104 (ulaw|g729) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7094 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7096 sip_new: *** Our preferred formats from the incoming channel are 0x1000 (g722) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:7124 sip_new: This channel will not be able to handle video. [Sep 23 11:50:52] DEBUG[1762]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:50:52] DEBUG[1762]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG4. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG3. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG2. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable ARG1. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Sep 23 11:50:52] DEBUG[1762]: channel.c:6152 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:5638 sip_call: Outgoing Call for 1203mobilep [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:6010 update_call_counter: Call to peer 'vitel-outbound' is 1 out of 2147483647 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:11413 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: False Text flag: False [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x1000 (g722) Audio is at 16432 Adding codec 0x4 (ulaw) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:11709 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729) [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method INVITE - callid 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 0 [ 52]: INVITE sip:1203mobilep@outbound.vitelity.net SIP/2.0 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7e4e0ee6;rport [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 4 [ 43]: To: [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 5 [ 39]: Contact: [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 6 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:50:52 GMT [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer [Sep 23 11:50:52] DEBUG[1762]: chan_sip.c:8521 parse_request: Header 12 [ 96]: Remote-Party-ID: "Cordless 1" ;party=calling;privacy=off;screen=no [Sep 23 11:50:52] DEBUG[1762]: 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=z9hG4bK7e4e0ee6;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as37ff7e13 To: Contact: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:50:52 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 1798449014 1798449014 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 16432 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:50:52] DEBUG[1762]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #239 [Sep 23 11:50:52] DEBUG[1762]: 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 [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[1760]: res_rtp_asterisk.c:1542 process_dtmf_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Sep 23 11:50:52] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:50:52] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:50:52] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 6 (Ringing) [Sep 23 11:50:52] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '6' [Sep 23 11:50:52] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:50:52] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:50:52] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 2 (In use) [Sep 23 11:50:52] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '2' [Sep 23 11:50:52] DEBUG[1761]: app_meetme.c:3595 conf_run: Got ignored control frame on channel Local/s@OutboundSLA-60de;1, f->frametype=4,f->subclass=3 [Sep 23 11:50:52] 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:50:52] 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:64.2.142.187:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7e4e0ee6;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as37ff7e13 To: ;tag=as354ee9e8 Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@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="3cc39c81" Content-Length: 0 <-------------> [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 41]: SIP/2.0 407 Proxy Authentication Required [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7e4e0ee6;received=24.128.119.26;rport=5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as354ee9e8 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 76]: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="3cc39c81" [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 (Checking To) --From tag as37ff7e13 --To-tag as354ee9e8 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3992 __sip_ack: Acked pending invite 102 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #239 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060' of Request 102: Match Found [Sep 23 11:50:52] 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=z9hG4bK7e4e0ee6;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as37ff7e13 To: ;tag=as354ee9e8 Contact: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 --- [Sep 23 11:50:52] 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:50:52] DEBUG[840]: chan_sip.c:19239 do_proxy_auth: Auth attempt 1 on INVITE [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:11413 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: False Text flag: False [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:11414 add_sdp: ** Our prefcodec: 0x1000 (g722) Audio is at 16432 Adding codec 0x4 (ulaw) to SDP Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:11523 add_sdp: -- Done with adding codecs to SDP [Sep 23 11:50:52] 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=z9hG4bK7926c41e;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as37ff7e13 To: Contact: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@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="3cc39c81", response="44f2967e57af42e611fd66816c1d3e85" Date: Sun, 23 Sep 2012 15:50:52 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 1798449014 1798449015 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 16432 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:50:52] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #241 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 64.2.142.187:5060 <--- 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=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as37ff7e13 To: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@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:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 43]: To: [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 (Checking To) --From tag as37ff7e13 --To-tag [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:4064 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #241 - INVITE (got response) [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:4071 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060' Request 103: Found [Sep 23 11:50:52] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 100 to standard invite <--- 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=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as37ff7e13 To: ;tag=as23d84873 Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@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:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as23d84873 [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 (Checking To) --From tag as37ff7e13 --To-tag as23d84873 [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:4071 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060' Request 103: Found [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 180 to standard invite [Sep 23 11:50:54] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: -- SIP/vitel-outbound-00000009 is ringing [Sep 23 11:50:54] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:50:54] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:50:54] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 6 (Ringing) [Sep 23 11:50:54] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '6' [Sep 23 11:50:54] DEBUG[1761]: app_meetme.c:3595 conf_run: Got ignored control frame on channel Local/s@OutboundSLA-60de;1, f->frametype=4,f->subclass=3 [Sep 23 11:50:54] 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. <--- 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=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 From: "Cordless 1" ;tag=as37ff7e13 To: ;tag=as23d84873 Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@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 17844 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:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 24.128.119.26:5060;branch=z9hG4bK7926c41e;received=24.128.119.26;rport=5060 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 58]: To: ;tag=as23d84873 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 19]: Supported: replaces [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 39]: Contact: [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 19]: Content-Length: 287 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Header 12 [ 0]: [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 0 [ 3]: v=0 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 1 [ 38]: o=root 15558 15558 IN IP4 64.2.142.187 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 2 [ 9]: s=session [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 3 [ 21]: c=IN IP4 64.2.142.187 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 4 [ 5]: t=0 0 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 5 [ 30]: m=audio 17844 RTP/AVP 0 18 101 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 8 [ 19]: a=fmtp:18 annexb=no [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8521 parse_request: Body 12 [ 10]: a=ptime:20 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8558 parse_request: Body 13 [ 10]: a=sendrecv --- (12 headers 14 lines) --- [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 (Checking To) --From tag as37ff7e13 --To-tag as23d84873 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:3992 __sip_ack: Acked pending invite 103 [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060' of Request 103: Match Found [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:20102 handle_response_invite: SIP response 200 to standard invite [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Sep 23 11:51:05] 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:51:05] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP s=session... UNSUPPORTED OR FAILED. [Sep 23 11:51:05] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187' into... [Sep 23 11:51:05] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '64.2.142.187' and port ''. [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:8908 process_sdp: Processing session-level SDP c=IN IP4 64.2.142.187... OK. [Sep 23 11:51:05] 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:51:05] 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:51:05] 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:51:05] 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:51:05] 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:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Sep 23 11:51:05] 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:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9179 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Sep 23 11:51:05] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x41504490 [Sep 23 11:51:05] DEBUG[840]: rtp_engine.c:644 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0x41504490 [Sep 23 11:51:05] 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:51:05] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x88d2450' Peer audio RTP is at port 64.2.142.187:17844 [Sep 23 11:51:05] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x41504490 to 0x88d25fc [Sep 23 11:51:05] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x41504490 to 0x88d25fc [Sep 23 11:51:05] DEBUG[840]: rtp_engine.c:522 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x41504490 to 0x88d25fc [Sep 23 11:51:05] DEBUG[840]: res_rtp_asterisk.c:2489 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x88d2450' [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9424 process_sdp: We're settling with these formats: 0x104 (ulaw|g729) [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:9429 process_sdp: We have an owner, now see if we need to change this call [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:14336 build_route: build_route: Contact hop: list_route: hop: [Sep 23 11:51:05] DEBUG[840]: chan_sip.c:10397 reqprep: Strict routing enforced for session 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 set_destination: Parsing for address/port to send to [Sep 23 11:51:05] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187' into... [Sep 23 11:51:05] 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=z9hG4bK43c722cf;rport Max-Forwards: 70 From: "Cordless 1" ;tag=as37ff7e13 To: ;tag=as23d84873 Contact: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 CSeq: 103 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 --- [Sep 23 11:51:05] 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:51:05] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:51:05] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:51:05] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 2 (In use) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '2' -- SIP/vitel-outbound-00000009 answered Local/s@OutboundSLA-60de;2 [Sep 23 11:51:05] DEBUG[1762]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;2 to read format slin [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000009 to write format slin [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000009 to read format slin [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel Local/s@OutboundSLA-60de;2 to write format slin [Sep 23 11:51:05] DEBUG[1762]: features.c:4012 ast_bridge_call: bridge answer set, chan answer set [Sep 23 11:51:05] DEBUG[1762]: features.c:3854 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/vitel-outbound-00000009 since we're bridging [Sep 23 11:51:05] DEBUG[1762]: res_rtp_asterisk.c:828 ast_rtp_update_source: Setting the marker bit due to a source update [Sep 23 11:51:05] DEBUG[1761]: app_meetme.c:3595 conf_run: Got ignored control frame on channel Local/s@OutboundSLA-60de;1, f->frametype=4,f->subclass=20 [Sep 23 11:51:05] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:51:05] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:51:05] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 2 (In use) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '2' [Sep 23 11:51:05] DEBUG[1762]: res_rtp_asterisk.c:1359 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 23 11:51:05] DEBUG[1762]: res_rtp_asterisk.c:1390 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [Sep 23 11:51:05] DEBUG[1762]: channel.c:5954 __ast_channel_masquerade: Planning to masquerade channel SIP/vitel-outbound-00000009 into the structure of Local/s@OutboundSLA-60de;1 [Sep 23 11:51:05] DEBUG[1762]: channel.c:5964 __ast_channel_masquerade: Done planning to masquerade channel SIP/vitel-outbound-00000009 into the structure of Local/s@OutboundSLA-60de;1 [Sep 23 11:51:05] DEBUG[1762]: chan_local.c:557 check_bridge: Masquerading Local/s@OutboundSLA-60de;1 <- SIP/vitel-outbound-00000009 [Sep 23 11:51:05] DEBUG[1762]: chan_local.c:760 local_indicate: Blocked indication -1 [Sep 23 11:51:05] DEBUG[1762]: channel.c:6539 ast_do_masquerade: Actually Masquerading SIP/vitel-outbound-00000009(6) into the structure of Local/s@OutboundSLA-60de;1(5) [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000009 to write format slin [Sep 23 11:51:05] DEBUG[1762]: channel.c:5175 set_format: Set channel SIP/vitel-outbound-00000009 to read format slin [Sep 23 11:51:05] DEBUG[1762]: channel.c:6743 ast_do_masquerade: Putting channel SIP/vitel-outbound-00000009 in slin/slin formats [Sep 23 11:51:05] DEBUG[1762]: chan_sip.c:6645 sip_fixup: SIP Fixup: New owner for dialogue 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060: SIP/vitel-outbound-00000009 (Old parent: Local/s@OutboundSLA-60de;1) [Sep 23 11:51:05] DEBUG[1762]: channel.c:6819 ast_do_masquerade: Done Masquerading SIP/vitel-outbound-00000009 (6) [Sep 23 11:51:05] DEBUG[1762]: res_rtp_asterisk.c:847 ast_rtp_change_source: Changing ssrc from 1112280245 to 87964624 due to a source change [Sep 23 11:51:05] DEBUG[1762]: chan_local.c:654 local_write: Not posting to 'Local/s@OutboundSLA-60de;2' queue since already masqueraded out [Sep 23 11:51:05] DEBUG[1762]: channel.c:7488 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=Local/s@OutboundSLA-60de;2, c1=Local/s@OutboundSLA-60de;1, flags: No,Yes,Yes,Yes [Sep 23 11:51:05] DEBUG[1762]: channel.c:7595 ast_channel_bridge: Bridge stops bridging channels Local/s@OutboundSLA-60de;2 and Local/s@OutboundSLA-60de;1 [Sep 23 11:51:05] DEBUG[1762]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'Local/s@OutboundSLA-60de;2' [Sep 23 11:51:05] DEBUG[1762]: pbx.c:4247 pbx_extension_helper: Launching 'Hangup' -- Executing [h@OutboundSLA:1] Hangup("Local/s@OutboundSLA-60de;2", "") in new stack [Sep 23 11:51:05] DEBUG[1762]: features.c:4393 ast_bridge_call: Spawn extension (OutboundSLA,h,1) exited non-zero on 'Local/s@OutboundSLA-60de;2' == Spawn extension (OutboundSLA, h, 1) exited non-zero on 'Local/s@OutboundSLA-60de;2' [Sep 23 11:51:05] DEBUG[1762]: channel.c:2850 ast_hangup: Hanging up zombie 'Local/s@OutboundSLA-60de;1' [Sep 23 11:51:05] DEBUG[1762]: app_dial.c:3027 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 23 11:51:05] DEBUG[1762]: app_macro.c:429 _macro_exec: Spawn extension (macro-trunkdial-failover,1-dial,1) exited non-zero on 'Local/s@OutboundSLA-60de;2' in macro 'trunkdial-failover' == Spawn extension (macro-trunkdial-failover, 1-dial, 1) exited non-zero on 'Local/s@OutboundSLA-60de;2' in macro 'trunkdial-failover' [Sep 23 11:51:05] DEBUG[1762]: pbx.c:5064 __ast_pbx_run: Spawn extension (OutboundSLA,1203mobilep,1) exited non-zero on 'Local/s@OutboundSLA-60de;2' == Spawn extension (OutboundSLA, 1203mobilep, 1) exited non-zero on 'Local/s@OutboundSLA-60de;2' [Sep 23 11:51:05] DEBUG[1762]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'Local/s@OutboundSLA-60de;2' [Sep 23 11:51:05] DEBUG[1762]: channel.c:2844 ast_hangup: Hanging up channel 'Local/s@OutboundSLA-60de;2' [Sep 23 11:51:05] DEBUG[1761]: app_meetme.c:3127 conf_run: Ooh, something swapped out under us, starting over [Sep 23 11:51:05] DEBUG[1761]: app_meetme.c:2683 conf_run: Placed channel SIP/vitel-outbound-00000009 in DAHDI conf 1023 [Sep 23 11:51:05] 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:51:05] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:51:05] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 1 (Not in use) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '1' [Sep 23 11:51:05] DEBUG[1761]: dsp.c:475 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Sep 23 11:51:05] DEBUG[1761]: dsp.c:475 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Sep 23 11:51:05] 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:51:05] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for Local - s@OutboundSLA [Sep 23 11:51:05] DEBUG[822]: chan_local.c:300 local_devicestate: Checking if extension s@OutboundSLA exists (devicestate) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for Local/s@OutboundSLA - state 1 (Not in use) [Sep 23 11:51:05] DEBUG[822]: devicestate.c:440 devstate_event: device 'Local/s@OutboundSLA' state '1' [Sep 23 11:51:05] 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:51:05] 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:51:08] DEBUG[840]: chan_sip.c:7795 sip_alloc: Allocating new SIP dialog for 6d3d8ab939dfcfb8663577e569c0b3bd@192.168.17.1:5060 - OPTIONS (No RTP) [Sep 23 11:51:08] DEBUG[840]: acl.c:736 ast_ouraddrfor: For destination '192.168.17.4', our source address is '192.168.17.1'. [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 192.168.17.1:5060 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:3075 initialize_initreq: Initializing initreq for method OPTIONS - callid 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 41]: OPTIONS sip:101@192.168.17.4:5060 SIP/2.0 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK29d96ec6;rport [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as22c2070d [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 31]: To: [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 41]: Contact: [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 59]: Call-ID: 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 33]: User-Agent: Asterisk PBX 1.8.15.0 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 35]: Date: Sun, 23 Sep 2012 15:51:08 GMT [Sep 23 11:51:08] 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:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 11 [ 26]: Supported: replaces, timer Reliably Transmitting (NAT) to 192.168.17.4:5060: OPTIONS sip:101@192.168.17.4:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK29d96ec6;rport Max-Forwards: 70 From: "asterisk" ;tag=as22c2070d To: Contact: Call-ID: 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.15.0 Date: Sun, 23 Sep 2012 15:51:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #243 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.17.4:5060 <--- SIP read from UDP:192.168.17.4:5060 ---> SIP/2.0 200 OK To: ;tag=3d870fd433ab4566i0 From: "asterisk" ;tag=as22c2070d Call-ID: 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK29d96ec6 Server: Linksys/PAP2T-5.1.6(LS) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces <-------------> [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 54]: To: ;tag=3d870fd433ab4566i0 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 59]: From: "asterisk" ;tag=as22c2070d [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 59]: Call-ID: 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 17]: CSeq: 102 OPTIONS [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 57]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK29d96ec6 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 31]: Server: Linksys/PAP2T-5.1.6(LS) [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 17]: Content-Length: 0 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 29]: Supported: x-sipura, replaces --- (10 headers 0 lines) --- [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 (Checking To) --From tag as22c2070d --To-tag 3d870fd433ab4566i0 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #243 [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060' of Request 102: Match Found [Sep 23 11:51:08] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060 Really destroying SIP dialog '0fa19fac30f769c749161adf162f8de9@192.168.17.1:5060' Method: OPTIONS <--- SIP read from UDP:64.2.142.187:5060 ---> BYE sip:myuserid@24.128.119.26:5060 SIP/2.0 Via: SIP/2.0/UDP 64.2.142.187:5060;branch=z9hG4bK03dedf60;rport From: ;tag=as23d84873 To: "Cordless 1" ;tag=as37ff7e13 Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 CSeq: 102 BYE User-Agent: packetrino Max-Forwards: 70 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 <-------------> [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 40]: BYE sip:myuserid@24.128.119.26:5060 SIP/2.0 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 64.2.142.187:5060;branch=z9hG4bK03dedf60;rport [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 60]: From: ;tag=as23d84873 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 57]: To: "Cordless 1" ;tag=as37ff7e13 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 60]: Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 13]: CSeq: 102 BYE [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 22]: User-Agent: packetrino [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 39]: X-Asterisk-HangupCause: Normal Clearing [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 30]: X-Asterisk-HangupCauseCode: 16 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 (Checking From) --From tag as23d84873 --To-tag as37ff7e13 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:25254 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:23954 handle_request_bye: Initializing initreq for method BYE - callid 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:51:11] DEBUG[840]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '64.2.142.187:5060' into... [Sep 23 11:51:11] DEBUG[840]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '64.2.142.187' and port '5060'. Sending to 64.2.142.187:5060 (NAT) [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:3088 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:51:11] DEBUG[840]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x88d2450' Scheduling destruction of SIP dialog '584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060' in 6400 ms (Method: BYE) [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:24056 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 64.2.142.187:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.2.142.187:5060;branch=z9hG4bK03dedf60;received=64.2.142.187;rport=5060 From: ;tag=as23d84873 To: "Cordless 1" ;tag=as37ff7e13 Call-ID: 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 CSeq: 102 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:51:11] DEBUG[840]: chan_sip.c:3346 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 64.2.142.187:5060 [Sep 23 11:51:11] WARNING[1761]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/vitel-outbound-00000009 [Sep 23 11:51:11] DEBUG[1761]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '1' [Sep 23 11:51:11] DEBUG[1761]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '1' [Sep 23 11:51:11] DEBUG[1761]: channel.c:2844 ast_hangup: Hanging up channel 'SIP/vitel-outbound-00000009' [Sep 23 11:51:11] DEBUG[1761]: chan_sip.c:6287 sip_hangup: Hangup call SIP/vitel-outbound-00000009, SIP callid 584e14a9070d5cbb68a9905c3946dfc0@24.128.119.26:5060 [Sep 23 11:51:11] DEBUG[1761]: chan_sip.c:6292 sip_hangup: update_call_counter(1203mobilep) - decrement call limit counter on hangup [Sep 23 11:51:11] DEBUG[1761]: chan_sip.c:5905 update_call_counter: Updating call counter for outgoing call [Sep 23 11:51:11] DEBUG[1761]: chan_sip.c:5976 update_call_counter: Call to peer 'vitel-outbound' removed from call limit 2147483647 [Sep 23 11:51:11] DEBUG[1761]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x88d2450' [Sep 23 11:51:11] DEBUG[1760]: devicestate.c:440 devstate_event: device 'meetme:SLA_SLAtrunk1' state '1' [Sep 23 11:51:11] DEBUG[1760]: channel.c:2844 ast_hangup: Hanging up channel 'DAHDI/pseudo-1633340121' [Sep 23 11:51:11] DEBUG[1760]: chan_dahdi.c:6149 dahdi_hangup: dahdi_hangup(DAHDI/pseudo-1633340121) [Sep 23 11:51:11] DEBUG[1760]: chan_dahdi.c:6316 dahdi_hangup: Hangup: channel: -2 index = 0, normal = 34, callwait = -1, thirdcall = -1 [Sep 23 11:51:11] DEBUG[1760]: chan_dahdi.c:6757 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/pseudo-1633340121 [Sep 23 11:51:11] DEBUG[1760]: chan_dahdi.c:4874 update_conf: Updated conferencing on -2, with 0 conference users -- Hungup 'DAHDI/pseudo-1633340121' [Sep 23 11:51:11] WARNING[1760]: app_meetme.c:4558 admin_exec: Conference number 'SLA_SLAtrunk1' not found! == Setting global variable 'MEETMEADMINSTATUS' to 'NOTFOUND' [Sep 23 11:51:11] DEBUG[1760]: devicestate.c:440 devstate_event: device 'SLA:SLAphone111_SLAtrunk1' state '1' [Sep 23 11:51:11] DEBUG[1760]: devicestate.c:440 devstate_event: device 'SLA:SLAphone112_SLAtrunk1' state '1' -- Auto fallthrough, channel 'SIP/111-00000008' status is 'UNKNOWN' [Sep 23 11:51:11] DEBUG[1760]: channel.c:2695 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/111-00000008' [Sep 23 11:51:11] DEBUG[1760]: pbx.c:4247 pbx_extension_helper: Launching 'Hangup' -- Executing [h@DialPlanSLA:1] Hangup("SIP/111-00000008", "") in new stack [Sep 23 11:51:11] DEBUG[1760]: pbx.c:5243 __ast_pbx_run: Spawn extension (DialPlanSLA,h,1) exited non-zero on 'SIP/111-00000008' == Spawn extension (DialPlanSLA, h, 1) exited non-zero on 'SIP/111-00000008' [Sep 23 11:51:11] DEBUG[1760]: channel.c:2844 ast_hangup: Hanging up channel 'SIP/111-00000008' [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:6287 sip_hangup: Hangup call SIP/111-00000008, SIP callid 1888579549@192_168_17_141 [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:6292 sip_hangup: update_call_counter(111) - decrement call limit counter on hangup [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:5905 update_call_counter: Updating call counter for incoming call [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:5976 update_call_counter: Call from peer '111' removed from call limit 10 [Sep 23 11:51:11] DEBUG[1760]: res_rtp_asterisk.c:2563 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8895f68' Scheduling destruction of SIP dialog '1888579549@192_168_17_141' in 6400 ms (Method: ACK) [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:10397 reqprep: Strict routing enforced for session 1888579549@192_168_17_141 set_destination: Parsing for address/port to send to [Sep 23 11:51:11] DEBUG[1760]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.17.141:5060' into... [Sep 23 11:51:11] DEBUG[1760]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.17.141' and port '5060'. set_destination: set destination to 192.168.17.141:5060 Reliably Transmitting (NAT) to 192.168.17.141:5060: BYE sip:111@192.168.17.141:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7190b295;rport Max-Forwards: 70 From: ;tag=as01c5d3a5 To: "Cordless 1" ;tag=3057794908 Call-ID: 1888579549@192_168_17_141 CSeq: 102 BYE User-Agent: Asterisk PBX 1.8.15.0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #248 [Sep 23 11:51:11] DEBUG[1760]: chan_sip.c:3346 __sip_xmit: Trying to put 'BYE sip:111' onto UDP socket destined for 192.168.17.141:5060 [Sep 23 11:51:11] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:51:11] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:51:11] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 1 (Not in use) [Sep 23 11:51:11] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '1' [Sep 23 11:51:11] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - vitel-outbound [Sep 23 11:51:11] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer vitel-outbound [Sep 23 11:51:11] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/vitel-outbound - state 1 (Not in use) [Sep 23 11:51:11] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/vitel-outbound' state '1' [Sep 23 11:51:11] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - pseudo [Sep 23 11:51:11] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for DAHDI/pseudo - state 0 (Unknown) [Sep 23 11:51:11] DEBUG[822]: devicestate.c:440 devstate_event: device 'DAHDI/pseudo' state '0' [Sep 23 11:51:11] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:51:11] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:51:11] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 1 (Not in use) [Sep 23 11:51:11] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '1' [Sep 23 11:51:11] DEBUG[822]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for SIP - 111 [Sep 23 11:51:11] DEBUG[822]: chan_sip.c:26559 sip_devicestate: Checking device state for peer 111 [Sep 23 11:51:11] DEBUG[822]: devicestate.c:460 do_state_change: Changing state for SIP/111 - state 1 (Not in use) [Sep 23 11:51:11] DEBUG[822]: devicestate.c:440 devstate_event: device 'SIP/111' state '1' [Sep 23 11:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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:51:11] 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=z9hG4bK7190b295;rport=5060 From: ;tag=as01c5d3a5 To: "Cordless 1" ;tag=3057794908 Call-ID: 1888579549@192_168_17_141 CSeq: 102 BYE Contact: Supported: replaces User-Agent: C610A IP/42.072.00.000.000 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.17.1:5060;branch=z9hG4bK7190b295;rport=5060 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 2 [ 55]: From: ;tag=as01c5d3a5 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 3 [ 56]: To: "Cordless 1" ;tag=3057794908 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 4 [ 34]: Call-ID: 1888579549@192_168_17_141 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 5 [ 13]: CSeq: 102 BYE [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 6 [ 38]: Contact: [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 7 [ 19]: Supported: replaces [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 8 [ 38]: User-Agent: C610A IP/42.072.00.000.000 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 9 [ 72]: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8521 parse_request: Header 10 [ 17]: Content-Length: 0 --- (11 headers 0 lines) --- [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:8115 find_call: = Looking for Call ID: 1888579549@192_168_17_141 (Checking To) --From tag as01c5d3a5 --To-tag 3057794908 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:3997 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #248 [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:4030 __sip_ack: Stopping retransmission on '1888579549@192_168_17_141' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived [Sep 23 11:51:11] DEBUG[840]: chan_sip.c:6053 sip_destroy: Destroying SIP dialog 1888579549@192_168_17_141 Really destroying SIP dialog '1888579549@192_168_17_141' Method: ACK [Sep 23 11:51:11] DEBUG[840]: rtp_engine.c:298 instance_destructor: Destroyed RTP instance '0x8895f68' pbx*CLI>