<-------------> [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 36]: OPTIONS sip:xx.xx.xx.xx:5070 SIP/2.0 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP xx.xx.xx.xx:47659;branch=z9hG4bK.14b656ab;rport;alias [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 47]: From: sip:sipsak@xx.xx.xx.xx:47659;tag=2949a0de [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 24]: To: sip:xx.xx.xx.xx:5070 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 30]: Call-ID: 692691166@xx.xx.xx.xx [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 15]: CSeq: 1 OPTIONS [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 37]: Contact: sip:sipsak@xx.xx.xx.xx:47659 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 17]: Content-Length: 0 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 18]: Accept: text/plain --- (11 headers 0 lines) --- [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 692691166@xx.xx.xx.xx (Checking From) --From tag 2949a0de --To-tag [Mar 17 09:31:37] DEBUG[8699]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:3482 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:7694 sip_alloc: Allocating new SIP dialog for 692691166@xx.xx.xx.xx - OPTIONS (No RTP) [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 17 09:31:37] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Mar 17 09:31:37] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:37] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:47659' into... [Mar 17 09:31:37] DEBUG[8699]: 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:51281 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:47659;branch=z9hG4bK.14b656ab;alias;received=xx.xx.xx.xx;rport=51281 From: sip:sipsak@xx.xx.xx.xx:47659;tag=2949a0de To: sip:xx.xx.xx.xx:5070;tag=as7aad1605 Call-ID: 692691166@xx.xx.xx.xx CSeq: 1 OPTIONS Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 17 09:31:37] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:51281 Scheduling destruction of SIP dialog '692691166@xx.xx.xx.xx' in 32000 ms (Method: OPTIONS) <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> INVITE sip:1000103@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK53b6.955376a4.0 Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjP9DDfMRxSsUKh2sBgZnrLYzXFX0sizrq Max-Forwards: 69 From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U To: Contact: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t CSeq: 6693 INVITE Route: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple r1108 / bravo-8 Proxy-Authorization: Digest username="1000104", realm="xx.xx.xx.xx", nonce="4f63bf69000082e640c025ba80d955b071c8eec621a9c966", uri="sip:1000103@xx.xx.xx.xx", response="6ed0b9d2fcd40e7c659f9d6aa89669f8" Content-Type: application/sdp Content-Length: 296 X-Enswitch-RURI: sip:1000103@xx.xx.xx.xx X-Enswitch-Source: yy.yy.yy.yy:56485 v=0 o=- 3540925898 3540925898 IN IP4 192.168.1.2 s=pjmedia c=IN IP4 yy.yy.yy.yy t=0 0 a=X-nat:0 m=audio 4002 RTP/AVP 3 101 a=rtcp:4003 IN IP4 192.168.1.2 a=rtpmap:3 GSM/8000 a=sendrecv a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=direction:active a=oldmediaip:192.168.1.2 <-------------> [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 57]: INVITE sip:1000103@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 75]: Record-Route: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK53b6.955376a4.0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [122]: Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjP9DDfMRxSsUKh2sBgZnrLYzXFX0sizrq [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 16]: Max-Forwards: 69 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 68]: From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 29]: To: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 60]: Contact: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 41]: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 17]: CSeq: 6693 INVITE [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 41]: Route: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [ 46]: Supported: replaces, 100rel, timer, norefersub [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 13 [ 21]: Session-Expires: 1800 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 14 [ 10]: Min-SE: 90 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 15 [ 38]: User-Agent: CSipSimple r1108 / bravo-8 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 16 [201]: Proxy-Authorization: Digest username="1000104", realm="xx.xx.xx.xx", nonce="4f63bf69000082e640c025ba80d955b071c8eec621a9c966", uri="sip:1000103@xx.xx.xx.xx", response="6ed0b9d2fcd40e7c659f9d6aa89669f8" [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 17 [ 29]: Content-Type: application/sdp [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 18 [ 19]: Content-Length: 296 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 19 [ 40]: X-Enswitch-RURI: sip:1000103@xx.xx.xx.xx [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 20 [ 39]: X-Enswitch-Source: yy.yy.yy.yy:56485 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 21 [ 0]: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 0 [ 3]: v=0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 1 [ 44]: o=- 3540925898 3540925898 IN IP4 192.168.1.2 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 2 [ 9]: s=pjmedia [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 3 [ 23]: c=IN IP4 yy.yy.yy.yy [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 4 [ 5]: t=0 0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 5 [ 9]: a=X-nat:0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 6 [ 26]: m=audio 4002 RTP/AVP 3 101 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 7 [ 30]: a=rtcp:4003 IN IP4 192.168.1.2 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 8 [ 19]: a=rtpmap:3 GSM/8000 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 9 [ 10]: a=sendrecv [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 12 [ 18]: a=direction:active [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8458 parse_request: Body 13 [ 24]: a=oldmediaip:192.168.1.2 --- (21 headers 14 lines) --- [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t (Checking From) --From tag Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U --To-tag [Mar 17 09:31:39] DEBUG[8699]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:3482 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 == Using UDPTL CoS mark 5 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:7694 sip_alloc: Allocating new SIP dialog for e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t - INVITE (No RTP) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1613 parse_sip_options: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -replaces- [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: replaces [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -100rel- [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: 100rel [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -timer- [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: timer [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -norefersub- [Mar 17 09:31:39] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: norefersub [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:22266 handle_request_invite: Initializing initreq for method INVITE - callid e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t Using INVITE request as basis request - e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:39] DEBUG[8699]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:39] DEBUG[8699]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000104' AND host = 'dynamic' [Mar 17 09:31:39] DEBUG[8699]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:39] DEBUG[8699]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000104' Found peer 'product-local' for '1000104' from xx.xx.xx.xx:5060 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:345 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xd7783c8' [Mar 17 09:31:39] DEBUG[8699]: res_rtp_asterisk.c:499 ast_rtp_new: Allocated port 15748 for RTP instance '0xd7783c8' [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:354 ast_rtp_instance_new: RTP instance '0xd7783c8' is setup and ready to go [Mar 17 09:31:39] DEBUG[8699]: res_rtp_asterisk.c:2447 ast_rtp_prop_set: Setup RTCP on RTP instance '0xd7783c8' == Using SIP RTP CoS mark 5 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:5043 do_setnat: Setting NAT on RTP to On [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP o=- 3540925898 3540925898 IN IP4 192.168.1.2... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP s=pjmedia... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'yy.yy.yy.yy' into... [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'yy.yy.yy.yy' and port ''. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP c=IN IP4 yy.yy.yy.yy... OK. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP a=X-nat:0... UNSUPPORTED. Found RTP audio format 3 [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x407b03d0 Found RTP audio format 101 [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x407b03d0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtcp:4003 IN IP4 192.168.1.2... UNSUPPORTED. Found audio description format GSM for ID 3 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Found audio description format telephone-event for ID 101 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=oldmediaip:192.168.1.2... UNSUPPORTED. [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 3 on 0x407b03d0 [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x407b03d0 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0x2 (gsm)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Mar 17 09:31:39] DEBUG[8699]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7783c8' Peer audio RTP is at port yy.yy.yy.yy:4002 [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 3 from 0x407b03d0 to 0xd778590 [Mar 17 09:31:39] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x407b03d0 to 0xd778590 [Mar 17 09:31:39] DEBUG[8699]: res_rtp_asterisk.c:2413 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xd7783c8' [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9249 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:9259 process_sdp: We're settling with these formats: 0x2 (gsm) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:22414 handle_request_invite: Checking SIP call limits for device [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:5862 update_call_counter: Updating call counter for incoming call [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:39] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Looking for 1000103 in from-internal (domain xx.xx.xx.xx) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:6987 sip_new: *** Our native formats are 0x2 (gsm) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:6988 sip_new: *** Joint capabilities are 0x2 (gsm) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:6989 sip_new: *** Our capabilities are 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:6990 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:7020 sip_new: This channel will not be able to handle video. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:14012 build_route: build_route: Record-Route hop: list_route: hop: [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:22525 handle_request_invite: Incoming INVITE with 'timer' option supported and "Session-Expires" header. [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:25842 parse_session_expires: Session-Expires: 1800 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:25812 parse_minse: Received Min-SE: 90 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:25710 start_session_timer: Session timer started: 139 - e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:22713 handle_request_invite: SIP/product-local-0000000f: 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=z9hG4bK53b6.955376a4.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjP9DDfMRxSsUKh2sBgZnrLYzXFX0sizrq Record-Route: From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U To: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t CSeq: 6693 INVITE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newchannel Privilege: call,all Timestamp: 1331937099.433947 Channel: SIP/product-local-0000000f ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1000104 CallerIDName: AccountCode: Exten: 1000103 Context: from-internal Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.434105 Channel: SIP/product-local-0000000f Variable: SIPURI Value: sip:1000104@yy.yy.yy.yy:56485 Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.434119 Channel: SIP/product-local-0000000f Variable: SIPDOMAIN Value: xx.xx.xx.xx Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.434131 Channel: SIP/product-local-0000000f Variable: SIPCALLID Value: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937099.434458 Channel: SIP/product-local-0000000f ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: ConnectedLineName: Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:39] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:39] DEBUG[8708]: 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. [Mar 17 09:31:39] DEBUG[10813]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [1000103@from-internal:1] AGI("SIP/product-local-0000000f", "agi://127.0.0.1/product?stype=internal") in new stack [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937099.441363 Channel: SIP/product-local-0000000f Context: from-internal Extension: 1000103 Priority: 1 Application: AGI AppData: agi://127.0.0.1/product?stype=internal Uniqueid: 1331937099.35 AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: product?stype=internal [Mar 17 09:31:39] DEBUG[10813]: 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-0000000f AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1331937099.35 AGI Tx >> agi_version: 1.8.9.2 AGI Tx >> agi_callerid: 1000104 AGI Tx >> agi_calleridname: unknown AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 1000103 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: 1000103 AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1113422144 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Sat Mar 17 09:31:39 2012 (1331937099)" 9 > agi://127.0.0.1/product?stype=internal: AGI starting at Sat Mar 17 09:31:39 2012 (1331937099) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Mar 17 09:31:39] DEBUG[10813]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is NULL AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE __PRODUCT-CALLID "1331937099.35" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.453695 Channel: SIP/product-local-0000000f Variable: __PRODUCT-CALLID Value: 1331937099.35 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCREEN [Mar 17 09:31:39] DEBUG[10813]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-SCREEN' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERTED [Mar 17 09:31:39] DEBUG[10813]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERTED' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERSION [Mar 17 09:31:39] DEBUG[10813]: 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" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.456220 Channel: SIP/product-local-0000000f Variable: __PRODUCT-MUSIC Value: default Uniqueid: 1331937099.35 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" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.456548 Channel: SIP/product-local-0000000f Variable: __TRANSFER_CONTEXT Value: from-internal Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-03-18 09:31:39.457 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CUTOFF [Mar 17 09:31:39] DEBUG[10813]: 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-03-18 09:31:39.457 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t) AGI Rx << VERBOSE "SIP Call-ID is: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t" 9 > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCUSTOMER [Mar 17 09:31:39] DEBUG[10813]: 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-Enswitch-Source) AGI Tx >> 200 result=1 (yy.yy.yy.yy:56485) AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-INTERNAL [Mar 17 09:31:39] DEBUG[10813]: 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 [Mar 17 09:31:39] DEBUG[10813]: 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-Enswitch-External) AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-TRANSFER-PHONE [Mar 17 09:31:39] DEBUG[10813]: 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 [Mar 17 09:31:39] DEBUG[10813]: 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="1000104", realm="xx.xx.xx.xx", nonce="4f63bf69000082e640c025ba80d955b071c8eec621a9c966", uri="sip:1000103@xx.xx.xx.xx", response="6ed0b9d2fcd40e7c659f9d6aa89669f8") AGI Rx << SET VARIABLE __PRODUCT-MUSIC "7" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.466192 Channel: SIP/product-local-0000000f Variable: __PRODUCT-MUSIC Value: 7 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(musicclass) "7" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Resolving type '', number '1000103', old '', forward 1 for channel SIP/product-local-0000000f" 5 > agi://127.0.0.1/product?stype=internal: Resolving type '', number '1000103', old '', forward 1 for channel SIP/product-local-0000000f AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Starting recording group '1' expires '1332023499' file '/var/lib/product/recordings/9/1/2012/03/17/record_133193709935_9372'" 9 > agi://127.0.0.1/product?stype=internal: Starting recording group '1' expires '1332023499' file '/var/lib/product/recordings/9/1/2012/03/17/record_133193709935_9372' AGI Tx >> 200 result=1 AGI Rx << EXEC Monitor "gsm,/var/lib/product/recordings/9/1/2012/03/17/record_133193709935_9372" -- AGI Script Executing Application: (Monitor) Options: (gsm,/var/lib/product/recordings/9/1/2012/03/17/record_133193709935_9372) AGI Tx >> 200 result=0 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.476927 Channel: SIP/product-local-0000000f Variable: __MONITORED Value: true Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: MonitorStart Privilege: call,all Timestamp: 1331937099.476932 Channel: SIP/product-local-0000000f Uniqueid: 1331937099.35 AGI Rx << VERBOSE "Writing entry to active table for 1331937099.35, phone:1000104 - phone:1000103." 9 > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1331937099.35, phone:1000104 - phone:1000103. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t) AGI Rx << GET VARIABLE CALLERID(name) AGI Tx >> 200 result=1 () AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-03-18 09:31:39.483 EST. AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DCUSTOMER "9" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.483452 Channel: SIP/product-local-0000000f Variable: __PRODUCT-DCUSTOMER Value: 9 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DTYPE "phone" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.483729 Channel: SIP/product-local-0000000f Variable: __PRODUCT-DTYPE Value: phone Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DNUMBER "1000103" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.484103 Channel: SIP/product-local-0000000f Variable: __PRODUCT-DNUMBER Value: 1000103 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CALLERID(number) "1000104" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-CUSTOMER "9" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.485544 Channel: SIP/product-local-0000000f Variable: __PRODUCT-TRANSFER-CUSTOMER Value: 9 Uniqueid: 1331937099.35 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 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.485820 Channel: SIP/product-local-0000000f Variable: __PRODUCT-PRESENTATION-INTERNAL Value: 1 Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.486176 Channel: SIP/product-local-0000000f Variable: __PRODUCT-PRESENTATION-EXTERNAL Value: 1 Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.486289 Channel: SIP/product-local-0000000f Variable: __PRODUCT-CUTOFF Value: 86400 Uniqueid: 1331937099.35 AGI Rx << SET VARIABLE __PRODUCT-PHONE-DOMAIN "xx.xx.xx.xx:5060" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.490260 Channel: SIP/product-local-0000000f Variable: __PRODUCT-PHONE-DOMAIN Value: xx.xx.xx.xx:5060 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PHONE-OPTS "ortM(product-answered^0^1331937099.35)" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.490576 Channel: SIP/product-local-0000000f Variable: __PRODUCT-PHONE-OPTS Value: ortM(product-answered^0^1331937099.35) Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-PHONE "1000103" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.490938 Channel: SIP/product-local-0000000f Variable: __PRODUCT-TRANSFER-PHONE Value: 1000103 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __SIPADDHEADER11 "X-Enswitch-Uniqueid: 1331937099.35" [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.492042 Channel: SIP/product-local-0000000f Variable: __SIPADDHEADER11 Value: X-Enswitch-Uniqueid: 1331937099.35 Uniqueid: 1331937099.35 AGI Tx >> 200 result=1 AGI Rx << EXEC Dial "Local/1000103@product-phone/n,15,o" -- AGI Script Executing Application: (Dial) Options: (Local/1000103@product-phone/n,15,o) [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.492389 Channel: SIP/product-local-0000000f Variable: DIALSTATUS Value: Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937099.492481 Channel: SIP/product-local-0000000f Variable: DIALEDPEERNUMBER Value: Uniqueid: 1331937099.35 [Mar 17 09:31:39] DEBUG[10813]: rtp_engine.c:1407 ast_rtp_instance_early_bridge_make_compatible: Can't find native functions for channel 'Local/1000103@product-phone-fc7c;1' [Mar 17 09:31:39] DEBUG[10813]: rtp_engine.c:1464 ast_rtp_instance_early_bridge_make_compatible: Seeded SDP of 'Local/1000103@product-phone-fc7c;1' with that of 'SIP/product-local-0000000f' [Mar 17 09:31:39] DEBUG[10813]: channel.c:6112 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Mar 17 09:31:39] DEBUG[10813]: channel.c:6112 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2ce2db35;rport=5070 User-Agent: Ekiga/3.2.6 From: "1000104" ;tag=as21dc1fa5 Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 To: ;tag=4ce07b77-256e-e111-9e40-0022681012a3 Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING Content-Length: 0 Record-Route: <-------------> [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 16]: CSeq: 102 INVITE [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2ce2db35;rport=5070 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 23]: User-Agent: Ekiga/3.2.6 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 61]: From: "1000104" ;tag=as21dc1fa5 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 58]: Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 75]: To: ;tag=4ce07b77-256e-e111-9e40-0022681012a3 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 77]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 17]: Content-Length: 0 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 53]: Record-Route: --- (10 headers 0 lines) --- [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 (Checking To) --From tag as21dc1fa5 --To-tag 4ce07b77-256e-e111-9e40-0022681012a3 [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:4054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' Request 102: Found [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:19732 handle_response_invite: SIP response 180 to standard invite [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:14012 build_route: build_route: Record-Route hop: list_route: hop: [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xx.xx:5060 [Mar 17 09:31:39] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer xx.xx.xx.xx:5060 [Mar 17 09:31:39] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937099.543554 Channel: SIP/xx.xx.xx.xx:5060-00000010 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000104 ConnectedLineName: Uniqueid: 1331937099.38 [Mar 17 09:31:39] DEBUG[8675]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:39] DEBUG[8675]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' [Mar 17 09:31:39] DEBUG[8675]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:39] DEBUG[8675]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/xx.xx.xx.xx:5060 - state 6 (Ringing) [Mar 17 09:31:39] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/xx.xx.xx.xx:5060' state '6' [Mar 17 09:31:39] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'SIP/xx.xx.xx.xx:5060' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- SIP/xx.xx.xx.xx:5060-00000010 is ringing -- Local/1000103@product-phone-fc7c;1 is ringing [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:3869 __sip_autodestruct: Auto destroying SIP dialog '956183939@xx.xx.xx.xx' [Mar 17 09:31:39] DEBUG[8699]: chan_sip.c:6010 sip_destroy: Destroying SIP dialog 956183939@xx.xx.xx.xx Really destroying SIP dialog '956183939@xx.xx.xx.xx' Method: OPTIONS <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> INVITE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKeb37.823d6977.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK703239dc From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Max-Forwards: 69 Date: Fri, 16 Mar 2012 22:34:18 GMT CSeq: 102 INVITE User-Agent: Cisco-CP7960G/8.0 Contact: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx",response="eeab74e08cb50d283deace824dbc965a",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 Expires: 180 Accept: application/sdp Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "A Aardvark" ;party=calling;id-type=subscriber;privacy=off;screen=yes Supported: replaces,join,norefersub Content-Length: 280 Content-Type: application/sdp Content-Disposition: session;handling=optional X-Enswitch-RURI: sip:**@xx.xx.xx.xx X-Enswitch-Source: yy.yy.yy.yy:5065 v=0 o=Cisco-SIPUA 22503 0 IN IP4 yy.yy.yy.yy s=SIP Call t=0 0 m=audio 16694 RTP/AVP 8 0 18 101 c=IN IP4 yy.yy.yy.yy a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 52]: INVITE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 76]: Record-Route: [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKeb37.823d6977.0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 59]: Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK703239dc [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 82]: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 24]: To: [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 59]: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 16]: Max-Forwards: 69 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 35]: Date: Fri, 16 Mar 2012 22:34:18 GMT [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 16]: CSeq: 102 INVITE [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 29]: User-Agent: Cisco-CP7960G/8.0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 56]: Contact: [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [206]: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx",response="eeab74e08cb50d283deace824dbc965a",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 13 [ 12]: Expires: 180 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 14 [ 23]: Accept: application/sdp [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 15 [ 65]: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 16 [111]: Remote-Party-ID: "A Aardvark" ;party=calling;id-type=subscriber;privacy=off;screen=yes [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 17 [ 35]: Supported: replaces,join,norefersub [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 18 [ 19]: Content-Length: 280 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 19 [ 29]: Content-Type: application/sdp [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 20 [ 46]: Content-Disposition: session;handling=optional [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 21 [ 35]: X-Enswitch-RURI: sip:**@xx.xx.xx.xx [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 22 [ 38]: X-Enswitch-Source: yy.yy.yy.yy:5065 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 23 [ 0]: [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 0 [ 3]: v=0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 1 [ 43]: o=Cisco-SIPUA 22503 0 IN IP4 yy.yy.yy.yy [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 2 [ 10]: s=SIP Call [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 3 [ 5]: t=0 0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 4 [ 32]: m=audio 16694 RTP/AVP 8 0 18 101 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 5 [ 23]: c=IN IP4 yy.yy.yy.yy [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 9 [ 19]: a=fmtp:18 annexb=no [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8421 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8458 parse_request: Body 12 [ 10]: a=sendrecv --- (23 headers 13 lines) --- [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy (Checking From) --From tag 00170ec855f5cee501df3e4e-763953b3 --To-tag [Mar 17 09:31:41] DEBUG[8699]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:3482 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 == Using UDPTL CoS mark 5 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:7694 sip_alloc: Allocating new SIP dialog for 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy - INVITE (No RTP) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1613 parse_sip_options: Begin: parsing SIP "Supported: replaces,join,norefersub" [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -replaces- [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: replaces [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -join- [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: join [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -norefersub- [Mar 17 09:31:41] DEBUG[8699]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: norefersub [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:22266 handle_request_invite: Initializing initreq for method INVITE - callid 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Using INVITE request as basis request - 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:41] DEBUG[8699]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:41] DEBUG[8699]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000101' AND host = 'dynamic' [Mar 17 09:31:41] DEBUG[8699]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:41] DEBUG[8699]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000101' Found peer 'product-local' for '1000101' from xx.xx.xx.xx:5060 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:345 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0xd7bb1f8' [Mar 17 09:31:41] DEBUG[8699]: res_rtp_asterisk.c:499 ast_rtp_new: Allocated port 13368 for RTP instance '0xd7bb1f8' [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:354 ast_rtp_instance_new: RTP instance '0xd7bb1f8' is setup and ready to go [Mar 17 09:31:41] DEBUG[8699]: res_rtp_asterisk.c:2447 ast_rtp_prop_set: Setup RTCP on RTP instance '0xd7bb1f8' == Using SIP RTP CoS mark 5 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:5043 do_setnat: Setting NAT on RTP to On [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:5051 do_setnat: Setting NAT on UDPTL to On [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP o=Cisco-SIPUA 22503 0 IN IP4 yy.yy.yy.yy... UNSUPPORTED. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:8816 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 8 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x407b03d0 Found RTP audio format 0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x407b03d0 Found RTP audio format 18 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 18 based on m type on 0x407b03d0 Found RTP audio format 101 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:536 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x407b03d0 [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'yy.yy.yy.yy' into... [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'yy.yy.yy.yy' and port ''. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP c=IN IP4 yy.yy.yy.yy... OK. Found audio description format PCMA for ID 8 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format PCMU for ID 0 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. Found audio description format G729 for ID 18 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. Found audio description format telephone-event for ID 101 [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9015 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 0 on 0x407b03d0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x407b03d0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 18 on 0x407b03d0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:639 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x407b03d0 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Mar 17 09:31:41] DEBUG[8699]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7bb1f8' Peer audio RTP is at port yy.yy.yy.yy:16694 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x407b03d0 to 0xd7bb3c0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x407b03d0 to 0xd7bb3c0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 18 from 0x407b03d0 to 0xd7bb3c0 [Mar 17 09:31:41] DEBUG[8699]: rtp_engine.c:517 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x407b03d0 to 0xd7bb3c0 [Mar 17 09:31:41] DEBUG[8699]: res_rtp_asterisk.c:2413 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0xd7bb1f8' [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9249 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:9259 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:22414 handle_request_invite: Checking SIP call limits for device [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:5862 update_call_counter: Updating call counter for incoming call [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:41] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Looking for ** in from-internal (domain xx.xx.xx.xx) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:6987 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:6988 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:6989 sip_new: *** Our capabilities are 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:6990 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:7020 sip_new: This channel will not be able to handle video. [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:14012 build_route: build_route: Record-Route hop: list_route: hop: [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:22713 handle_request_invite: SIP/product-local-00000011: 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=z9hG4bKeb37.823d6977.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK703239dc Record-Route: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy CSeq: 102 INVITE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Mar 17 09:31:41] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newchannel Privilege: call,all Timestamp: 1331937101.479520 Channel: SIP/product-local-00000011 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 1000101 CallerIDName: A Aardvark AccountCode: Exten: ** Context: from-internal Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.479563 Channel: SIP/product-local-00000011 Variable: SIPURI Value: sip:1000101@yy.yy.yy.yy:5065 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.479567 Channel: SIP/product-local-00000011 Variable: SIPDOMAIN Value: xx.xx.xx.xx Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.479570 Channel: SIP/product-local-00000011 Variable: SIPCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937101.479649 Channel: SIP/product-local-00000011 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: ConnectedLineName: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:41] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:41] DEBUG[8708]: 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. [Mar 17 09:31:41] DEBUG[10820]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [**@from-internal:1] AGI("SIP/product-local-00000011", "agi://127.0.0.1/product?stype=internal") in new stack [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937101.482484 Channel: SIP/product-local-00000011 Context: from-internal Extension: ** Priority: 1 Application: AGI AppData: agi://127.0.0.1/product?stype=internal Uniqueid: 1331937101.39 AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: product?stype=internal [Mar 17 09:31:41] DEBUG[10820]: 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-00000011 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1331937101.39 AGI Tx >> agi_version: 1.8.9.2 AGI Tx >> agi_callerid: 1000101 AGI Tx >> agi_calleridname: A Aardvark AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: ** AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: ** AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1089018176 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Sat Mar 17 09:31:41 2012 (1331937101)" 9 > agi://127.0.0.1/product?stype=internal: AGI starting at Sat Mar 17 09:31:41 2012 (1331937101) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is NULL AGI Tx >> 200 result=0 AGI Rx << SET VARIABLE __PRODUCT-CALLID "1331937101.39" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.499197 Channel: SIP/product-local-00000011 Variable: __PRODUCT-CALLID Value: 1331937101.39 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCREEN [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-SCREEN' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERTED [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-DIVERTED' is NULL AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-DIVERSION [Mar 17 09:31:41] DEBUG[10820]: 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" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.502156 Channel: SIP/product-local-00000011 Variable: __PRODUCT-MUSIC Value: default Uniqueid: 1331937101.39 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" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.503189 Channel: SIP/product-local-00000011 Variable: __TRANSFER_CONTEXT Value: from-internal Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-03-18 09:31:41.504 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CUTOFF [Mar 17 09:31:41] DEBUG[10820]: 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-03-18 09:31:41.504 EST. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy) AGI Rx << VERBOSE "SIP Call-ID is: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy" 9 > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-SCUSTOMER [Mar 17 09:31:41] DEBUG[10820]: 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-Enswitch-Source) AGI Tx >> 200 result=1 (yy.yy.yy.yy:5065) AGI Rx << GET VARIABLE PRODUCT-PRESENTATION-INTERNAL [Mar 17 09:31:41] DEBUG[10820]: 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 [Mar 17 09:31:41] DEBUG[10820]: 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-Enswitch-External) AGI Tx >> 200 result=0 AGI Rx << GET VARIABLE PRODUCT-TRANSFER-PHONE [Mar 17 09:31:41] DEBUG[10820]: 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 [Mar 17 09:31:41] DEBUG[10820]: 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="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx",response="eeab74e08cb50d283deace824dbc965a",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5) AGI Rx << SET VARIABLE __PRODUCT-MUSIC "7" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.516127 Channel: SIP/product-local-00000011 Variable: __PRODUCT-MUSIC Value: 7 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(musicclass) "7" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Resolving type 'gpickup', number '', old '', forward 1 for channel SIP/product-local-00000011" 5 > agi://127.0.0.1/product?stype=internal: Resolving type 'gpickup', number '', old '', forward 1 for channel SIP/product-local-00000011 AGI Tx >> 200 result=1 AGI Rx << VERBOSE "Starting recording group '1' expires '1332023501' file '/var/lib/product/recordings/9/1/2012/03/17/record_133193710139_10332'" 9 > agi://127.0.0.1/product?stype=internal: Starting recording group '1' expires '1332023501' file '/var/lib/product/recordings/9/1/2012/03/17/record_133193710139_10332' AGI Tx >> 200 result=1 AGI Rx << EXEC Monitor "gsm,/var/lib/product/recordings/9/1/2012/03/17/record_133193710139_10332" -- AGI Script Executing Application: (Monitor) Options: (gsm,/var/lib/product/recordings/9/1/2012/03/17/record_133193710139_10332) [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.528433 Channel: SIP/product-local-00000011 Variable: __MONITORED Value: true Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: MonitorStart Privilege: call,all Timestamp: 1331937101.529138 Channel: SIP/product-local-00000011 Uniqueid: 1331937101.39 AGI Tx >> 200 result=0 AGI Rx << VERBOSE "Writing entry to active table for 1331937101.39, phone:1000101 - gpickup:." 9 > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1331937101.39, phone:1000101 - gpickup:. AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) AGI Tx >> 200 result=1 (00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy) AGI Rx << GET VARIABLE CALLERID(name) AGI Tx >> 200 result=1 (A Aardvark) AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" Channel will hangup at 2012-03-18 09:31:41.569 EST. AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DCUSTOMER "9" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.570551 Channel: SIP/product-local-00000011 Variable: __PRODUCT-DCUSTOMER Value: 9 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DTYPE "gpickup" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.570997 Channel: SIP/product-local-00000011 Variable: __PRODUCT-DTYPE Value: gpickup Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-DNUMBER "" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.571448 Channel: SIP/product-local-00000011 Variable: __PRODUCT-DNUMBER Value: Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CALLERID(number) "1000101" AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-CUSTOMER "9" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.572317 Channel: SIP/product-local-00000011 Variable: __PRODUCT-TRANSFER-CUSTOMER Value: 9 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-INTERNAL "1" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.572869 Channel: SIP/product-local-00000011 Variable: __PRODUCT-PRESENTATION-INTERNAL Value: 1 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-PRESENTATION-EXTERNAL "1" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.573370 Channel: SIP/product-local-00000011 Variable: __PRODUCT-PRESENTATION-EXTERNAL Value: 1 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-CUTOFF "86400" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.573838 Channel: SIP/product-local-00000011 Variable: __PRODUCT-CUTOFF Value: 86400 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE TIMEOUT(absolute) "3600" Channel will hangup at 2012-03-17 10:31:41.574 EST. AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE __PRODUCT-TRANSFER-PHONE "1000101" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.574875 Channel: SIP/product-local-00000011 Variable: __PRODUCT-TRANSFER-PHONE Value: 1000101 Uniqueid: 1331937101.39 AGI Tx >> 200 result=1 AGI Rx << EXEC Dial "Local/1000103@product-pickup/n,60,M(product-answered^0^1331937101.39)orL(3600000:60000)" -- AGI Script Executing Application: (Dial) Options: (Local/1000103@product-pickup/n,60,M(product-answered^0^1331937101.39)orL(3600000:60000)) [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.578105 Channel: SIP/product-local-00000011 Variable: DIALSTATUS Value: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.578274 Channel: SIP/product-local-00000011 Variable: DIALEDPEERNUMBER Value: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.578453 Channel: SIP/product-local-00000011 Variable: DIALEDPEERNAME Value: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.578601 Channel: SIP/product-local-00000011 Variable: ANSWEREDTIME Value: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.578770 Channel: SIP/product-local-00000011 Variable: DIALEDTIME Value: Uniqueid: 1331937101.39 > Limit Data for this call: > timelimit = 3600000 ms (3600.000 s) > play_warning = 60000 ms (60.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 0 ms (0.000 s) > start_sound = > warning_sound = timeleft > end_sound = [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newchannel Privilege: call,all Timestamp: 1331937101.579708 Channel: Local/1000103@product-pickup-f725;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: AccountCode: Exten: 1000103 Context: product-pickup Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newchannel Privilege: call,all Timestamp: 1331937101.579900 Channel: Local/1000103@product-pickup-f725;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: AccountCode: Exten: 1000103 Context: product-pickup Uniqueid: 1331937101.41 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.580070 Channel: Local/1000103@product-pickup-f725;1 Variable: DIALEDPEERNUMBER Value: 1000103@product-pickup/n Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-PHONE. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CUTOFF. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-EXTERNAL. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-PRESENTATION-INTERNAL. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-TRANSFER-CUSTOMER. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DNUMBER. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DTYPE. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-DCUSTOMER. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable MONITORED. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-MUSIC. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6108 ast_channel_inherit_variables: Copying hard-transferable variable PRODUCT-CALLID. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 17 09:31:41] DEBUG[10820]: channel.c:6112 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: NewCallerid Privilege: call,all Timestamp: 1331937101.581940 Channel: Local/1000103@product-pickup-f725;1 CallerIDNum: 1000101 CallerIDName: A Aardvark Uniqueid: 1331937101.40 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Dial Privilege: call,all Timestamp: 1331937101.582156 SubEvent: Begin Channel: SIP/product-local-00000011 Destination: Local/1000103@product-pickup-f725;1 CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: ConnectedLineName: UniqueID: 1331937101.39 DestUniqueID: 1331937101.40 Dialstring: 1000103@product-pickup/n -- Called Local/1000103@product-pickup/n <--- Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKeb37.823d6977.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK703239dc Record-Route: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy CSeq: 102 INVITE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:41] DEBUG[10829]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is '1000103' [Mar 17 09:31:41] DEBUG[10829]: pbx.c:4230 pbx_extension_helper: Launching 'PickupChan' -- Executing [1000103@product-pickup:1] PickupChan("Local/1000103@product-pickup-f725;2", "Local/1000103@product-phone") in new stack [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937101.584389 Channel: Local/1000103@product-pickup-f725;2 Context: product-pickup Extension: 1000103 Priority: 1 Application: PickupChan AppData: Local/1000103@product-phone Uniqueid: 1331937101.41 [Mar 17 09:31:41] DEBUG[10829]: features.c:7220 ast_do_pickup: Call pickup on 'Local/1000103@product-phone-fc7c;1' by 'Local/1000103@product-pickup-f725;2' [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-pickup [Mar 17 09:31:41] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-pickup exists (devicestate) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-pickup - state 2 (In use) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-pickup' state '2' [Mar 17 09:31:41] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-pickup' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937101.584949 Channel: Local/1000103@product-pickup-f725;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000101 ConnectedLineName: A Aardvark Uniqueid: 1331937101.40 -- Local/1000103@product-pickup-f725;1 answered SIP/product-local-00000011 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585197 Channel: SIP/product-local-00000011 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585369 Channel: SIP/product-local-00000011 Variable: DIALEDPEERNAME Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585514 Channel: SIP/product-local-00000011 Variable: DIALEDPEERNUMBER Value: 1000103@product-pickup/n Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585676 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_EXTEN Value: ** Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585829 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_CONTEXT Value: from-internal Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.585971 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_PRIORITY Value: 1 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.586113 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.586412 Channel: Local/1000103@product-pickup-f725;1 Variable: ARG1 Value: 0 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.586583 Channel: Local/1000103@product-pickup-f725;1 Variable: ARG2 Value: 1331937101.39 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.586766 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_DEPTH Value: 1 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG1' is '0' [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ARG2' is '1331937101.39' [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG3' is NULL [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'ARG4' is NULL [Mar 17 09:31:41] DEBUG[10820]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-product-answered:1] AGI("Local/1000103@product-pickup-f725;1", "agi://127.0.0.1/answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber=") in new stack [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937101.587408 Channel: Local/1000103@product-pickup-f725;1 Context: macro-product-answered Extension: s Priority: 1 Application: AGI AppData: agi://127.0.0.1/answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber= Uniqueid: 1331937101.40 AGI Tx >> agi_network: yes AGI Tx >> agi_network_script: answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber= [Mar 17 09:31:41] DEBUG[10820]: res_agi.c:1520 launch_netscript: Wow, connected! AGI Tx >> agi_request: agi://127.0.0.1/answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber= AGI Tx >> agi_channel: Local/1000103@product-pickup-f725;1 AGI Tx >> agi_language: en AGI Tx >> agi_type: Local AGI Tx >> agi_uniqueid: 1331937101.40 AGI Tx >> agi_version: 1.8.9.2 AGI Tx >> agi_callerid: 1000104 AGI Tx >> agi_calleridname: unknown AGI Tx >> agi_callingpres: 0 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: 1089018176 AGI Tx >> AGI Rx << VERBOSE "AGI starting at Sat Mar 17 09:31:41 2012 (1331937101)" 9 > agi://127.0.0.1/answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber=: AGI starting at Sat Mar 17 09:31:41 2012 (1331937101) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Mar 17 09:31:41] DEBUG[10820]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1331937101.39' AGI Tx >> 200 result=1 (1331937101.39) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-pickup [Mar 17 09:31:41] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-pickup exists (devicestate) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-pickup - state 2 (In use) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-pickup' state '2' [Mar 17 09:31:41] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-pickup' changed to state '2' (In use) but we don't care because they're not a member of any queue. AGI Rx << SET VARIABLE MACRO_RESULT "" [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.606468 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_RESULT Value: Uniqueid: 1331937101.40 AGI Tx >> 200 result=1 -- AGI Script agi://127.0.0.1/answered?screen=0&puniqueid=1331937101.39&pcallid=&snumber= completed, returning 0 AGI Tx >> HANGUP [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.607630 Channel: Local/1000103@product-pickup-f725;1 Variable: AGISTATUS Value: SUCCESS Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[10820]: app_macro.c:435 _macro_exec: Executed application: AGI [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.608346 Channel: Local/1000103@product-pickup-f725;1 Variable: MACRO_DEPTH Value: 0 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[10820]: app_dial.c:2595 dial_exec_full: Macro exited with status 0 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.608637 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.608847 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:41] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:41] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:41] DEBUG[8708]: 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. [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937101.609221 Channel: SIP/product-local-00000011 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: 1000104 ConnectedLineName: Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:6436 sip_answer: SIP answering channel: SIP/product-local-00000011 [Mar 17 09:31:41] DEBUG[10820]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:11632 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:11231 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:11232 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 13368 Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:11341 add_sdp: -- Done with adding codecs to SDP [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:11527 add_sdp: Done building SDP. Settling with this capability: 0xc (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=z9hG4bKeb37.823d6977.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK703239dc Record-Route: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy CSeq: 102 INVITE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 256 v=0 o=root 878217929 878217929 IN IP4 xx.xx.xx.xx s=Asterisk PBX 1.8.9.2 c=IN IP4 xx.xx.xx.xx t=0 0 m=audio 13368 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:3785 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #146 [Mar 17 09:31:41] DEBUG[10820]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: NewAccountCode Privilege: call,all Timestamp: 1331937101.611377 Channel: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.40 AccountCode: OldAccountCode: [Mar 17 09:31:41] DEBUG[10820]: features.c:3963 ast_bridge_call: bridge answer set, chan answer set [Mar 17 09:31:41] DEBUG[10820]: features.c:3805 clear_dialed_interfaces: Removing dialed interfaces datastore on Local/1000103@product-pickup-f725;1 since we're bridging [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Bridge Privilege: call,all Timestamp: 1331937101.611731 Bridgestate: Link Bridgetype: core Channel1: SIP/product-local-00000011 Channel2: Local/1000103@product-pickup-f725;1 Uniqueid1: 1331937101.39 Uniqueid2: 1331937101.40 CallerID1: 1000101 CallerID2: 1000104 [Mar 17 09:31:41] DEBUG[10820]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937101.611981 Channel: Local/1000103@product-pickup-f725;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: 1000104 ConnectedLineName: Uniqueid: 1331937101.41 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.612336 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.612513 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.612647 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.612801 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.612944 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.613653 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[10820]: channel.c:7100 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/1000103@product-pickup-f725;1 [Mar 17 09:31:41] DEBUG[10820]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Unlink Privilege: call,all Timestamp: 1331937101.613985 Channel1: SIP/product-local-00000011 Channel2: Local/1000103@product-pickup-f725;1 Uniqueid1: 1331937101.39 Uniqueid2: 1331937101.40 CallerID1: 1000101 CallerID2: 1000104 [Mar 17 09:31:41] DEBUG[10820]: channel.c:7518 ast_channel_bridge: Bridge stops bridging channels SIP/product-local-00000011 and Local/1000103@product-pickup-f725;1 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Bridge Privilege: call,all Timestamp: 1331937101.614193 Bridgestate: Link Bridgetype: core Channel1: SIP/product-local-00000011 Channel2: Local/1000103@product-pickup-f725;1 Uniqueid1: 1331937101.39 Uniqueid2: 1331937101.40 CallerID1: 1000101 CallerID2: 1000104 [Mar 17 09:31:41] DEBUG[10820]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.614450 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.614598 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.614761 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.614907 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.615021 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:41] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937101.615143 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:42] DEBUG[10820]: chan_sip.c:7351 sip_rtp_read: Oooh, format changed to alaw [Mar 17 09:31:42] DEBUG[10820]: channel.c:5147 set_format: Set channel SIP/product-local-00000011 to read format ulaw [Mar 17 09:31:42] DEBUG[10820]: channel.c:5147 set_format: Set channel SIP/product-local-00000011 to write format ulaw [Mar 17 09:31:42] DEBUG[10829]: channel.c:5916 __ast_channel_masquerade: Planning to masquerade channel Local/1000103@product-pickup-f725;2 into the structure of Local/1000103@product-phone-fc7c;1 [Mar 17 09:31:42] DEBUG[10829]: channel.c:5926 __ast_channel_masquerade: Done planning to masquerade channel Local/1000103@product-pickup-f725;2 into the structure of Local/1000103@product-phone-fc7c;1 [Mar 17 09:31:42] DEBUG[10829]: channel.c:6487 ast_do_masquerade: Actually Masquerading Local/1000103@product-pickup-f725;2(6) into the structure of Local/1000103@product-phone-fc7c;1(5) [Mar 17 09:31:42] DEBUG[10829]: chan_local.c:974 local_hangup: This local call has the ANSWERED_ELSEWHERE flag set. [Mar 17 09:31:42] DEBUG[10829]: channel.c:5147 set_format: Set channel Local/1000103@product-pickup-f725;2 to write format gsm [Mar 17 09:31:42] DEBUG[10829]: channel.c:5147 set_format: Set channel Local/1000103@product-pickup-f725;2 to read format gsm [Mar 17 09:31:42] DEBUG[10829]: channel.c:6710 ast_do_masquerade: Putting channel Local/1000103@product-pickup-f725;2 in gsm/gsm formats [Mar 17 09:31:42] DEBUG[10829]: channel.c:6755 ast_do_masquerade: Released clone lock on 'Local/1000103@product-phone-fc7c;1' [Mar 17 09:31:42] DEBUG[10829]: channel.c:6763 ast_do_masquerade: Done Masquerading Local/1000103@product-pickup-f725;2 (6) [Mar 17 09:31:42] DEBUG[10829]: pbx.c:5047 __ast_pbx_run: Spawn extension (product-pickup,1000103,1) exited non-zero on 'Local/1000103@product-phone-fc7c;1' == Spawn extension (product-pickup, 1000103, 1) exited non-zero on 'Local/1000103@product-phone-fc7c;1' [Mar 17 09:31:42] DEBUG[10829]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1000103@product-phone-fc7c;1' [Mar 17 09:31:42] DEBUG[10829]: channel.c:2831 ast_hangup: Hanging up zombie 'Local/1000103@product-phone-fc7c;1' [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011169 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011181 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011185 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011192 Channel: SIP/product-local-00000011 Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.39 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011195 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPEER Value: SIP/product-local-00000011 Uniqueid: 1331937101.40 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.011198 Channel: Local/1000103@product-pickup-f725;1 Variable: BRIDGEPVTCALLID Value: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Uniqueid: 1331937101.40 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Pickup Privilege: call,all Timestamp: 1331937102.011218 Channel: Local/1000103@product-pickup-f725;2 TargetChannel: Local/1000103@product-phone-fc7c;1 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Masquerade Privilege: call,all Timestamp: 1331937102.011235 Clone: Local/1000103@product-pickup-f725;2 CloneState: Up Original: Local/1000103@product-phone-fc7c;1 OriginalState: Ringing [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Rename Privilege: call,all Timestamp: 1331937102.011238 Channel: Local/1000103@product-pickup-f725;2 Newname: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937101.41 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Rename Privilege: call,all Timestamp: 1331937102.011241 Channel: Local/1000103@product-phone-fc7c;1 Newname: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Rename Privilege: call,all Timestamp: 1331937102.011255 Channel: Local/1000103@product-pickup-f725;2 Newname: Local/1000103@product-phone-fc7c;1 Uniqueid: 1331937101.41 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: NewCallerid Privilege: call,all Timestamp: 1331937102.011267 Channel: Local/1000103@product-pickup-f725;2 CallerIDNum: 1000101 CallerIDName: A Aardvark Uniqueid: 1331937099.36 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937102.011386 Channel: Local/1000103@product-phone-fc7c;1 Uniqueid: 1331937101.41 CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000104 ConnectedLineName: Cause: 0 Cause-txt: Unknown -- Local/1000103@product-pickup-f725;2 answered SIP/product-local-0000000f [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:6436 sip_answer: SIP answering channel: SIP/product-local-0000000f [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:11632 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:11231 add_sdp: ** Our capability: 0x2 (gsm) Video flag: True Text flag: True [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:11232 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 15748 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:11341 add_sdp: -- Done with adding codecs to SDP [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:11527 add_sdp: Done building SDP. Settling with this capability: 0x2 (gsm) <--- Reliably Transmitting (NAT) to xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK53b6.955376a4.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjP9DDfMRxSsUKh2sBgZnrLYzXFX0sizrq Record-Route: From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U To: ;tag=as7c35e0a2 Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t CSeq: 6693 INVITE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Content-Length: 229 v=0 o=root 38057074 38057074 IN IP4 xx.xx.xx.xx s=Asterisk PBX 1.8.9.2 c=IN IP4 xx.xx.xx.xx t=0 0 m=audio 15748 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:3785 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #148 [Mar 17 09:31:42] DEBUG[10813]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:42] DEBUG[10813]: features.c:3963 ast_bridge_call: bridge answer set, chan answer set [Mar 17 09:31:42] DEBUG[10813]: features.c:3805 clear_dialed_interfaces: Removing dialed interfaces datastore on Local/1000103@product-pickup-f725;2 since we're bridging [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:1298 ast_rtp_write: Ooh, format changed from unknown to gsm [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:1329 ast_rtp_write: Created smoother: format: gsm ms: 20 len: 33 [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:1194 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0xd7783c8' [Mar 17 09:31:42] DEBUG[10813]: channel.c:3944 __ast_read: Dropping duplicate answer! [Mar 17 09:31:42] DEBUG[10815]: channel.c:2820 ast_hangup: Hanging up channel 'SIP/xx.xx.xx.xx:5060-00000010' [Mar 17 09:31:42] DEBUG[10815]: chan_sip.c:6233 sip_hangup: Hanging up zombie call. Be scared. [Mar 17 09:31:42] DEBUG[10815]: chan_sip.c:6254 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 17 09:31:42] DEBUG[10815]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd77c458' Scheduling destruction of SIP dialog '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' in 32000 ms (Method: INVITE) [Mar 17 09:31:42] DEBUG[10815]: chan_sip.c:4054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' Request 102: Found set_destination: Parsing for address/port to send to [Mar 17 09:31:42] DEBUG[10815]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:42] DEBUG[10815]: 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: CANCEL sip:1000103@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK2ce2db35;rport Route: Max-Forwards: 70 From: "1000104" ;tag=as21dc1fa5 To: Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 CSeq: 102 CANCEL User-Agent: Enswitch Content-Length: 0 --- [Mar 17 09:31:42] DEBUG[10815]: chan_sip.c:3785 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #151 [Mar 17 09:31:42] DEBUG[10815]: chan_sip.c:3328 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for xx.xx.xx.xx:5060 Scheduling destruction of SIP dialog '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' in 32000 ms (Method: INVITE) [Mar 17 09:31:42] DEBUG[10815]: app_dial.c:2901 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Mar 17 09:31:42] DEBUG[10815]: pbx.c:5047 __ast_pbx_run: Spawn extension (product-phone,1000103,3) exited non-zero on 'Local/1000103@product-phone-fc7c;2' == Spawn extension (product-phone, 1000103, 3) exited non-zero on 'Local/1000103@product-phone-fc7c;2' [Mar 17 09:31:42] DEBUG[10815]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1000103@product-phone-fc7c;2' [Mar 17 09:31:42] DEBUG[10815]: channel.c:2820 ast_hangup: Hanging up channel 'Local/1000103@product-phone-fc7c;2' [Mar 17 09:31:42] DEBUG[10815]: chan_local.c:974 local_hangup: This local call has the ANSWERED_ELSEWHERE flag set. [Mar 17 09:31:42] DEBUG[10820]: res_rtp_asterisk.c:781 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Mar 17 09:31:42] DEBUG[10820]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-phone [Mar 17 09:31:42] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-phone exists (devicestate) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-phone - state 1 (Not in use) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-phone' state '1' [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:42] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - xx.xx.xx.xx:5060 [Mar 17 09:31:42] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer xx.xx.xx.xx:5060 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012049 Channel: SIP/product-local-0000000f Variable: DIALSTATUS Value: ANSWER Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012056 Channel: SIP/product-local-0000000f Variable: DIALEDPEERNAME Value: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012060 Channel: SIP/product-local-0000000f Variable: DIALEDPEERNUMBER Value: 1000103@product-phone/n Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012067 Channel: SIP/product-local-0000000f Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012070 Channel: Local/1000103@product-pickup-f725;2 Variable: BRIDGEPEER Value: SIP/product-local-0000000f Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newstate Privilege: call,all Timestamp: 1331937102.012079 Channel: SIP/product-local-0000000f ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: ConnectedLineName: Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: NewAccountCode Privilege: call,all Timestamp: 1331937102.012247 Channel: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.36 AccountCode: OldAccountCode: [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Bridge Privilege: call,all Timestamp: 1331937102.012264 Bridgestate: Link Bridgetype: core Channel1: SIP/product-local-0000000f Channel2: Local/1000103@product-pickup-f725;2 Uniqueid1: 1331937099.35 Uniqueid2: 1331937099.36 CallerID1: 1000104 CallerID2: 1000101 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012278 Channel: SIP/product-local-0000000f Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012282 Channel: Local/1000103@product-pickup-f725;2 Variable: BRIDGEPEER Value: SIP/product-local-0000000f Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012284 Channel: Local/1000103@product-pickup-f725;2 Variable: BRIDGEPVTCALLID Value: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012288 Channel: SIP/product-local-0000000f Variable: BRIDGEPEER Value: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.35 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012291 Channel: Local/1000103@product-pickup-f725;2 Variable: BRIDGEPEER Value: SIP/product-local-0000000f Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012293 Channel: Local/1000103@product-pickup-f725;2 Variable: BRIDGEPVTCALLID Value: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t Uniqueid: 1331937099.36 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937102.012443 Channel: SIP/xx.xx.xx.xx:5060-00000010 Uniqueid: 1331937099.38 CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000104 ConnectedLineName: Cause: 16 Cause-txt: Normal Clearing [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937102.012455 Channel: Local/1000103@product-phone-fc7c;2 Variable: DIALSTATUS Value: CANCEL Uniqueid: 1331937099.37 [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Dial Privilege: call,all Timestamp: 1331937102.012458 SubEvent: End Channel: Local/1000103@product-phone-fc7c;2 UniqueID: 1331937099.37 DialStatus: CANCEL [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937102.012506 Channel: Local/1000103@product-phone-fc7c;2 Uniqueid: 1331937099.37 CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000104 ConnectedLineName: Cause: 0 Cause-txt: Unknown [Mar 17 09:31:42] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 17 09:31:42] DEBUG[8708]: 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. [Mar 17 09:31:42] DEBUG[8675]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:42] DEBUG[8675]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' AND host = 'dynamic' [Mar 17 09:31:42] DEBUG[8675]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Mar 17 09:31:42] DEBUG[8675]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.xx.xx:5060' [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/xx.xx.xx.xx:5060 - state 0 (Unknown) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/xx.xx.xx.xx:5060' state '0' [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-phone [Mar 17 09:31:42] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-phone exists (devicestate) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-phone - state 1 (Not in use) [Mar 17 09:31:42] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-phone' state '1' [Mar 17 09:31:42] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'SIP/xx.xx.xx.xx:5060' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Mar 17 09:31:42] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-phone' 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 canceling Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK2ce2db35;rport=5070 From: "1000104" ;tag=as21dc1fa5 To: ;tag=78d5a7e4be24d05dcd56d6d486697a3b-7ad8 Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 CSeq: 102 CANCEL Server: Enswitch SIP proxy Content-Length: 0 Warning: 392 xx.xx.xx.xx:5060 "Noisy feedback tells: pid=16763 req_src_ip=xx.xx.xx.xx req_src_port=5070 in_uri=sip:1000103@xx.xx.xx.xx:5060 out_uri=sip:1000103@192.168.1.40:5071 via_cnt==1" <-------------> [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 21]: SIP/2.0 200 canceling [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 67]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK2ce2db35;rport=5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 61]: From: "1000104" ;tag=as21dc1fa5 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 76]: To: ;tag=78d5a7e4be24d05dcd56d6d486697a3b-7ad8 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 58]: Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 16]: CSeq: 102 CANCEL [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 26]: Server: Enswitch SIP proxy [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 17]: Content-Length: 0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [189]: Warning: 392 xx.xx.xx.xx:5060 "Noisy feedback tells: pid=16763 req_src_ip=xx.xx.xx.xx req_src_port=5070 in_uri=sip:1000103@xx.xx.xx.xx:5060 out_uri=sip:1000103@192.168.1.40:5071 via_cnt==1" --- (9 headers 0 lines) --- [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 (Checking To) --From tag as21dc1fa5 --To-tag 78d5a7e4be24d05dcd56d6d486697a3b-7ad8 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3975 __sip_ack: Acked pending invite 102 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3980 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:4013 __sip_ack: Stopping retransmission on '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' of Request 102: Match Found <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 487 Request Terminated CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2ce2db35;rport=5070 User-Agent: Ekiga/3.2.6 From: "1000104" ;tag=as21dc1fa5 Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 To: ;tag=4ce07b77-256e-e111-9e40-0022681012a3 Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING Content-Length: 0 Record-Route: <-------------> [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 30]: SIP/2.0 487 Request Terminated [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 16]: CSeq: 102 INVITE [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;received=xx.xx.xx.xx;branch=z9hG4bK2ce2db35;rport=5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 23]: User-Agent: Ekiga/3.2.6 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 61]: From: "1000104" ;tag=as21dc1fa5 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 58]: Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 75]: To: ;tag=4ce07b77-256e-e111-9e40-0022681012a3 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 77]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 17]: Content-Length: 0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 53]: Record-Route: --- (10 headers 0 lines) --- [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 (Checking To) --From tag as21dc1fa5 --To-tag 4ce07b77-256e-e111-9e40-0022681012a3 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:4013 __sip_ack: Stopping retransmission on '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' of Request 102: Match Found [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:19732 handle_response_invite: SIP response 487 to standard invite set_destination: Parsing for address/port to send to Mar 17 09:31:42] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:42] DEBUG[8699]: 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:1000103@xx.xx.xx.xx:5060 SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK2ce2db35;rport Route: Max-Forwards: 70 From: "1000104" ;tag=as21dc1fa5 To: ;tag=4ce07b77-256e-e111-9e40-0022681012a3 Contact: Call-ID: 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 CSeq: 102 ACK User-Agent: Enswitch Content-Length: 0 --- [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'ACK sip:100' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:5862 update_call_counter: Updating call counter for outgoing call [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3070 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:6010 sip_destroy: Destroying SIP dialog 65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070 Really destroying SIP dialog '65b0a1386a3fe34f78f2fe257262ec9d@xx.xx.xx.xx:5070' Method: INVITE [Mar 17 09:31:42] DEBUG[8699]: rtp_engine.c:293 instance_destructor: Destroyed RTP instance '0xd77c458' <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> ACK sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKeb37.823d6977.2 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5e084c75 From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Max-Forwards: 69 Date: Fri, 16 Mar 2012 22:34:19 GMT CSeq: 102 ACK User-Agent: Cisco-CP7960G/8.0 Route: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx",response="eeab74e08cb50d283deace824dbc965a",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 Remote-Party-ID: "A Aardvark" ;party=calling;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 X-Enswitch-Source: yy.yy.yy.yy:5065 <-------------> [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 49]: ACK sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 76]: Record-Route: [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKeb37.823d6977.2 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 59]: Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5e084c75 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 82]: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 39]: To: ;tag=as243d9b54 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 59]: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 16]: Max-Forwards: 69 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 35]: Date: Fri, 16 Mar 2012 22:34:19 GMT [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 13]: CSeq: 102 ACK [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 29]: User-Agent: Cisco-CP7960G/8.0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 71]: Route: [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [206]: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx",response="eeab74e08cb50d283deace824dbc965a",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 13 [111]: Remote-Party-ID: "A Aardvark" ;party=calling;id-type=subscriber;privacy=off;screen=yes [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 14 [ 17]: Content-Length: 0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 15 [ 79]: X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 16 [ 38]: X-Enswitch-Source: yy.yy.yy.yy:5065 --- (17 headers 0 lines) --- [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy (Checking From) --From tag 00170ec855f5cee501df3e4e-763953b3 --To-tag as243d9b54 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3980 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #146 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:4013 __sip_ack: Stopping retransmission on '00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy' of Response 102: Match Found [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:1732 ast_rtcp_read: Got RTCP report of 32 bytes [Mar 17 09:31:42] DEBUG[10820]: res_rtp_asterisk.c:1298 ast_rtp_write: Ooh, format changed from unknown to alaw [Mar 17 09:31:42] DEBUG[10820]: res_rtp_asterisk.c:1329 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160 <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> ACK sip:1000103@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK53b6.955376a4.2 Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjXdEzPyDR45hMrqASnnS5lO7kKnfcOx0i Max-Forwards: 69 From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U To: ;tag=as7c35e0a2 Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t CSeq: 6693 ACK Route: Content-Length: 0 X-Enswitch-RURI: sip:1000103@xx.xx.xx.xx:5070 X-Enswitch-Source: yy.yy.yy.yy:56485 <-------------> [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 54]: ACK sip:1000103@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 75]: Record-Route: [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK53b6.955376a4.2 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [122]: Via: SIP/2.0/UDP yy.yy.yy.yy:56485;received=yy.yy.yy.yy;rport=56485;branch=z9hG4bKPjXdEzPyDR45hMrqASnnS5lO7kKnfcOx0i [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 16]: Max-Forwards: 69 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 68]: From: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 44]: To: ;tag=as7c35e0a2 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 41]: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 14]: CSeq: 6693 ACK [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 65]: Route: [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 17]: Content-Length: 0 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 45]: X-Enswitch-RURI: sip:1000103@xx.xx.xx.xx:5070 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [ 39]: X-Enswitch-Source: yy.yy.yy.yy:56485 --- (13 headers 0 lines) --- [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t (Checking From) --From tag Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U --To-tag as7c35e0a2 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:3980 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #148 [Mar 17 09:31:42] DEBUG[8699]: chan_sip.c:4013 __sip_ack: Stopping retransmission on 'e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t' of Response 6693: Match Found [Mar 17 09:31:42] DEBUG[10813]: res_rtp_asterisk.c:1732 ast_rtcp_read: Got RTCP report of 52 bytes [Mar 17 09:31:42] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1331937102.294078 From: yy.yy.yy.yy:4003 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 39967 SequenceNumberCycles: 0 IAJitter: 0 LastSR: 0.0000000000 DLSR: 0.0000(sec) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1437 create_dtmf_frame: Sending dtmf: 35 (#), at yy.yy.yy.yy:16694 [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.590183 Channel: SIP/product-local-00000011 Uniqueid: 1331937101.39 Digit: # Direction: Received Begin: Yes End: No [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.590258 Channel: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.40 Digit: # Direction: Sent Begin: Yes End: No [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.590612 Channel: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.36 Digit: # Direction: Received Begin: Yes End: No [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.590692 Channel: SIP/product-local-0000000f Uniqueid: 1331937099.35 Digit: # Direction: Sent Begin: Yes End: No [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1437 create_dtmf_frame: Sending dtmf: 35 (#), at yy.yy.yy.yy:16694 [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.670557 Channel: SIP/product-local-00000011 Uniqueid: 1331937101.39 Digit: # Direction: Received Begin: No End: Yes [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.670668 Channel: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.40 Digit: # Direction: Sent Begin: No End: Yes [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[10820]: res_rtp_asterisk.c:1481 process_dtmf_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.671222 Channel: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.36 Digit: # Direction: Received Begin: No End: Yes [Mar 17 09:31:43] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: DTMF Privilege: dtmf,all Timestamp: 1331937103.671330 Channel: SIP/product-local-0000000f Uniqueid: 1331937099.35 Digit: # Direction: Sent Begin: No End: Yes <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> BYE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKfb37.11036eb3.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Max-Forwards: 69 Date: Fri, 16 Mar 2012 22:34:24 GMT CSeq: 103 BYE User-Agent: Cisco-CP7960G/8.0 Content-Length: 0 RTP-RxStat: Dur=??,Pkt=??,Oct=??,LatePkt=??,LostPkt=??,AvgJit=?? RTP-TxStat: Dur=??,Pkt=??,Oct=?? Route: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3",response="ce3433d84fd44a3006d5ee6ea7e8cf6b",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 X-Enswitch-Source: yy.yy.yy.yy:5065 <-------------> [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 49]: BYE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 76]: Record-Route: [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKfb37.11036eb3.0 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 59]: Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 82]: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 39]: To: ;tag=as243d9b54 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 59]: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 16]: Max-Forwards: 69 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 35]: Date: Fri, 16 Mar 2012 22:34:24 GMT [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 13]: CSeq: 103 BYE [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 29]: User-Agent: Cisco-CP7960G/8.0 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 17]: Content-Length: 0 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [ 64]: RTP-RxStat: Dur=??,Pkt=??,Oct=??,LatePkt=??,LostPkt=??,AvgJit=?? [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 13 [ 32]: RTP-TxStat: Dur=??,Pkt=??,Oct=?? [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 14 [ 71]: Route: [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 15 [250]: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3",response="ce3433d84fd44a3006d5ee6ea7e8cf6b",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 16 [ 79]: X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 17 [ 38]: X-Enswitch-Source: yy.yy.yy.yy:5065 --- (18 headers 0 lines) --- [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy (Checking From) --From tag 00170ec855f5cee501df3e4e-763953b3 --To-tag as243d9b54 [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:23586 handle_request_bye: Initializing initreq for method BYE - callid 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:46] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:46] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:3070 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:46] DEBUG[8699]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7bb1f8' Scheduling destruction of SIP dialog '00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy' in 32000 ms (Method: BYE) [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:23689 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=z9hG4bKfb37.11036eb3.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e Record-Route: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy CSeq: 103 BYE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Mar 17 09:31:46] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819195 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOS Value: ssrc=1226555569;themssrc=4116039694;lp=0;rxjitter=0.000230;rxcount=243;txjitter=0.000000;txcount=236;rlp=0;rtt=0.000000 Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819204 Channel: Local/1000103@product-pickup-f725;1 Variable: RTPAUDIOQOSBRIDGED Value: ssrc=1226555569;themssrc=4116039694;lp=0;rxjitter=0.000230;rxcount=243;txjitter=0.000000;txcount=236;rlp=0;rtt=0.000000 Uniqueid: 1331937101.40 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819211 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819214 Channel: Local/1000103@product-pickup-f725;1 Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1331937101.40 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819220 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819223 Channel: Local/1000103@product-pickup-f725;1 Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1331937101.40 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819227 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819230 Channel: Local/1000103@product-pickup-f725;1 Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1331937101.40 [Mar 17 09:31:46] DEBUG[10820]: channel.c:7059 ast_generic_bridge: Didn't get a frame from channel: SIP/product-local-00000011 [Mar 17 09:31:46] DEBUG[10820]: channel.c:7518 ast_channel_bridge: Bridge stops bridging channels SIP/product-local-00000011 and Local/1000103@product-pickup-f725;1 [Mar 17 09:31:46] DEBUG[10820]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-00000011' [Mar 17 09:31:46] DEBUG[10820]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [h@from-internal:1] AGI("SIP/product-local-00000011", "agi://127.0.0.1/end") in new stack [Mar 17 09:31:46] DEBUG[10820]: 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 [Mar 17 09:31:46] DEBUG[10820]: 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-00000011 AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1331937101.39 AGI Tx >> agi_version: 1.8.9.2 AGI Tx >> agi_callerid: 1000101 AGI Tx >> agi_calleridname: A Aardvark AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: ** 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: 1089018176 AGI Tx >> [Mar 17 09:31:46] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Unlink Privilege: call,all Timestamp: 1331937106.819466 Channel1: SIP/product-local-00000011 Channel2: Local/1000103@product-pickup-f725;1 Uniqueid1: 1331937101.39 Uniqueid2: 1331937101.40 CallerID1: 1000101 CallerID2: 1000104 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819480 Channel: SIP/product-local-00000011 Variable: ANSWEREDTIME Value: 5 Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937106.819483 Channel: SIP/product-local-00000011 Variable: DIALEDTIME Value: 5 Uniqueid: 1331937101.39 [Mar 17 09:31:46] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937106.819513 Channel: SIP/product-local-00000011 Context: from-internal Extension: h Priority: 1 Application: AGI AppData: agi://127.0.0.1/end Uniqueid: 1331937101.39 AGI Rx << VERBOSE "AGI starting at Sat Mar 17 09:31:46 2012 (1331937106)" 9 > agi://127.0.0.1/end: AGI starting at Sat Mar 17 09:31:46 2012 (1331937106) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Mar 17 09:31:46] DEBUG[10820]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1331937101.39' AGI Tx >> 200 result=1 (1331937101.39) AGI Rx << GET VARIABLE ANSWEREDTIME [Mar 17 09:31:46] DEBUG[10820]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '5' AGI Tx >> 200 result=1 (5) AGI Rx << GET VARIABLE DIALSTATUS [Mar 17 09:31:46] DEBUG[10820]: 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 [Mar 17 09:31:46] DEBUG[10820]: pbx.c:3236 ast_str_retrieve_variable: Result of 'PRODUCT-FAX-FILE' is NULL AGI Tx >> 200 result=0 [Mar 17 09:31:47] DEBUG[10813]: res_rtp_asterisk.c:1732 ast_rtcp_read: Got RTCP report of 52 bytes [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: RTCPReceived Privilege: reporting,all Timestamp: 1331937107.002284 From: yy.yy.yy.yy:4003 PT: 200(Sender Report) ReceptionReports: 1 SenderSSRC: 0 FractionLost: 0 PacketsLost: 0 HighestSequence: 40192 SequenceNumberCycles: 0 IAJitter: 28 LastSR: 0.0000000000 DLSR: 0.0000(sec) [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: RTCPSent Privilege: reporting,all Timestamp: 1331937107.012410 To: yy.yy.yy.yy:4003 OurSSRC: 234243495 SentNTP: 1331937107.0050565120 SentRTP: 9703856 SentPackets: 232 SentOctets: 7656 ReportBlock: FractionLost: 0 CumulativeLoss: 0 IAJitter: 0.0056 TheirLastSR: 1037167124 DLSR: 0.0100 (sec) <--- SIP read from UDP:xx.xx.xx.xx:60886 ---> OPTIONS sip:xx.xx.xx.xx:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:40827;branch=z9hG4bK.2f65f930;rport;alias From: sip:sipsak@xx.xx.xx.xx:40827;tag=20cf9a6 To: sip:xx.xx.xx.xx:5070 Call-ID: 34404774@xx.xx.xx.xx CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.xx.xx:40827 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 36]: OPTIONS sip:xx.xx.xx.xx:5070 SIP/2.0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 70]: Via: SIP/2.0/UDP xx.xx.xx.xx:40827;branch=z9hG4bK.2f65f930;rport;alias [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 46]: From: sip:sipsak@xx.xx.xx.xx:40827;tag=20cf9a6 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 24]: To: sip:xx.xx.xx.xx:5070 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 29]: Call-ID: 34404774@xx.xx.xx.xx [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 15]: CSeq: 1 OPTIONS [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 37]: Contact: sip:sipsak@xx.xx.xx.xx:40827 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 17]: Content-Length: 0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 18]: Accept: text/plain --- (11 headers 0 lines) --- [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 34404774@xx.xx.xx.xx (Checking From) --From tag 20cf9a6 --To-tag [Mar 17 09:31:47] DEBUG[8699]: acl.c:728 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'. [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:3482 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5070 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:7694 sip_alloc: Allocating new SIP dialog for 34404774@xx.xx.xx.xx - OPTIONS (No RTP) [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 17 09:31:47] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:5070' into... [Mar 17 09:31:47] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. [Mar 17 09:31:47] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx:40827' into... [Mar 17 09:31:47] DEBUG[8699]: 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:60886 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:40827;branch=z9hG4bK.2f65f930;alias;received=xx.xx.xx.xx;rport=60886 From: sip:sipsak@xx.xx.xx.xx:40827;tag=20cf9a6 To: sip:xx.xx.xx.xx:5070;tag=as3cf1fe7e Call-ID: 34404774@xx.xx.xx.xx CSeq: 1 OPTIONS Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:60886 Scheduling destruction of SIP dialog '34404774@xx.xx.xx.xx' in 32000 ms (Method: OPTIONS) <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> BYE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKfb37.11036eb3.0 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy Max-Forwards: 69 Date: Fri, 16 Mar 2012 22:34:24 GMT CSeq: 103 BYE User-Agent: Cisco-CP7960G/8.0 Content-Length: 0 RTP-RxStat: Dur=??,Pkt=??,Oct=??,LatePkt=??,LostPkt=??,AvgJit=?? RTP-TxStat: Dur=??,Pkt=??,Oct=?? Route: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3",response="ce3433d84fd44a3006d5ee6ea7e8cf6b",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 X-Enswitch-Source: yy.yy.yy.yy:5065 <-------------> [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 49]: BYE sip:**@xx.xx.xx.xx:5070;transport=udp SIP/2.0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 76]: Record-Route: [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKfb37.11036eb3.0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 59]: Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 82]: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 39]: To: ;tag=as243d9b54 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 59]: Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 16]: Max-Forwards: 69 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 8 [ 35]: Date: Fri, 16 Mar 2012 22:34:24 GMT [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 9 [ 13]: CSeq: 103 BYE [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 10 [ 29]: User-Agent: Cisco-CP7960G/8.0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 11 [ 17]: Content-Length: 0 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 12 [ 64]: RTP-RxStat: Dur=??,Pkt=??,Oct=??,LatePkt=??,LostPkt=??,AvgJit=?? [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 13 [ 32]: RTP-TxStat: Dur=??,Pkt=??,Oct=?? [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 14 [ 71]: Route: [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 15 [250]: Proxy-Authorization: Digest username="1000101",realm="xx.xx.xx.xx",uri="sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3",response="ce3433d84fd44a3006d5ee6ea7e8cf6b",nonce="4f63bf6b000082e758b2c83917faa7a279540adf0dc132a1",algorithm=md5 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 16 [ 79]: X-Enswitch-RURI: sip:**@xx.xx.xx.xx:5070;ftag=00170ec855f5cee501df3e4e-763953b3 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 17 [ 38]: X-Enswitch-Source: yy.yy.yy.yy:5065 --- (18 headers 0 lines) --- [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy (Checking From) --From tag 00170ec855f5cee501df3e4e-763953b3 --To-tag as243d9b54 [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:24884 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:24909 handle_incoming: Ignoring SIP message because of retransmit (BYE Seqno 103, ours 103) [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:23586 handle_request_bye: Initializing initreq for method BYE - callid 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:47] DEBUG[8699]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:47] DEBUG[8699]: netsock2.c:188 ast_sockaddr_split_hostport: ...host 'xx.xx.xx.xx' and port ''. Sending to xx.xx.xx.xx:5060 (NAT) [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:3070 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy [Mar 17 09:31:47] DEBUG[8699]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7bb1f8' [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:23689 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=z9hG4bKfb37.11036eb3.0;received=xx.xx.xx.xx;rport=5060 Via: SIP/2.0/UDP yy.yy.yy.yy:5065;branch=z9hG4bK5a3aba8e Record-Route: From: "A Aardvark" ;tag=00170ec855f5cee501df3e4e-763953b3 To: ;tag=as243d9b54 Call-ID: 00170ec8-55f50053-13cce575-336e322f@yy.yy.yy.yy CSeq: 103 BYE Server: Enswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Mar 17 09:31:47] DEBUG[8699]: chan_sip.c:3328 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.252849 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOS Value: ssrc=1226555569;themssrc=4116039694;lp=0;rxjitter=0.000230;rxcount=243;txjitter=0.000000;txcount=236;rlp=0;rtt=0.000000 Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.252863 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.252869 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.252874 Channel: SIP/product-local-00000011 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1331937101.39 -- AGI Script agi://127.0.0.1/end completed, returning 0 AGI Tx >> HANGUP [Mar 17 09:31:47] DEBUG[10820]: channel.c:2820 ast_hangup: Hanging up channel 'Local/1000103@product-pickup-f725;1' [Mar 17 09:31:47] DEBUG[10820]: app_dial.c:2901 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Mar 17 09:31:47] DEBUG[10820]: res_agi.c:3507 run_agi: SIP/product-local-00000011 hungup AGI Tx >> HANGUP [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.870518 Channel: SIP/product-local-00000011 Variable: AGISTATUS Value: SUCCESS Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937107.870638 Channel: Local/1000103@product-pickup-f725;1 Uniqueid: 1331937101.40 CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000101 ConnectedLineName: A Aardvark Cause: 16 Cause-txt: Normal Clearing [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.870663 Channel: SIP/product-local-00000011 Variable: DIALSTATUS Value: ANSWER Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Dial Privilege: call,all Timestamp: 1331937107.870667 SubEvent: End Channel: SIP/product-local-00000011 UniqueID: 1331937101.39 DialStatus: ANSWER [Mar 17 09:31:47] DEBUG[10813]: channel.c:7059 ast_generic_bridge: Didn't get a frame from channel: Local/1000103@product-pickup-f725;2 [Mar 17 09:31:47] DEBUG[10813]: res_rtp_asterisk.c:769 ast_rtp_update_source: Setting the marker bit due to a source update [Mar 17 09:31:47] DEBUG[10813]: channel.c:7518 ast_channel_bridge: Bridge stops bridging channels SIP/product-local-0000000f and Local/1000103@product-pickup-f725;2 [Mar 17 09:31:47] DEBUG[10813]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-0000000f' [Mar 17 09:31:47] DEBUG[10813]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [h@from-internal:1] AGI("SIP/product-local-0000000f", "agi://127.0.0.1/end") in new stack [Mar 17 09:31:47] DEBUG[10813]: 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 [Mar 17 09:31:47] DEBUG[10813]: 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-0000000f AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1331937099.35 AGI Tx >> agi_version: 1.8.9.2 AGI Tx >> agi_callerid: 1000104 AGI Tx >> agi_calleridname: unknown AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 1000103 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: 1113422144 AGI Tx >> [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-pickup Mar 17 09:31:47] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-pickup exists (devicestate) [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-pickup - state 1 (Not in use) [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-pickup' state '1' [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Unlink Privilege: call,all Timestamp: 1331937107.871072 Channel1: SIP/product-local-0000000f Channel2: Local/1000103@product-pickup-f725;2 Uniqueid1: 1331937099.35 Uniqueid2: 1331937099.36 CallerID1: 1000104 CallerID2: 1000101 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.871086 Channel: SIP/product-local-0000000f Variable: ANSWEREDTIME Value: 6 Uniqueid: 1331937099.35 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.871090 Channel: SIP/product-local-0000000f Variable: DIALEDTIME Value: 8 Uniqueid: 1331937099.35 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Newexten Privilege: dialplan,all Timestamp: 1331937107.871117 Channel: SIP/product-local-0000000f Context: from-internal Extension: h Priority: 1 Application: AGI AppData: agi://127.0.0.1/end Uniqueid: 1331937099.35 -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 4 AGI Tx >> HANGUP [Mar 17 09:31:47] ERROR[10820]: utils.c:1164 ast_carefulwrite: write() returned error: Broken pipe [Mar 17 09:31:47] DEBUG[10820]: pbx.c:5047 __ast_pbx_run: Spawn extension (from-internal,**,1) exited non-zero on 'SIP/product-local-00000011' == Spawn extension (from-internal, **, 1) exited non-zero on 'SIP/product-local-00000011' [Mar 17 09:31:47] DEBUG[10820]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-00000011' [Mar 17 09:31:47] DEBUG[10820]: channel.c:2820 ast_hangup: Hanging up channel 'SIP/product-local-00000011' [Mar 17 09:31:47] DEBUG[10820]: chan_sip.c:6233 sip_hangup: Hanging up zombie call. Be scared. [Mar 17 09:31:47] DEBUG[10820]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7bb1f8' [Mar 17 09:31:47] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-pickup' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937107.873365 Channel: SIP/product-local-00000011 Variable: AGISTATUS Value: HANGUP Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937107.873429 Channel: SIP/product-local-00000011 Uniqueid: 1331937101.39 CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: 1000104 ConnectedLineName: Cause: 16 Cause-txt: Normal Clearing [Mar 17 09:31:47] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: MonitorStop Privilege: call,all Timestamp: 1331937107.873480 Channel: SIP/product-local-00000011 Uniqueid: 1331937101.39 [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:47] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:47] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:47] DEBUG[8708]: 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 Rx << VERBOSE "AGI starting at Sat Mar 17 09:31:47 2012 (1331937107)" 9 > agi://127.0.0.1/end: AGI starting at Sat Mar 17 09:31:47 2012 (1331937107) AGI Tx >> 200 result=1 AGI Rx << SET VARIABLE CHANNEL(language) "en" AGI Tx >> 200 result=1 AGI Rx << GET VARIABLE PRODUCT-CALLID [Mar 17 09:31:47] DEBUG[10813]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PRODUCT-CALLID' is '1331937099.35' AGI Tx >> 200 result=1 (1331937099.35) AGI Rx << GET VARIABLE ANSWEREDTIME [Mar 17 09:31:47] DEBUG[10813]: pbx.c:3239 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '6' AGI Tx >> 200 result=1 (6) AGI Rx << GET VARIABLE DIALSTATUS Mar 17 09:31:47] DEBUG[10813]: 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 [Mar 17 09:31:47] DEBUG[10813]: 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/end completed, returning 0 AGI Tx >> HANGUP [Mar 17 09:31:48] DEBUG[10813]: channel.c:2820 ast_hangup: Hanging up channel 'Local/1000103@product-pickup-f725;2' [Mar 17 09:31:48] DEBUG[10813]: app_dial.c:2901 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Mar 17 09:31:48] DEBUG[10813]: res_agi.c:3507 run_agi: SIP/product-local-0000000f hungup AGI Tx >> HANGUP [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.904310 Channel: SIP/product-local-0000000f Variable: AGISTATUS Value: SUCCESS Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937108.904432 Channel: Local/1000103@product-pickup-f725;2 Uniqueid: 1331937099.36 CallerIDNum: 1000101 CallerIDName: A Aardvark ConnectedLineNum: 1000104 ConnectedLineName: Cause: 0 Cause-txt: Unknown [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.904451 Channel: SIP/product-local-0000000f Variable: DIALSTATUS Value: ANSWER Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Dial Privilege: call,all Timestamp: 1331937108.904454 SubEvent: End Channel: SIP/product-local-0000000f UniqueID: 1331937099.35 DialStatus: ANSWER [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for Local - 1000103@product-pickup [Mar 17 09:31:48] DEBUG[8675]: chan_local.c:300 local_devicestate: Checking if extension 1000103@product-pickup exists (devicestate) [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for Local/1000103@product-pickup - state 1 (Not in use) [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:438 devstate_event: device 'Local/1000103@product-pickup' state '1' [Mar 17 09:31:48] DEBUG[8708]: app_queue.c:1487 handle_statechange: Device 'Local/1000103@product-pickup' 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 [Mar 17 09:31:48] DEBUG[10813]: 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?stype=internal completed, returning 4 AGI Tx >> HANGUP [Mar 17 09:31:48] DEBUG[10813]: pbx.c:5047 __ast_pbx_run: Spawn extension (from-internal,1000103,1) exited non-zero on 'SIP/product-local-0000000f' == Spawn extension (from-internal, 1000103, 1) exited non-zero on 'SIP/product-local-0000000f' [Mar 17 09:31:48] DEBUG[10813]: channel.c:2680 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-0000000f' [Mar 17 09:31:48] DEBUG[10813]: channel.c:2820 ast_hangup: Hanging up channel 'SIP/product-local-0000000f' [Mar 17 09:31:48] DEBUG[10813]: chan_sip.c:6233 sip_hangup: Hanging up zombie call. Be scared. [Mar 17 09:31:48] DEBUG[10813]: res_rtp_asterisk.c:2487 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xd7783c8' Scheduling destruction of SIP dialog 'e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t' in 32000 ms (Method: ACK) [Mar 17 09:31:48] DEBUG[10813]: chan_sip.c:25681 stop_session_timer: Session timer stopped: 139 - e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t set_destination: Parsing for address/port to send to [Mar 17 09:31:48] DEBUG[10813]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting 'xx.xx.xx.xx' into... [Mar 17 09:31:48] DEBUG[10813]: 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:1000104@yy.yy.yy.yy:56485;transport=UDP;ob SIP/2.0 Via: SIP/2.0/UDP xx.xx.xx.xx:5070;branch=z9hG4bK5cdbbc1a;rport Route: Max-Forwards: 70 From: ;tag=as7c35e0a2 To: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t CSeq: 102 BYE User-Agent: Enswitch X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode: 0 Content-Length: 0 --- [Mar 17 09:31:48] DEBUG[10813]: chan_sip.c:3785 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #156 [Mar 17 09:31:48] DEBUG[10813]: chan_sip.c:3328 __sip_xmit: Trying to put 'BYE sip:100' onto UDP socket destined for xx.xx.xx.xx:5060 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.947916 Channel: SIP/product-local-0000000f Variable: AGISTATUS Value: HANGUP Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.948043 Channel: SIP/product-local-0000000f Variable: RTPAUDIOQOS Value: ssrc=234243495;themssrc=241145850;lp=0;rxjitter=0.004645;rxcount=288;txjitter=0.000000;txcount=232;rlp=0;rtt=0.000000 Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.948053 Channel: SIP/product-local-0000000f Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.948061 Channel: SIP/product-local-0000000f Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.948068 Channel: SIP/product-local-0000000f Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: VarSet Privilege: dialplan,all Timestamp: 1331937108.948077 Channel: SIP/product-local-0000000f Variable: RTPAUDIOQOS Value: ssrc=234243495;themssrc=241145850;lp=0;rxjitter=0.004645;rxcount=288;txjitter=0.000000;txcount=232;rlp=0;rtt=0.000000 Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: Hangup Privilege: call,all Timestamp: 1331937108.948213 Channel: SIP/product-local-0000000f Uniqueid: 1331937099.35 CallerIDNum: 1000104 CallerIDName: ConnectedLineNum: 1000101 ConnectedLineName: A Aardvark Cause: 0 Cause-txt: Unknown [Mar 17 09:31:48] DEBUG[9370]: manager.c:4216 match_filter: Examining event: Event: MonitorStop Privilege: call,all Timestamp: 1331937108.948275 Channel: SIP/product-local-0000000f Uniqueid: 1331937099.35 [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - product-local [Mar 17 09:31:48] DEBUG[8675]: chan_sip.c:26150 sip_devicestate: Checking device state for peer product-local [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:458 do_state_change: Changing state for SIP/product-local - state 1 (Not in use) [Mar 17 09:31:48] DEBUG[8675]: devicestate.c:438 devstate_event: device 'SIP/product-local' state '1' [Mar 17 09:31:48] DEBUG[8708]: 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. <--- SIP read from UDP:xx.xx.xx.xx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.xx.xx:5070;rport=5070;received=xx.xx.xx.xx;branch=z9hG4bK5cdbbc1a Record-Route: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t From: ;tag=as7c35e0a2 To: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U CSeq: 102 BYE Content-Length: 0 <-------------> [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 1 [ 88]: Via: SIP/2.0/UDP xx.xx.xx.xx:5070;rport=5070;received=xx.xx.xx.xx;branch=z9hG4bK5cdbbc1a [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 2 [ 50]: Record-Route: [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 3 [ 41]: Call-ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 4 [ 46]: From: ;tag=as7c35e0a2 [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 5 [ 66]: To: ;tag=Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 6 [ 13]: CSeq: 102 BYE [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8421 parse_request: Header 7 [ 17]: Content-Length: 0 --- (8 headers 0 lines) --- [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:8014 find_call: = Looking for Call ID: e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t (Checking To) --From tag as7c35e0a2 --To-tag Nj3uoAkttxTGIelTE8PMH.f9FQr1-76U [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:3980 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #156 [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:4013 __sip_ack: Stopping retransmission on 'e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived [Mar 17 09:31:48] DEBUG[8699]: chan_sip.c:6010 sip_destroy: Destroying SIP dialog e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t Really destroying SIP dialog 'e9.CEvKdY3-g1I-EOmLkOp2jJe5j6V6t' Method: ACK [Mar 17 09:31:48] DEBUG[8699]: rtp_engine.c:293 instance_destructor: Destroyed RTP instance '0xd7783c8' [Mar 17 09:31:49] DEBUG[8699]: chan_sip.c:3869 __sip_autodestruct: Auto destroying SIP dialog '214513849@xx.xx.xx.xx' [Mar 17 09:31:49] DEBUG[8699]: chan_sip.c:6010 sip_destroy: Destroying SIP dialog 214513849@xx.xx.xx.xx Really destroying SIP dialog '214513849@xx.xx.xx.xx' Method: OPTIONS