[root@endev ~]# asterisk -r Asterisk 1.8.12.0, Copyright (C) 1999 - 2012 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= Connected to Asterisk 1.8.12.0 currently running on endev (pid = 14998) Verbosity is at least 9 Core debug is at least 9 [Jul 11 09:47:45] DEBUG[15012]: chan_sip.c:3885 __sip_autodestruct: Auto destroying SIP dialog '921932177@xx.xx.xx.xx' [Jul 11 09:47:45] DEBUG[15012]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 921932177@xx.xx.xx.xx Really destroying SIP dialog '921932177@xx.xx.xx.xx' Method: OPTIONS <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> INVITE sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Date: Tue, 10 Jul 2012 23:47:48 GMT CSeq: 2 INVITE Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 User-Agent: Ekiga/3.2.6 From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar To: Contact: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx", algorithm=MD5, response="41634434a804b7e5eb147c904857e7cf" Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING Content-Type: application/sdp Content-Length: 318 Max-Forwards: 69 X-Product-RURI: sip:301@xx.xx.xx.xx X-Product-Source: yy.yy.yy.yy:5071 v=0 o=- 1341964067 1 IN IP4 yy.yy.yy.yy s=Opal SIP Session c=IN IP4 yy.yy.yy.yy t=0 0 m=audio 10152 RTP/AVP 0 8 3 101 120 a=sendrecv a=rtpmap:0 PCMU/8000/1 a=rtpmap:8 PCMA/8000/1 a=rtpmap:3 gsm/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16,32,36 a=rtpmap:120 NSE/8000 a=fmtp:120 192-193 <-------------> [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 53]: INVITE sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Record-Route: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 35]: Date: Tue, 10 Jul 2012 23:47:48 GMT [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 14]: CSeq: 2 INVITE [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [122]: Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 23]: User-Agent: Ekiga/3.2.6 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 88]: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 54]: Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 25]: To: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [ 42]: Contact: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 11 [212]: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx", algorithm=MD5, response="41634434a804b7e5eb147c904857e7cf" [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 12 [ 77]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 14 [ 19]: Content-Length: 318 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 15 [ 16]: Max-Forwards: 69 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 16 [ 36]: X-Product-RURI: sip:301@xx.xx.xx.xx [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 17 [ 38]: X-Product-Source: yy.yy.yy.yy:5071 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 18 [ 0]: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 0 [ 3]: v=0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 1 [ 38]: o=- 1341964067 1 IN IP4 yy.yy.yy.yy [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 2 [ 18]: s=Opal SIP Session [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 3 [ 23]: c=IN IP4 yy.yy.yy.yy [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 4 [ 5]: t=0 0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 5 [ 35]: m=audio 10152 RTP/AVP 0 8 3 101 120 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 6 [ 10]: a=sendrecv [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 7 [ 22]: a=rtpmap:0 PCMU/8000/1 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 8 [ 22]: a=rtpmap:8 PCMA/8000/1 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 9 [ 21]: a=rtpmap:3 gsm/8000/1 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 11 [ 21]: a=fmtp:101 0-16,32,36 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 12 [ 21]: a=rtpmap:120 NSE/8000 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8533 parse_request: Body 13 [ 18]: a=fmtp:120 192-193 --- (18 headers 14 lines) --- [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar (Checking From) --From tag 28216a52-57c9-e111-9989-0022681012a3 --To-tag [Jul 11 09:47:48] DEBUG[15012]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 72276a52-57c9-e111-9989-0022681012a3@scimitar - INVITE (No RTP) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:25096 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:22486 handle_request_invite: Initializing initreq for method INVITE - callid 72276a52-57c9-e111-9989-0022681012a3@scimitar Using INVITE request as basis request - 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Jul 11 09:47:48] DEBUG[15012]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15012]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000103' AND host = 'dynamic' [Jul 11 09:47:48] DEBUG[15012]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15012]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000103' Found peer 'product-local' for '1000103' from xx.xx.xx.xx:5060 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8cb2cb0' [Jul 11 09:47:48] DEBUG[15012]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 13490 for RTP instance '0x8cb2cb0' [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0x8cb2cb0' is setup and ready to go [Jul 11 09:47:48] DEBUG[15012]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8cb2cb0' == Using SIP RTP CoS mark 5 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to On [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP o=- 1341964067 1 IN IP4 yy.yy.yy.yy... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP s=Opal SIP Session... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'yy.yy.yy.yy' into... [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'yy.yy.yy.yy' and port ''. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP c=IN IP4 yy.yy.yy.yy... OK. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 0 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x40af7440 Found RTP audio format 8 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x40af7440 Found RTP audio format 3 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x40af7440 Found RTP audio format 101 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x40af7440 Found RTP audio format 120 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Found audio description format PCMU for ID 0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000/1... OK. Found audio description format PCMA for ID 8 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000/1... OK. Found audio description format gsm for ID 3 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 gsm/8000/1... OK. Found audio description format telephone-event for ID 101 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16,32,36... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:604 ast_rtp_codecs_payloads_unset: Unsetting payload 120 on 0x40af7440 Found unknown media description format NSE for ID 120 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:120 NSE/8000... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=fmtp:120 192-193... UNSUPPORTED. [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x40af7440 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 3 on 0x40af7440 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x40af7440 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x40af7440 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jul 11 09:47:48] DEBUG[15012]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8cb2cb0' Peer audio RTP is at port yy.yy.yy.yy:10152 [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x40af7440 to 0x8cb2e5c [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x40af7440 to 0x8cb2e5c [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x40af7440 to 0x8cb2e5c [Jul 11 09:47:48] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x40af7440 to 0x8cb2e5c [Jul 11 09:47:48] DEBUG[15012]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x8cb2cb0' [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:9354 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:22623 handle_request_invite: Checking SIP call limits for device [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:5900 update_call_counter: Updating call counter for incoming call [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:48] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Looking for 301 in from-internal (domain xx.xx.xx.xx) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7070 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7071 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7072 sip_new: *** Our capabilities are 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7073 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:7103 sip_new: This channel will not be able to handle video. [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:14214 build_route: build_route: Record-Route hop: list_route: hop: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:22922 handle_request_invite: SIP/product-local-00000002: New call is still down.... Trying... <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 2 INVITE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Jul 11 09:47:48] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer product-local [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Jul 11 09:47:48] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/product-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 11 09:47:48] DEBUG[15273]: pbx.c:4230 pbx_extension_helper: Launching 'Set' -- Executing [301@from-internal:1] Set("SIP/product-local-00000002", "CALLERPRES()=allowed") in new stack [Jul 11 09:47:48] DEBUG[15273]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [301@from-internal:2] AGI("SIP/product-local-00000002", "agi://127.0.0.1/product?stype=internal") in new stack AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: product?stype=internal [Jul 11 09:47:48] DEBUG[15273]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal AGI Tx >> agi_channel: SIP/product-local-00000002 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1341964068.6 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 301 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: 301 AGI Tx >> agi_priority: 2 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092184976 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:48 2012 (1341964068)" 9 > agi://127.0.0.1/product?stype=internal: AGI starting at Wed Jul 11 09:47:48 2012 (1341964068) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is NULL AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE __PRODUCT-CALLID "1341964068.6" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCREEN [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-SCREEN' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERTED [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERTED' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERSION [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERSION' is NULL AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE __PRODUCT-MUSIC "default" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.132 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CUTOFF [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-CUTOFF' is NULL AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.133 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (72276a52-57c9-e111-9989-0022681012a3@scimitar) AGI Rx << VERBOSE "SIP Call-ID is: 72276a52-57c9-e111-9989-0022681012a3@scimitar" 9 > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: 72276a52-57c9-e111-9989-0022681012a3@scimitar AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCUSTOMER [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-SCUSTOMER' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE SIP_HEADER(X-Product-Source) AGI Tx >> 200 result=1 (yy.yy.yy.yy:5071) AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-INTERNAL [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-PRESENTATION-INTERNAL' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-EXTERNAL [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-PRESENTATION-EXTERNAL' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE SIP_HEADER(X-Product-External) AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-TRANSFER-PHONE [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-TRANSFER-PHONE' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-TRANSFER-CUSTOMER [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-TRANSFER-CUSTOMER' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE SIP_HEADER(Proxy-Authorization) AGI Tx >> 200 result=1 (Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx", algorithm=MD5, response="41634434a804b7e5eb147c904857e7cf") AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Resolving type '', number '301', old '', forward 1 for channel SIP/product-local-00000002" 5 > agi://127.0.0.1/product?stype=internal: Resolving type '', number '301', old '', forward 1 for channel SIP/product-local-00000002 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DIVERSION "301" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Resolving type 'huntgroup', number '1', old '', forward 2 for channel SIP/product-local-00000002" 5 > agi://127.0.0.1/product?stype=internal: Resolving type 'huntgroup', number '1', old '', forward 2 for channel SIP/product-local-00000002 AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-QUEUE [Jul 11 09:47:48] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-QUEUE' is NULL AGI Tx >> 200 result=0 AGI Rx << VERBOSE "Writing entry to active table for 1341964068.6, phone:1000103 - huntgroup:1." 9 > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1341964068.6, phone:1000103 - huntgroup:1. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (72276a52-57c9-e111-9989-0022681012a3@scimitar) AGI Rx << GET VARIABLE CALLERID(name) AGI Tx >> 200 result=1 (David's Ekiga) AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.158 EST. AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DCUSTOMER "3" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DTYPE "huntgroup" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DNUMBER "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CALLERID(number) "1000103" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-CUSTOMER "3" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-INTERNAL "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-EXTERNAL "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CUTOFF "86400" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CALLERID-EXTERNAL "" AGI Tx >> 200 result=1 AGI Rx << EXEC Ringing "" -- AGI Script Executing Application: (Ringing) Options: () <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: ;tag=as7c647729 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 2 INVITE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 11 09:47:48] DEBUG[15273]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.xx.xx:5060 AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE __PRODUCT-SCUSTOMER "3" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-STYPE "huntgroup" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-SNUMBER "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CTYPE-1 "phone" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CNUMBER-1 "1000101" AGI Tx >> 200 result=1 AGI Rx << EXEC Dial "Local/1@product-call-exten/n,10,M(product-answered^0^1341964068.6)oir" -- AGI Script Executing Application: (Dial) Options: (Local/1@product-call-exten/n,10,M(product-answered^0^1341964068.6)oir) [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CNUMBER-1. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CTYPE-1. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SNUMBER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-STYPE. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SCUSTOMER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLERID-EXTERNAL. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CUTOFF. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-EXTERNAL. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-INTERNAL. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-CUSTOMER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLEE. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DNUMBER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DTYPE. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DCUSTOMER. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DIVERSION. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-MUSIC. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLID. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jul 11 09:47:48] DEBUG[15273]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called Local/1@product-call-exten/n <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: ;tag=as7c647729 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 2 INVITE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 11 09:47:48] DEBUG[15273]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-SCUSTOMER' is '3' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-STYPE' is 'huntgroup' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-SNUMBER' is '1' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is '1' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CTYPE-1' is 'phone' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is '1' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CNUMBER-1' is '1000101' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is '1' [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-APPEND-CALLERID-1' is NULL [Jul 11 09:47:48] DEBUG[15275]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [1@product-call-exten:1] AGI("Local/1@product-call-exten-115b;2", "agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1") in new stack AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1 [Jul 11 09:47:48] DEBUG[15275]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1 AGI Tx >> agi_channel: Local/1@product-call-exten-115b;2 AGI Tx >> agi_language: en AGI Tx >> agi_type: Local AGI Tx >> agi_uniqueid: 1341964068.8 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: unknown AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: product-call-exten AGI Tx >> agi_extension: 1 AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092434832 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:48 2012 (1341964068)" 9 > agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1: AGI starting at Wed Jul 11 09:47:48 2012 (1341964068) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) AGI Rx << GET VARIABLE PRODUCT-SCREEN [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-SCREEN' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERTED [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERTED' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERSION [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERSION' is '301' AGI Tx >> 200 result=1 (301) AGI Rx << SET VARIABLE __PRODUCT-MUSIC "default" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.180 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CUTOFF [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CUTOFF' is '86400' AGI Tx >> 200 result=1 (86400) AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.180 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-INTERNAL [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-PRESENTATION-INTERNAL' is '1' AGI Tx >> 200 result=1 (1) AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-EXTERNAL [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-PRESENTATION-EXTERNAL' is '1' AGI Tx >> 200 result=1 (1) AGI Rx << GET VARIABLE PRODUCT-TRANSFER-PHONE [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-TRANSFER-PHONE' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-CALLERID-EXTERNAL [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLERID-EXTERNAL' is '' AGI Tx >> 200 result=1 () AGI Rx << VERBOSE "Resolving type 'phone', number '1000101', old '', forward 1 for channel Local/1@product-call-exten-115b;2" 5 > agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1: Resolving type 'phone', number '1000101', old '', forward 1 for channel Local/1@product-call-exten-115b;2 AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-QUEUE [Jul 11 09:47:48] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-QUEUE' is NULL AGI Tx >> 200 result=0 AGI Rx << VERBOSE "Writing entry to active table for 1341964068.8, huntgroup:1 - phone:1000101." 9 > agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1: Writing entry to active table for 1341964068.8, huntgroup:1 - phone:1000101. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE CALLERID(name) AGI Tx >> 200 result=1 (David's Ekiga) AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-07-12 09:47:48.190 EST. AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DCUSTOMER "3" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DTYPE "phone" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DNUMBER "1000101" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CALLERID(number) "1000103" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-CUSTOMER "3" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-INTERNAL "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-EXTERNAL "1" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CUTOFF "86400" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __SIPADDHEADER06 "Diversion: " AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PHONE-DOMAIN "xx.xx.xx.xx:5060" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PHONE-OPTS "oitM(product-answered^0^1341964068.8)" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __SIPADDHEADER11 "X-Product-Uniqueid: 1341964068.8" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-PHONE "1000101" AGI Tx >> 200 result=1 AGI Rx << EXEC Dial "Local/1000101@product-phone/n,3600,o" -- AGI Script Executing Application: (Dial) Options: (Local/1000101@product-phone/n,3600,o) [Jul 11 09:47:48] DEBUG[15275]: rtp_engine.c:1408 ast_rtp_instance_early_bridge_make_compatible: Can't find native functions for channel 'Local/1000101@product-phone-1ae0;1' [Jul 11 09:47:48] DEBUG[15275]: rtp_engine.c:1469 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'Local/1000101@product-phone-1ae0;1' with that of 'Local/1@product-call-exten-115b;2' [Jul 11 09:47:48] DEBUG[15275]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6146 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-PHONE. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER11. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PHONE-OPTS. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PHONE-DOMAIN. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER06. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CUTOFF. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-EXTERNAL. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-INTERNAL. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-CUSTOMER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLEE. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DNUMBER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DTYPE. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DCUSTOMER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-MUSIC. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CNUMBER-1. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CTYPE-1. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SNUMBER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-STYPE. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SCUSTOMER. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLERID-EXTERNAL. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DIVERSION. [Jul 11 09:47:48] DEBUG[15275]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLID. -- Called Local/1000101@product-phone/n [Jul 11 09:47:48] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-MUSIC' is 'default' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:4126 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:4230 pbx_extension_helper: Launching 'GotoIf' -- Executing [1000101@product-phone:1] GotoIf("Local/1000101@product-phone-1ae0;2", "0?3") in new stack [Jul 11 09:47:48] DEBUG[15277]: pbx.c:10151 pbx_builtin_gotoif: Not taking any branch [Jul 11 09:47:48] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-MUSIC' is 'default' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:4230 pbx_extension_helper: Launching 'SetMusicOnHold' -- Executing [1000101@product-phone:2] SetMusicOnHold("Local/1000101@product-phone-1ae0;2", "default") in new stack [Jul 11 09:47:48] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is '1000101' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-PHONE-DOMAIN' is 'xx.xx.xx.xx:5060' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-PHONE-OPTS' is 'oitM(product-answered^0^1341964068.8)' [Jul 11 09:47:48] DEBUG[15277]: pbx.c:4230 pbx_extension_helper: Launching 'Dial' -- Executing [1000101@product-phone:3] Dial("Local/1000101@product-phone-1ae0;2", "SIP/1000101@xx.xx.xx.xx:5060,3600,oitM(product-answered^0^1341964068.8)") in new stack [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:26465 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 3604db4919b0bfd850ee0a2879d48ec7@xx.xx.xx.xx:5070 - INVITE (No RTP) [Jul 11 09:47:48] DEBUG[15277]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15277]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' [Jul 11 09:47:48] DEBUG[15277]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15277]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Jul 11 09:47:48] DEBUG[15277]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8c9d800' [Jul 11 09:47:48] DEBUG[15277]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 19704 for RTP instance '0x8c9d800' [Jul 11 09:47:48] DEBUG[15277]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0x8c9d800' is setup and ready to go [Jul 11 09:47:48] DEBUG[15277]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8c9d800' == Using SIP RTP CoS mark 5 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to On [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:3144 obproxy_get: OBPROXY: Not applying OBproxy to this call [Jul 11 09:47:48] DEBUG[15277]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5060' into... [Jul 11 09:47:48] DEBUG[15277]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port '5060'. [Jul 11 09:47:48] DEBUG[15277]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7070 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7071 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7072 sip_new: *** Our capabilities are 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7073 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7075 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:7103 sip_new: This channel will not be able to handle video. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6146 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-PHONE. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER11. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PHONE-OPTS. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PHONE-DOMAIN. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable SIPADDHEADER06. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CUTOFF. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-EXTERNAL. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-INTERNAL. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-CUSTOMER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLEE. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable LIMIT_PLAYAUDIO_CALLER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DNUMBER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DTYPE. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DCUSTOMER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-MUSIC. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CNUMBER-1. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CTYPE-1. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SNUMBER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-STYPE. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-SCUSTOMER. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLERID-EXTERNAL. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DIVERSION. [Jul 11 09:47:48] DEBUG[15277]: channel.c:6142 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLID. [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:5637 sip_call: Outgoing Call for 1000101 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:5900 update_call_counter: Updating call counter for outgoing call [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:12263 transmit_invite: Adding SIP Header "X-Product-Uniqueid" with content :1341964068.8: [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:12263 transmit_invite: Adding SIP Header "Diversion" with content :: [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:11344 add_sdp: ** Our capability: 0x1cee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|ilbc|g722) Video flag: False Text flag: False [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 19704 Adding codec 0x4 (ulaw) to SDP Adding codec 0x1000 (g722) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x40 (slin) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x800 (g726) to SDP Adding codec 0x20 (adpcm) to SDP Adding codec 0x80 (lpc10) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:11454 add_sdp: -- Done with adding codecs to SDP [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:11640 add_sdp: Done building SDP. Settling with this capability: 0x1cee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|ilbc|g722) [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method INVITE - callid 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 0 [ 43]: INVITE sip:1000101@xx.xx.xx.xx:5060 SIP/2.0 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 1 [ 62]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK7bad4e73;rport [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 3 [ 67]: From: "David's Ekiga" ;tag=as0c67409e [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 4 [ 34]: To: [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 5 [ 39]: Contact: [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 6 [ 58]: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 8 [ 20]: User-Agent: Product [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 9 [ 35]: Date: Tue, 10 Jul 2012 23:47:48 GMT [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 11 [ 26]: Supported: replaces, timer [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 12 [ 33]: X-Product-Uniqueid: 1341964068.8 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 13 [ 26]: Diversion: [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:8496 parse_request: Header 14 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to xx.xx.xx.xx:5060: INVITE sip:1000101@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK7bad4e73;rport Max-Forwards: 70 From: "David's Ekiga" ;tag=as0c67409e To: Contact: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 CSeq: 102 INVITE User-Agent: Product Date: Tue, 10 Jul 2012 23:47:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-Product-Uniqueid: 1341964068.8 Diversion: Content-Type: application/sdp Content-Length: 452 v=0 o=root 597259009 597259009 IN IP4 xx.xx.xx.xx s=Asterisk PBX 1.8.12.0 c=IN IP4 xx.xx.xx.xx t=0 0 m=audio 19704 RTP/AVP 0 9 8 10 3 111 5 7 97 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:10 L16/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:7 LPC/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #24 [Jul 11 09:47:48] DEBUG[15277]: chan_sip.c:3344 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for xx.xx.xx.xx:5060 <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 100 Giving a try Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK7bad4e73;rport=5070 From: "David's Ekiga" ;tag=as0c67409e To: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 CSeq: 102 INVITE Server: Product SIP proxy Content-Length: 0 Warning: 392 xx.xx.xx.xx:5060 "Noisy feedback tells: pid=16921 req_src_ip=xx.xx.xx.xx req_src_port=5070 in_uri=sip:1000101@xx.xx.xx.xx:5060 out_uri=sip:1000101@yy.yy.yy.yy:5065;transport=udp via_cnt==1" <-------------> [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 24]: SIP/2.0 100 Giving a try [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK7bad4e73;rport=5070 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "David's Ekiga" ;tag=as0c67409e [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 34]: To: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 26]: Server: Product SIP proxy [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 17]: Content-Length: 0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [205]: Warning: 392 xx.xx.xx.xx:5060 "Noisy feedback tells: pid=16921 req_src_ip=xx.xx.xx.xx req_src_port=5070 in_uri=sip:1000101@xx.xx.xx.xx:5060 out_uri=sip:1000101@yy.yy.yy.yy:5065;transport=udp via_cnt==1" --- (9 headers 0 lines) --- [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 (Checking To) --From tag as0c67409e --To-tag [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:4063 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #24 - INVITE (got response) [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' Request 102: Found [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:19947 handle_response_invite: SIP response 100 to standard invite -- Called SIP/1000101@xx.xx.xx.xx:5060 <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK7bad4e73;rport=5070 From: "David's Ekiga" ;tag=as0c67409e To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 Date: Tue, 10 Jul 2012 23:52:21 GMT CSeq: 102 INVITE Server: Cisco-CP7960G/8.0 Contact: Record-Route: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 <-------------> [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK7bad4e73;rport=5070 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "David's Ekiga" ;tag=as0c67409e [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 72]: To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [ 35]: Date: Tue, 10 Jul 2012 23:52:21 GMT [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 16]: CSeq: 102 INVITE [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 25]: Server: Cisco-CP7960G/8.0 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 56]: Contact: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 53]: Record-Route: [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 11 [107]: Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 (Checking To) --From tag as0c67409e --To-tag 00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' Request 102: Found [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:19947 handle_response_invite: SIP response 180 to standard invite [Jul 11 09:47:48] DEBUG[15012]: chan_sip.c:14214 build_route: build_route: Record-Route hop: list_route: hop: -- SIP/xx.xx.xx.xx:5060-00000003 is ringing [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xx.xx:5060 [Jul 11 09:47:48] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer xx.xx.xx.xx:5060 -- Local/1000101@product-phone-1ae0;1 is ringing -- Local/1@product-call-exten-115b;1 is ringing <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: ;tag=as7c647729 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 2 INVITE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 11 09:47:48] DEBUG[15273]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:48] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' [Jul 11 09:47:48] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:48] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/xx.xx.xx.xx:5060 - state 4 (Invalid) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/xx.xx.xx.xx:5060' state '4' [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000101@product-phone [Jul 11 09:47:48] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1000101@product-phone exists (devicestate) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1000101@product-phone - state 2 (In use) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1000101@product-phone' state '2' [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1@product-call-exten [Jul 11 09:47:48] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1@product-call-exten exists (devicestate) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1@product-call-exten - state 2 (In use) [Jul 11 09:47:48] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1@product-call-exten' state '2' [Jul 11 09:47:48] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/xx.xx.xx.xx:5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jul 11 09:47:48] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1000101@product-phone' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 11 09:47:48] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1@product-call-exten' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK7bad4e73;rport=5070 From: "David's Ekiga" ;tag=as0c67409e To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 Date: Tue, 10 Jul 2012 23:52:22 GMT CSeq: 102 INVITE Server: Cisco-CP7960G/8.0 Contact: Record-Route: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes Supported: replaces,join,norefersub Content-Length: 229 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 22902 0 IN IP4 yy.yy.yy.yy s=SIP Call t=0 0 m=audio 17116 RTP/AVP 8 101 c=IN IP4 yy.yy.yy.yy a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=direction:active <-------------> [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK7bad4e73;rport=5070 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "David's Ekiga" ;tag=as0c67409e [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 72]: To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [ 35]: Date: Tue, 10 Jul 2012 23:52:22 GMT [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 16]: CSeq: 102 INVITE [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 25]: Server: Cisco-CP7960G/8.0 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 56]: Contact: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 53]: Record-Route: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 11 [107]: Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 12 [ 35]: Supported: replaces,join,norefersub [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 13 [ 19]: Content-Length: 229 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 14 [ 29]: Content-Type: application/sdp [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 15 [ 46]: Content-Disposition: session;handling=optional [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 16 [ 0]: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 0 [ 3]: v=0 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 1 [ 43]: o=Cisco-SIPUA 22902 0 IN IP4 yy.yy.yy.yy [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 2 [ 10]: s=SIP Call [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 3 [ 5]: t=0 0 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 4 [ 27]: m=audio 17116 RTP/AVP 8 101 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 5 [ 23]: c=IN IP4 yy.yy.yy.yy [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Body 9 [ 10]: a=sendrecv [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8533 parse_request: Body 10 [ 18]: a=direction:active --- (16 headers 11 lines) --- [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 (Checking To) --From tag as0c67409e --To-tag 00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:3991 __sip_ack: Acked pending invite 102 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' of Request 102: Match Found [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:19947 handle_response_invite: SIP response 200 to standard invite [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP o=Cisco-SIPUA 22902 0 IN IP4 yy.yy.yy.yy... UNSUPPORTED. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8891 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 8 [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x40af7110 Found RTP audio format 101 [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x40af7110 [Jul 11 09:47:50] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'yy.yy.yy.yy' into... [Jul 11 09:47:50] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'yy.yy.yy.yy' and port ''. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP c=IN IP4 yy.yy.yy.yy... OK. Found audio description format PCMA for ID 8 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format telephone-event for ID 101 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9110 process_sdp: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x40af7110 [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x40af7110 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jul 11 09:47:50] DEBUG[15012]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8c9d800' Peer audio RTP is at port yy.yy.yy.yy:17116 [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x40af7110 to 0x8c9d9ac [Jul 11 09:47:50] DEBUG[15012]: rtp_engine.c:518 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x40af7110 to 0x8c9d9ac [Jul 11 09:47:50] DEBUG[15012]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x8c9d800' [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9354 process_sdp: We're settling with these formats: 0x8 (alaw) [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9359 process_sdp: We have an owner, now see if we need to change this call [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:9366 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x8 (alaw) and not 0x4 (ulaw) [Jul 11 09:47:50] DEBUG[15012]: channel.c:5171 set_format: Set channel SIP/xx.xx.xx.xx:5060-00000003 to read format ulaw [Jul 11 09:47:50] DEBUG[15012]: channel.c:5171 set_format: Set channel SIP/xx.xx.xx.xx:5060-00000003 to write format ulaw [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:5900 update_call_counter: Updating call counter for outgoing call [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:14214 build_route: build_route: Record-Route hop: list_route: hop: set_destination: Parsing for address/port to send to [Jul 11 09:47:50] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:50] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. set_destination: set destination to xx.xx.xx.xx:5060 Transmitting (NAT) to xx.xx.xx.xx:5060: ACK sip:1000101@yy.yy.yy.yy:5065;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK34ddf34b;rport Route: Max-Forwards: 70 From: "David's Ekiga" ;tag=as0c67409e To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 Contact: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 CSeq: 102 ACK User-Agent: Product Content-Length: 0 --- [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:3344 __sip_xmit: Trying to put 'ACK sip:100' onto UDP socket destined for xx.xx.xx.xx:5060 -- SIP/xx.xx.xx.xx:5060-00000003 answered Local/1000101@product-phone-1ae0;2 [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG1' is '0' [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG2' is '1341964068.8' [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG3' is NULL [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG4' is NULL [Jul 11 09:47:50] DEBUG[15277]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-product-answered:1] AGI("SIP/xx.xx.xx.xx:5060-00000003", "agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.8&pcallid=&snumber=") in new stack AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: answered?screen=0&puniqueid=1341964068.8&pcallid=&snumber= [Jul 11 09:47:50] DEBUG[15277]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.8&pcallid=&snumber= AGI Tx >> agi_channel: SIP/xx.xx.xx.xx:5060-00000003 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1341964068.11 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: unknown AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: macro-product-answered AGI Tx >> agi_extension: s AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092684688 AGI Tx >> [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xx.xx:5060 [Jul 11 09:47:50] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer xx.xx.xx.xx:5060 AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:50 2012 (1341964070)" 9 > agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.8&pcallid=&snumber=: AGI starting at Wed Jul 11 09:47:50 2012 (1341964070) AGI Tx >> 200 result=1 [Jul 11 09:47:50] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:50] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) [Jul 11 09:47:50] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:50] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/xx.xx.xx.xx:5060 - state 4 (Invalid) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/xx.xx.xx.xx:5060' state '4' [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/xx.xx.xx.xx:5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. AGI Rx << SET VARIABLE MACRO_RESULT "" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-TRANSFERRED-BY [Jul 11 09:47:50] DEBUG[15277]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-TRANSFERRED-BY' is NULL AGI Tx >> 200 result=0 -- AGI Script agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.8&pcallid=&snumber= completed, returning 0 AGI Tx >> HANGUP [Jul 11 09:47:50] DEBUG[15277]: app_macro.c:435 _macro_exec: Executed application: AGI [Jul 11 09:47:50] DEBUG[15277]: app_dial.c:2654 dial_exec_full: Macro exited with status 0 [Jul 11 09:47:50] DEBUG[15277]: features.c:3967 ast_bridge_call: bridge answer set, chan answer set [Jul 11 09:47:50] DEBUG[15277]: features.c:3809 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/xx.xx.xx.xx:5060-00000003 since we're bridging [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update -- Local/1000101@product-phone-1ae0;1 answered Local/1@product-call-exten-115b;2 [Jul 11 09:47:50] DEBUG[15275]: features.c:3967 ast_bridge_call: bridge answer set, chan answer set [Jul 11 09:47:50] DEBUG[15275]: features.c:3809 clear_dialed_interfaces: Removing dialed interfaces datastore on Local/1000101@product-phone-1ae0;1 since we're bridging [Jul 11 09:47:50] DEBUG[15275]: channel.c:7134 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/1000101@product-phone-1ae0;1 [Jul 11 09:47:50] DEBUG[15275]: channel.c:7552 ast_channel_bridge: Bridge stops bridging channels Local/1@product-call-exten-115b;2 and Local/1000101@product-phone-1ae0;1 [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000101@product-phone [Jul 11 09:47:50] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1000101@product-phone exists (devicestate) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1000101@product-phone - state 2 (In use) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1000101@product-phone' state '2' [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000101@product-phone [Jul 11 09:47:50] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1000101@product-phone exists (devicestate) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1000101@product-phone - state 2 (In use) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1000101@product-phone' state '2' [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1@product-call-exten [Jul 11 09:47:50] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1@product-call-exten exists (devicestate) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1@product-call-exten - state 2 (In use) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1@product-call-exten' state '2' -- Local/1@product-call-exten-115b;1 answered SIP/product-local-00000002 [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG1' is '0' [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG2' is '1341964068.6' [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG3' is NULL [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG4' is NULL [Jul 11 09:47:50] DEBUG[15273]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-product-answered:1] AGI("Local/1@product-call-exten-115b;1", "agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.6&pcallid=&snumber=") in new stack AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: answered?screen=0&puniqueid=1341964068.6&pcallid=&snumber= [Jul 11 09:47:50] DEBUG[15273]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.6&pcallid=&snumber= AGI Tx >> agi_channel: Local/1@product-call-exten-115b;1 AGI Tx >> agi_language: en AGI Tx >> agi_type: Local AGI Tx >> agi_uniqueid: 1341964068.7 AGI Tx >> agi_version: 1.8.12.0 [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1@product-call-exten [Jul 11 09:47:50] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1@product-call-exten exists (devicestate) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1@product-call-exten - state 2 (In use) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1@product-call-exten' state '2' AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: unknown AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: macro-product-answered AGI Tx >> agi_extension: s AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092184976 AGI Tx >> [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1000101@product-phone' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1000101@product-phone' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1@product-call-exten' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1@product-call-exten' changed to state '2' (In use) but we don't care because they're not a member of any queue. AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:50 2012 (1341964070)" 9 > agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.6&pcallid=&snumber=: AGI starting at Wed Jul 11 09:47:50 2012 (1341964070) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) AGI Rx << SET VARIABLE MACRO_RESULT "" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-TRANSFERRED-BY [Jul 11 09:47:50] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-TRANSFERRED-BY' is NULL AGI Tx >> 200 result=0 -- AGI Script agi://127.0.0.1/answered?screen=0&puniqueid=1341964068.6&pcallid=&snumber= completed, returning 0 AGI Tx >> HANGUP [Jul 11 09:47:50] DEBUG[15273]: app_macro.c:435 _macro_exec: Executed application: AGI [Jul 11 09:47:50] DEBUG[15273]: app_dial.c:2654 dial_exec_full: Macro exited with status 0 [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:6474 sip_answer: SIP answering channel: SIP/product-local-00000002 [Jul 11 09:47:50] DEBUG[15273]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:11745 transmit_response_with_sdp: Setting framing from config on incoming call [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:11344 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Text flag: True [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 13490 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:11454 add_sdp: -- Done with adding codecs to SDP [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:11640 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) <--- Reliably Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKe4c07252-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: ;tag=as7c647729 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 2 INVITE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 280 v=0 o=root 198642624 198642624 IN IP4 xx.xx.xx.xx s=Asterisk PBX 1.8.12.0 c=IN IP4 xx.xx.xx.xx t=0 0 m=audio 13490 RTP/AVP 0 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #27 [Jul 11 09:47:50] DEBUG[15273]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:50] DEBUG[15273]: features.c:3967 ast_bridge_call: bridge answer set, chan answer set [Jul 11 09:47:50] DEBUG[15273]: features.c:3809 clear_dialed_interfaces: Removing dialed interfaces datastore on Local/1@product-call-exten-115b;1 since we're bridging [Jul 11 09:47:50] DEBUG[15273]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Jul 11 09:47:50] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer product-local [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Jul 11 09:47:50] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:50] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/product-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 11 09:47:50] DEBUG[15273]: res_rtp_asterisk.c:1791 ast_rtcp_read: Got RTCP report of 1 bytes [Jul 11 09:47:50] WARNING[15273]: res_rtp_asterisk.c:2135 ast_rtp_read: RTP Read too short <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> ACK sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Route: CSeq: 2 ACK Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.2 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bK08b8b053-57c9-e111-9989-0022681012a3;rport=5071 From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar To: ;tag=as7c647729 Contact: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx:5070", algorithm=MD5, response="906c454ee23b3be10636af3a396b229a" Content-Length: 0 Max-Forwards: 69 X-Product-RURI: sip:301@xx.xx.xx.xx:5070 X-Product-Source: yy.yy.yy.yy:5071 <-------------> [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 50]: ACK sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Record-Route: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 72]: Route: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 11]: CSeq: 2 ACK [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKaf81.bdaf96a6.2 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [122]: Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bK08b8b053-57c9-e111-9989-0022681012a3;rport=5071 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 88]: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 54]: Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 40]: To: ;tag=as7c647729 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 42]: Contact: [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [217]: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx:5070", algorithm=MD5, response="906c454ee23b3be10636af3a396b229a" [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 11 [ 17]: Content-Length: 0 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 12 [ 16]: Max-Forwards: 69 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 13 [ 41]: X-Product-RURI: sip:301@xx.xx.xx.xx:5070 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 14 [ 38]: X-Product-Source: yy.yy.yy.yy:5071 --- (15 headers 0 lines) --- [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar (Checking From) --From tag 28216a52-57c9-e111-9989-0022681012a3 --To-tag as7c647729 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:25096 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #27 [Jul 11 09:47:50] DEBUG[15012]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '72276a52-57c9-e111-9989-0022681012a3@scimitar' of Response 2: Match Found [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to alaw [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160 [Jul 11 09:47:50] DEBUG[15277]: res_rtp_asterisk.c:1253 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x8c9d800' [Jul 11 09:47:50] DEBUG[15273]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jul 11 09:47:50] DEBUG[15273]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> BYE sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Route: CSeq: 3 BYE Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKbf81.1819c973.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKead71b55-57c9-e111-9989-0022681012a3;rport=5071 From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar To: ;tag=as7c647729 Contact: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx:5070", algorithm=MD5, response="fc404495fd3b9b5e7e879f57e00dd92a" Content-Length: 0 Max-Forwards: 69 X-Product-RURI: sip:301@xx.xx.xx.xx:5070 X-Product-Source: yy.yy.yy.yy:5071 <-------------> [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 50]: BYE sip:301@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 79]: Record-Route: [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 72]: Route: [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 11]: CSeq: 3 BYE [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKbf81.1819c973.0 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [122]: Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKead71b55-57c9-e111-9989-0022681012a3;rport=5071 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 88]: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 54]: Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 40]: To: ;tag=as7c647729 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 42]: Contact: [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [217]: Proxy-Authorization: Digest username="1000103", realm="xx.xx.xx.xx", nonce="4ffcbf420000006adc97b2b23dcc27828e82ab00a5ba07b9", uri="sip:301@xx.xx.xx.xx:5070", algorithm=MD5, response="fc404495fd3b9b5e7e879f57e00dd92a" [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 11 [ 17]: Content-Length: 0 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 12 [ 16]: Max-Forwards: 69 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 13 [ 41]: X-Product-RURI: sip:301@xx.xx.xx.xx:5070 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 14 [ 38]: X-Product-Source: yy.yy.yy.yy:5071 --- (15 headers 0 lines) --- [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar (Checking From) --From tag 28216a52-57c9-e111-9989-0022681012a3 --To-tag as7c647729 [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:25096 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:23795 handle_request_bye: Initializing initreq for method BYE - callid 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:52] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:52] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:3086 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 72276a52-57c9-e111-9989-0022681012a3@scimitar [Jul 11 09:47:52] DEBUG[15012]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8cb2cb0' Scheduling destruction of SIP dialog '72276a52-57c9-e111-9989-0022681012a3@scimitar' in 32000 ms (Method: BYE) [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:23898 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKbf81.1819c973.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5071;received=yy.yy.yy.yy;branch=z9hG4bKead71b55-57c9-e111-9989-0022681012a3;rport=5071 Record-Route: From: "David's Ekiga" ;tag=28216a52-57c9-e111-9989-0022681012a3 To: ;tag=as7c647729 Call-ID: 72276a52-57c9-e111-9989-0022681012a3@scimitar CSeq: 3 BYE Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jul 11 09:47:52] DEBUG[15012]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:52] DEBUG[15273]: channel.c:7093 ast_generic_bridge: Didn't get a frame from channel: SIP/product-local-00000002 [Jul 11 09:47:52] DEBUG[15273]: channel.c:7552 ast_channel_bridge: Bridge stops bridging channels SIP/product-local-00000002 and Local/1@product-call-exten-115b;1 [Jul 11 09:47:52] DEBUG[15273]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-00000002' [Jul 11 09:47:52] DEBUG[15273]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [h@from-internal:1] AGI("SIP/product-local-00000002", "agi://127.0.0.1/end") in new stack [Jul 11 09:47:52] DEBUG[15273]: res_agi.c:3840 agi_exec_full: Hungup channel detected, running agi in dead mode. AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: end [Jul 11 09:47:52] DEBUG[15273]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/end AGI Tx >> agi_channel: SIP/product-local-00000002 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1341964068.6 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 301 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: h AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092184976 AGI Tx >> [Jul 11 09:47:52] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:52 2012 (1341964072)" 9 > agi://127.0.0.1/end: AGI starting at Wed Jul 11 09:47:52 2012 (1341964072) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:52] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) AGI Rx << GET VARIABLE ANSWEREDTIME [Jul 11 09:47:52] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '2' AGI Tx >> 200 result=1 (2) AGI Rx << GET VARIABLE DIALSTATUS [Jul 11 09:47:52] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' AGI Tx >> 200 result=1 (ANSWER) AGI Rx << GET VARIABLE PRODUCT-FAX-FILE [Jul 11 09:47:52] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-FAX-FILE' is NULL AGI Tx >> 200 result=0 <--- SIP read from UDP:xx.xx.xx.xx:46826 ---> OPTIONS sip:xx.xx.xx.xx:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:44618;branch=z9hG4bK.3641f5a1;rport;alias From: sip:sipsak@xx.xx.xx.xx:44618;tag=3094f312 To: sip:xx.xx.xx.xx:5070 Call-ID: 815067922@xx.xx.xx.xx CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.xx.xx:44618 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 36]: OPTIONS sip:xx.xx.xx.xx:5070 SIP/2.0 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP xx.xx.xx.xx:44618;branch=z9hG4bK.3641f5a1;rport;alias [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 47]: From: sip:sipsak@xx.xx.xx.xx:44618;tag=3094f312 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 24]: To: sip:xx.xx.xx.xx:5070 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 30]: Call-ID: 815067922@xx.xx.xx.xx [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [ 15]: CSeq: 1 OPTIONS [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 37]: Contact: sip:sipsak@xx.xx.xx.xx:44618 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 17]: Content-Length: 0 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [ 18]: Accept: text/plain --- (11 headers 0 lines) --- [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 815067922@xx.xx.xx.xx (Checking From) --From tag 3094f312 --To-tag [Jul 11 09:47:53] DEBUG[15012]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 815067922@xx.xx.xx.xx - OPTIONS (No RTP) [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:25096 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jul 11 09:47:53] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Jul 11 09:47:53] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Jul 11 09:47:53] DEBUG[15012]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:44618' into... [Jul 11 09:47:53] DEBUG[15012]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Looking for s in from-external (domain xx.xx.xx.xx) <--- Transmitting (NAT) to xx.xx.xx.xx:46826 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:44618;branch=z9hG4bK.3641f5a1;alias;received=xx.xx.xx.xx;rport=46826 From: sip:sipsak@xx.xx.xx.xx:44618;tag=3094f312 To: sip:xx.xx.xx.xx:5070;tag=as5133fc2c Call-ID: 815067922@xx.xx.xx.xx CSeq: 1 OPTIONS Server: Product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Jul 11 09:47:53] DEBUG[15012]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:46826 Scheduling destruction of SIP dialog '815067922@xx.xx.xx.xx' in 32000 ms (Method: OPTIONS) -- AGI Script agi://127.0.0.1/end completed, returning 0 AGI Tx >> HANGUP [Jul 11 09:47:53] DEBUG[15273]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [h@from-internal:2] AGI("SIP/product-local-00000002", "agi://127.0.0.1/product?stype=internal") in new stack [Jul 11 09:47:53] DEBUG[15273]: res_agi.c:3840 agi_exec_full: Hungup channel detected, running agi in dead mode. AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: product?stype=internal [Jul 11 09:47:53] DEBUG[15273]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal AGI Tx >> agi_channel: SIP/product-local-00000002 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1341964068.6 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 301 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: h AGI Tx >> agi_priority: 2 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092184976 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:53 2012 (1341964073)" 9 > agi://127.0.0.1/product?stype=internal: AGI starting at Wed Jul 11 09:47:53 2012 (1341964073) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:53] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) AGI Rx << GET VARIABLE ANSWEREDTIME [Jul 11 09:47:53] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '2' AGI Tx >> 200 result=1 (2) AGI Rx << GET VARIABLE DIALSTATUS [Jul 11 09:47:53] DEBUG[15273]: pbx.c:3239 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' AGI Tx >> 200 result=1 (ANSWER) AGI Rx << GET VARIABLE PRODUCT-FAX-FILE [Jul 11 09:47:53] DEBUG[15273]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-FAX-FILE' is NULL AGI Tx >> 200 result=0 -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 0 AGI Tx >> HANGUP [Jul 11 09:47:53] DEBUG[15273]: channel.c:2831 ast_hangup: Hanging up channel 'Local/1@product-call-exten-115b;1' [Jul 11 09:47:53] DEBUG[15273]: app_dial.c:2960 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Jul 11 09:47:53] DEBUG[15273]: res_agi.c:3507 run_agi: SIP/product-local-00000002 hungup AGI Tx >> HANGUP [Jul 11 09:47:53] DEBUG[15275]: channel.c:7093 ast_generic_bridge: Didn't get a frame from channel: Local/1@product-call-exten-115b;2 [Jul 11 09:47:53] DEBUG[15275]: channel.c:7552 ast_channel_bridge: Bridge stops bridging channels Local/1@product-call-exten-115b;2 and Local/1000101@product-phone-1ae0;1 [Jul 11 09:47:53] DEBUG[15275]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1@product-call-exten-115b;2' [Jul 11 09:47:53] DEBUG[15275]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [h@product-call-exten:1] AGI("Local/1@product-call-exten-115b;2", "agi://127.0.0.1/end") in new stack [Jul 11 09:47:53] DEBUG[15275]: res_agi.c:3840 agi_exec_full: Hungup channel detected, running agi in dead mode. AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: end [Jul 11 09:47:53] DEBUG[15275]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/end AGI Tx >> agi_channel: Local/1@product-call-exten-115b;2 AGI Tx >> agi_language: en AGI Tx >> agi_type: Local AGI Tx >> agi_uniqueid: 1341964068.8 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: David's Ekiga AGI Tx >> agi_callingpres: 3 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: unknown AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: product-call-exten AGI Tx >> agi_extension: h AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1092434832 AGI Tx >> [Jul 11 09:47:53] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 4 AGI Tx >> HANGUP [Jul 11 09:47:53] ERROR[15273]: utils.c:1164 ast_carefulwrite: write() returned error: Broken pipe [Jul 11 09:47:53] DEBUG[15273]: pbx.c:5047 __ast_pbx_run: Spawn extension (from-internal,301,2) exited non-zero on 'SIP/product-local-00000002' == Spawn extension (from-internal, 301, 2) exited non-zero on 'SIP/product-local-00000002' [Jul 11 09:47:53] DEBUG[15273]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-00000002' [Jul 11 09:47:53] DEBUG[15273]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/product-local-00000002' [Jul 11 09:47:53] DEBUG[15273]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Jul 11 09:47:53] DEBUG[15273]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8cb2cb0' AGI Rx << VERBOSE "AGI starting at Wed Jul 11 09:47:53 2012 (1341964073)" 9 > agi://127.0.0.1/end: AGI starting at Wed Jul 11 09:47:53 2012 (1341964073) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Jul 11 09:47:53] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1341964068.6' AGI Tx >> 200 result=1 (1341964068.6) AGI Rx << GET VARIABLE ANSWEREDTIME [Jul 11 09:47:53] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '3' AGI Tx >> 200 result=1 (3) AGI Rx << GET VARIABLE DIALSTATUS [Jul 11 09:47:53] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' AGI Tx >> 200 result=1 (ANSWER) AGI Rx << GET VARIABLE PRODUCT-FAX-FILE [Jul 11 09:47:53] DEBUG[15275]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-FAX-FILE' is NULL AGI Tx >> 200 result=0 [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1@product-call-exten [Jul 11 09:47:53] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1@product-call-exten exists (devicestate) [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1@product-call-exten - state 1 (Not in use) [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1@product-call-exten' state '1' [Jul 11 09:47:53] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1@product-call-exten' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Jul 11 09:47:53] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer product-local [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Jul 11 09:47:53] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Jul 11 09:47:53] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/product-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- AGI Script agi://127.0.0.1/end completed, returning 0 AGI Tx >> HANGUP [Jul 11 09:47:54] DEBUG[15275]: channel.c:2831 ast_hangup: Hanging up channel 'Local/1000101@product-phone-1ae0;1' [Jul 11 09:47:54] DEBUG[15275]: app_dial.c:2960 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Jul 11 09:47:54] DEBUG[15275]: res_agi.c:3507 run_agi: Local/1@product-call-exten-115b;2 hungup AGI Tx >> HANGUP [Jul 11 09:47:54] DEBUG[15277]: channel.c:7093 ast_generic_bridge: Didn't get a frame from channel: Local/1000101@product-phone-1ae0;2 [Jul 11 09:47:54] DEBUG[15277]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [Jul 11 09:47:54] DEBUG[15277]: channel.c:7552 ast_channel_bridge: Bridge stops bridging channels Local/1000101@product-phone-1ae0;2 and SIP/xx.xx.xx.xx:5060-00000003 [Jul 11 09:47:54] DEBUG[15277]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/xx.xx.xx.xx:5060-00000003' [Jul 11 09:47:54] DEBUG[15277]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Jul 11 09:47:54] DEBUG[15277]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8c9d800' Scheduling destruction of SIP dialog '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' in 32000 ms (Method: INVITE) set_destination: Parsing for address/port to send to [Jul 11 09:47:54] DEBUG[15277]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Jul 11 09:47:54] DEBUG[15277]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. set_destination: set destination to xx.xx.xx.xx:5060 Reliably Transmitting (NAT) to xx.xx.xx.xx:5060: BYE sip:1000101@yy.yy.yy.yy:5065;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK2d0d7002;rport Route: Max-Forwards: 70 From: "David's Ekiga" ;tag=as0c67409e To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 CSeq: 103 BYE User-Agent: Product X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jul 11 09:47:54] DEBUG[15277]: chan_sip.c:3801 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #33 [Jul 11 09:47:54] DEBUG[15277]: chan_sip.c:3344 __sip_xmit: Trying to put 'BYE sip:100' onto UDP socket destined for xx.xx.xx.xx:5060 [Jul 11 09:47:54] DEBUG[15277]: app_dial.c:2960 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jul 11 09:47:54] DEBUG[15277]: pbx.c:5047 __ast_pbx_run: Spawn extension (product-phone,1000101,3) exited non-zero on 'Local/1000101@product-phone-1ae0;2' == Spawn extension (product-phone, 1000101, 3) exited non-zero on 'Local/1000101@product-phone-1ae0;2' [Jul 11 09:47:54] DEBUG[15277]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1000101@product-phone-1ae0;2' [Jul 11 09:47:54] DEBUG[15277]: channel.c:2831 ast_hangup: Hanging up channel 'Local/1000101@product-phone-1ae0;2' AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-PHONE "" AGI Tx >> 200 result=1 [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000101@product-phone [Jul 11 09:47:54] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1000101@product-phone exists (devicestate) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1000101@product-phone - state 1 (Not in use) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1000101@product-phone' state '1' [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xx.xx:5060 [Jul 11 09:47:54] DEBUG[15004]: chan_sip.c:26365 sip_devicestate: Checking device state for peer xx.xx.xx.xx:5060 [Jul 11 09:47:54] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:54] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' [Jul 11 09:47:54] DEBUG[15004]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Jul 11 09:47:54] DEBUG[15004]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for SIP/xx.xx.xx.xx:5060 - state 4 (Invalid) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:438 devstate_event: device 'SIP/xx.xx.xx.xx:5060' state '4' [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000101@product-phone [Jul 11 09:47:54] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1000101@product-phone exists (devicestate) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1000101@product-phone - state 1 (Not in use) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1000101@product-phone' state '1' [Jul 11 09:47:54] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1000101@product-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 11 09:47:54] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'SIP/xx.xx.xx.xx:5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jul 11 09:47:54] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1000101@product-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. AGI Rx << GET VARIABLE DIALSTATUS [Jul 11 09:47:54] DEBUG[15275]: pbx.c:3239 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' AGI Tx >> 200 result=1 (ANSWER) -- AGI Script agi://127.0.0.1/product?scustomer=3&stype=huntgroup&snumber=1&ctype=phone&cnumber=1000101&append_callerid=&loopback=1 completed, returning 4 AGI Tx >> HANGUP [Jul 11 09:47:54] DEBUG[15275]: pbx.c:5047 __ast_pbx_run: Spawn extension (product-call-exten,1,1) exited non-zero on 'Local/1@product-call-exten-115b;2' == Spawn extension (product-call-exten, 1, 1) exited non-zero on 'Local/1@product-call-exten-115b;2' [Jul 11 09:47:54] DEBUG[15275]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1@product-call-exten-115b;2' [Jul 11 09:47:54] DEBUG[15275]: channel.c:2831 ast_hangup: Hanging up channel 'Local/1@product-call-exten-115b;2' [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1@product-call-exten [Jul 11 09:47:54] DEBUG[15004]: chan_local.c:300 local_devicestate: Checking if extension 1@product-call-exten exists (devicestate) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:458 do_state_change: Changing state for Local/1@product-call-exten - state 1 (Not in use) [Jul 11 09:47:54] DEBUG[15004]: devicestate.c:438 devstate_event: device 'Local/1@product-call-exten' state '1' [Jul 11 09:47:54] DEBUG[15036]: app_queue.c:1487 handle_statechange: Device 'Local/1@product-call-exten' 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:xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2d0d7002;rport=5070 From: "David's Ekiga" ;tag=as0c67409e To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 Date: Tue, 10 Jul 2012 23:52:27 GMT CSeq: 103 BYE Server: Cisco-CP7960G/8.0 Content-Length: 0 RTP-RxStat: Dur=5,Pkt=113,Oct=18080,LatePkt=0,LostPkt=0,AvgJit=9 TP-TxStat: Dur=5,Pkt=224,Oct=35840 <-------------> [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2d0d7002;rport=5070 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 2 [ 67]: From: "David's Ekiga" ;tag=as0c67409e [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 3 [ 72]: To: ;tag=00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 4 [ 58]: Call-ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 5 [ 35]: Date: Tue, 10 Jul 2012 23:52:27 GMT [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 6 [ 13]: CSeq: 103 BYE [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 7 [ 25]: Server: Cisco-CP7960G/8.0 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 8 [ 17]: Content-Length: 0 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 9 [ 64]: RTP-RxStat: Dur=5,Pkt=113,Oct=18080,LatePkt=0,LostPkt=0,AvgJit=9 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8496 parse_request: Header 10 [ 35]: RTP-TxStat: Dur=5,Pkt=224,Oct=35840 --- (11 headers 0 lines) --- [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:8089 find_call: = Looking for Call ID: 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 (Checking To) --From tag as0c67409e --To-tag 00170ec855f5c5a826d560a0-7c3170b9 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:3996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #33 [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' of Request 103: Match Found [Jul 11 09:47:54] DEBUG[15012]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070 Really destroying SIP dialog '26d866dd11afcd212ab24e253185801b@xx.xx.xx.xx:5070' Method: INVITE [Jul 11 09:47:54] DEBUG[15012]: rtp_engine.c:294 instance_destructor: Destroyed RTP instance '0x8c9d800' [Jul 11 09:47:55] DEBUG[15012]: chan_sip.c:3885 __sip_autodestruct: Auto destroying SIP dialog '570186264@xx.xx.xx.xx' [Jul 11 09:47:55] DEBUG[15012]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 570186264@xx.xx.xx.xx Really destroying SIP dialog '570186264@xx.xx.xx.xx' Method: OPTIONS endev*CLI> quit [root@endev ~]#