[Jan 14 09:03:37] VERBOSE[9260] config.c: == Parsing '/etc/asterisk/logger.conf': [Jan 14 09:03:37] DEBUG[9260] config.c: Parsing /etc/asterisk/logger.conf [Jan 14 09:03:37] VERBOSE[9260] config.c: == Found [Jan 14 09:03:37] VERBOSE[9260] logger.c: Asterisk Queue Logger restarted [Jan 14 09:03:37] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:37] VERBOSE[9408] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 14 09:03:37] VERBOSE[9408] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:37] DEBUG[9408] channel.c: Hanging up channel 'SIP/product-local-00001712' [Jan 14 09:03:37] DEBUG[9408] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 09:03:37] DEBUG[9408] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c8030f28' [Jan 14 09:03:37] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:37] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:37] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:37] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:37] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:39] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:03:39] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:36107 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:58970;branch=z9hG4bK.5e47f74b;rport;alias From: sip:sipsak@xx.xx.46.25:58970;tag=15edd8fc To: sip:xx.xx.46.25:5070 Call-ID: 367909116@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:58970 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:58970;branch=z9hG4bK.5e47f74b;rport;alias [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:58970;tag=15edd8fc [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 4 [ 31]: Call-ID: 367909116@xx.xx.46.25 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:58970 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 09:03:39] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: = Looking for Call ID: 367909116@xx.xx.46.25 (Checking From) --From tag 15edd8fc --To-tag [Jan 14 09:03:39] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 367909116@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 09:03:39] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:39] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:39] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:58970' into... [Jan 14 09:03:39] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:39] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 09:03:39] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:36107 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:58970;branch=z9hG4bK.5e47f74b;alias;received=xx.xx.46.25;rport=36107 From: sip:sipsak@xx.xx.46.25:58970;tag=15edd8fc To: sip:xx.xx.46.25:5070;tag=as3f1b4ee0 Call-ID: 367909116@xx.xx.46.25 CSeq: 1 OPTIONS Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Jan 14 09:03:39] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:36107 [Jan 14 09:03:39] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '367909116@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:03:41] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1317276851@xx.xx.46.25' [Jan 14 09:03:41] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1317276851@xx.xx.46.25 [Jan 14 09:03:41] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1317276851@xx.xx.46.25' Method: OPTIONS [Jan 14 09:03:42] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:44] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> INVITE sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-853f7459 From: "A C" ;tag=55ccf804248dc50do0 To: "P M" Call-ID: 472ee090-fe2c15f1@10.0.0.214 CSeq: 102 INVITE Max-Forwards: 69 Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3ca110000124f7cacf755ee6cc487ca20adaca4a50990",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="b7ac2d519b89559842add8ed29a3fbba" Contact: "A C" Expires: 240 User-Agent: Cisco/SPA502G-7.5.4 Content-Length: 443 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp X-product-RURI: sip:0000003@hostname.example.com X-product-Source: yy.yy.10.241:19050 v=0 o=- 42126018 42126018 IN IP4 10.0.0.214 s=- c=IN IP4 yy.yy.10.241 t=0 0 m=audio 16428 RTP/AVP 9 0 2 8 18 96 97 98 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv a=direction:active a=oldmediaip:10.0.0.214 <-------------> [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 0 [ 58]: INVITE sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-853f7459 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 4 [ 77]: From: "A C" ;tag=55ccf804248dc50do0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 5 [ 51]: To: "P M" [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 6 [ 37]: Call-ID: 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 9 [225]: Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3ca110000124f7cacf755ee6cc487ca20adaca4a50990",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="b7ac2d519b89559842add8ed29a3fbba" [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 10 [ 58]: Contact: "A C" [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 11 [ 12]: Expires: 240 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 12 [ 31]: User-Agent: Cisco/SPA502G-7.5.4 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 13 [ 19]: Content-Length: 443 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 14 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 15 [ 19]: Supported: replaces [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 16 [ 29]: Content-Type: application/sdp [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 17 [ 47]: X-product-RURI: sip:0000003@hostname.example.com [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 18 [ 38]: X-product-Source: yy.yy.10.241:19050 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 19 [ 0]: [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 1 [ 39]: o=- 42126018 42126018 IN IP4 10.0.0.214 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 3 [ 22]: c=IN IP4 yy.yy.10.241 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 5 [ 45]: m=audio 16428 RTP/AVP 9 0 2 8 18 96 97 98 101 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 17 [ 10]: a=sendrecv [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 18 [ 18]: a=direction:active [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Body 19 [ 23]: a=oldmediaip:10.0.0.214 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: --- (19 headers 20 lines) --- [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: = Looking for Call ID: 472ee090-fe2c15f1@10.0.0.214 (Checking From) --From tag 55ccf804248dc50do0 --To-tag [Jan 14 09:03:47] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 472ee090-fe2c15f1@10.0.0.214 - INVITE (No RTP) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 09:03:47] DEBUG[5183] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 14 09:03:47] DEBUG[5183] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 14 09:03:47] DEBUG[5183] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 14 09:03:47] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:47] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Initializing initreq for method INVITE - callid 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Using INVITE request as basis request - 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:47] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:47] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:47] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0000004' AND host = 'dynamic' [Jan 14 09:03:47] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0000004' [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found peer 'product-local' for '0000004' from xx.xx.46.25:5060 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74c40415f8' [Jan 14 09:03:47] DEBUG[5183] res_rtp_asterisk.c: Allocated port 18826 for RTP instance '0x2b74c40415f8' [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: RTP instance '0x2b74c40415f8' is setup and ready to go [Jan 14 09:03:47] DEBUG[5183] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74c40415f8' [Jan 14 09:03:47] VERBOSE[5183] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Setting NAT on RTP to On [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 42126018 42126018 IN IP4 10.0.0.214... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] netsock2.c: Splitting 'yy.yy.10.241' into... [Jan 14 09:03:47] DEBUG[5183] netsock2.c: ...host 'yy.yy.10.241' and port ''. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 yy.yy.10.241... OK. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 0 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 2 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 8 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 8 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 18 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 18 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 96 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 97 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 97 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 98 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 98 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format G726-32 for ID 2 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format G729a for ID 18 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Unsetting payload 96 on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-40 for ID 96 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Unsetting payload 97 on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-24 for ID 97 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Unsetting payload 98 on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-16 for ID 98 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:10.0.0.214... UNSUPPORTED. [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 0 on 0x2b74bb598290 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 2 on 0x2b74bb598290 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 8 on 0x2b74bb598290 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598290 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 18 on 0x2b74bb598290 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598290 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Capabilities: us - 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722), peer - audio=0x190c (ulaw|alaw|g726|g729|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 09:03:47] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c40415f8' [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port yy.yy.10.241:16428 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 0 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 2 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 8 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 18 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598290 to 0x2b74c40417c0 [Jan 14 09:03:47] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74c40415f8' [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Checking SIP call limits for device [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Updating call counter for incoming call [Jan 14 09:03:47] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:47] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:47] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:47] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: Looking for 0000003 in from-internal (domain xx.xx.46.25) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: *** Joint capabilities are 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: This channel will not be able to handle video. [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: SIP/product-local-00001713: New call is still down.... Trying... [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-853f7459 Record-Route: From: "A C" ;tag=55ccf804248dc50do0 To: "P M" Call-ID: 472ee090-fe2c15f1@10.0.0.214 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:47] DEBUG[9536] pbx.c: Launching 'AGI' [Jan 14 09:03:47] VERBOSE[9536] pbx.c: -- Executing [0000003@from-internal:1] AGI("SIP/product-local-00001713", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 14 09:03:47] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:47] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:47] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:47] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:47] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_network_script: product?stype=internal [Jan 14 09:03:47] DEBUG[9536] res_agi.c: Wow, connected! [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-00001713 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_uniqueid: 1358154227.13485 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_callerid: 0000004 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_calleridname: A C [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_dnid: 0000003 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_extension: 0000003 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> agi_threadid: 47780447246080 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:03:47 2013 (1358154227)" 9 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: > agi://127.0.0.1/product?stype=internal: AGI starting at Mon Jan 14 09:03:47 2013 (1358154227) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-CALLID' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1358154227.13485" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-SCREEN' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-DIVERTED' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-DIVERSION' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:47] VERBOSE[9536] func_timeout.c: Channel will hangup at 2013-01-15 09:03:47.313 GMT. [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-CUTOFF' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:47] VERBOSE[9536] func_timeout.c: Channel will hangup at 2013-01-15 09:03:47.313 GMT. [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (472ee090-fe2c15f1@10.0.0.214) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: 472ee090-fe2c15f1@10.0.0.214" 9 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-SCUSTOMER' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (yy.yy.10.241:19050) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-PRESENTATION-INTERNAL' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-PRESENTATION-EXTERNAL' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-External) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-TRANSFER-PHONE' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-CUSTOMER [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-TRANSFER-CUSTOMER' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Proxy-Authorization) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (Digest username="0000004",realm="hostname.example.com",nonce="50f3ca110000124f7cacf755ee6cc487ca20adaca4a50990",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="b7ac2d519b89559842add8ed29a3fbba") [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "10" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "10" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER01 "Alert-Info: Simple-1" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '0000003', old '', forward 1 for channel SIP/product-local-00001713" 5 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '0000003', old '', forward 1 for channel SIP/product-local-00001713 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << VERBOSE "Starting recording group '1' expires '1359363827' file '/var/lib/product/recordings/2/1/2013/01/14/record_135815422713485_6713'" 9 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: > agi://127.0.0.1/product?stype=internal: Starting recording group '1' expires '1359363827' file '/var/lib/product/recordings/2/1/2013/01/14/record_135815422713485_6713' [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << EXEC Monitor gsm,/var/lib/product/recordings/2/1/2013/01/14/record_135815422713485_6713 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: -- AGI Script Executing Application: (Monitor) Options: (gsm,/var/lib/product/recordings/2/1/2013/01/14/record_135815422713485_6713) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 14 09:03:47] DEBUG[9536] pbx.c: Result of 'product-QUEUE' is NULL [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (472ee090-fe2c15f1@10.0.0.214) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (A C) [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1358154227.13485, phone:0000004 - phone:0000003." 9 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1358154227.13485, phone:0000004 - phone:0000003. [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:47] VERBOSE[9536] func_timeout.c: Channel will hangup at 2013-01-15 09:03:47.406 GMT. [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "2" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "phone" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "0000003" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "0000004" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "2" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "86400" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-PHONE-DOMAIN "xx.xx.46.25:5060" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-PHONE-OPTS "ortM(product-answered^0^1358154227.13485)" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER11 "X-product-Uniqueid: 1358154227.13485" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-PHONE "0000003" [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: AGI Rx << EXEC Dial Local/0000003@product-phone/n,20,o [Jan 14 09:03:47] VERBOSE[9536] res_agi.c: -- AGI Script Executing Application: (Dial) Options: (Local/0000003@product-phone/n,20,o) [Jan 14 09:03:47] DEBUG[9536] rtp_engine.c: Can't find native functions for channel 'Local/0000003@product-phone-456a;1' [Jan 14 09:03:47] DEBUG[9536] rtp_engine.c: Seeded SDP of 'Local/0000003@product-phone-456a;1' with that of 'SIP/product-local-00001713' [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable DIALEDTIME. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable ANSWEREDTIME. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable DIALEDPEERNAME. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable DIALSTATUS. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-TRANSFER-PHONE. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable SIPADDHEADER11. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-PHONE-OPTS. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-PHONE-DOMAIN. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-CUTOFF. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-PRESENTATION-EXTERNAL. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-PRESENTATION-INTERNAL. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-TRANSFER-CUSTOMER. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-DNUMBER. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-DTYPE. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-DCUSTOMER. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable MONITORED. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable SIPADDHEADER01. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-MUSIC. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 14 09:03:47] DEBUG[9536] channel.c: Copying hard-transferable variable product-CALLID. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable SIPCALLID. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable SIPDOMAIN. [Jan 14 09:03:47] DEBUG[9536] channel.c: Not copying variable SIPURI. [Jan 14 09:03:47] VERBOSE[9536] app_dial.c: -- Called Local/0000003@product-phone/n [Jan 14 09:03:47] DEBUG[9558] pbx.c: Result of 'product-MUSIC' is '10' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Expression result is '0' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Launching 'GotoIf' [Jan 14 09:03:47] VERBOSE[9558] pbx.c: -- Executing [0000003@product-phone:1] GotoIf("Local/0000003@product-phone-456a;2", "0?3") in new stack [Jan 14 09:03:47] DEBUG[9558] pbx.c: Not taking any branch [Jan 14 09:03:47] DEBUG[9558] pbx.c: Result of 'product-MUSIC' is '10' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Launching 'SetMusicOnHold' [Jan 14 09:03:47] VERBOSE[9558] pbx.c: -- Executing [0000003@product-phone:2] SetMusicOnHold("Local/0000003@product-phone-456a;2", "10") in new stack [Jan 14 09:03:47] DEBUG[9558] pbx.c: Result of 'EXTEN' is '0000003' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Result of 'product-PHONE-DOMAIN' is 'xx.xx.46.25:5060' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Result of 'product-PHONE-OPTS' is 'ortM(product-answered^0^1358154227.13485)' [Jan 14 09:03:47] DEBUG[9558] pbx.c: Launching 'Dial' [Jan 14 09:03:47] VERBOSE[9558] pbx.c: -- Executing [0000003@product-phone:3] Dial("Local/0000003@product-phone-456a;2", "SIP/0000003@xx.xx.46.25:5060,3600,ortM(product-answered^0^1358154227.13485)") in new stack [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Asked to create a SIP channel with formats: 0x1000 (g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Allocating new SIP dialog for 748caf9f2ec53be871854cde2065e706@xx.xx.46.25:5070 - INVITE (No RTP) [Jan 14 09:03:47] DEBUG[9558] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[9558] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' AND host = 'dynamic' [Jan 14 09:03:47] DEBUG[9558] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[9558] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 09:03:47] DEBUG[9558] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74c80492a8' [Jan 14 09:03:47] DEBUG[9558] res_rtp_asterisk.c: Allocated port 18422 for RTP instance '0x2b74c80492a8' [Jan 14 09:03:47] DEBUG[9558] rtp_engine.c: RTP instance '0x2b74c80492a8' is setup and ready to go [Jan 14 09:03:47] DEBUG[9558] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74c80492a8' [Jan 14 09:03:47] VERBOSE[9558] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Setting NAT on RTP to On [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jan 14 09:03:47] DEBUG[9558] netsock2.c: Splitting 'xx.xx.46.25:5060' into... [Jan 14 09:03:47] DEBUG[9558] netsock2.c: ...host 'xx.xx.46.25' and port '5060'. [Jan 14 09:03:47] DEBUG[9558] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** Joint capabilities are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** Our preferred formats from the incoming channel are 0x1000 (g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: This channel will not be able to handle video. [Jan 14 09:03:47] DEBUG[9558] channel.c: Not copying variable DIALEDTIME. [Jan 14 09:03:47] DEBUG[9558] channel.c: Not copying variable ANSWEREDTIME. [Jan 14 09:03:47] DEBUG[9558] channel.c: Not copying variable DIALEDPEERNAME. [Jan 14 09:03:47] DEBUG[9558] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 09:03:47] DEBUG[9558] channel.c: Not copying variable DIALSTATUS. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-TRANSFER-PHONE. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable SIPADDHEADER11. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-PHONE-OPTS. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-PHONE-DOMAIN. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-CUTOFF. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-PRESENTATION-EXTERNAL. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-PRESENTATION-INTERNAL. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-TRANSFER-CUSTOMER. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-DNUMBER. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-DTYPE. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-DCUSTOMER. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable MONITORED. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable SIPADDHEADER01. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-MUSIC. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 14 09:03:47] DEBUG[9558] channel.c: Copying hard-transferable variable product-CALLID. [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Outgoing Call for 0000003 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Updating call counter for outgoing call [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Adding SIP Header "X-product-Uniqueid" with content :1358154227.13485: [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Adding SIP Header "Alert-Info" with content :Simple-1: [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: ** Our capability: 0x1dee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g722) Video flag: False Text flag: False [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: ** Our prefcodec: 0x1000 (g722) [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Audio is at 18422 [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x1000 (g722) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x40 (slin) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x2 (gsm) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x800 (g726) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x20 (adpcm) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x80 (lpc10) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x400 (ilbc) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Done building SDP. Settling with this capability: 0x1dee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g722) [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Initializing initreq for method INVITE - callid 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 0 [ 44]: INVITE sip:0000003@xx.xx.46.25:5060 SIP/2.0 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK060f116f;rport [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 3 [ 68]: From: "A C" ;tag=as7ef11ca5 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 4 [ 35]: To: [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 5 [ 40]: Contact: [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 6 [ 59]: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 8 [ 20]: User-Agent: product [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 9 [ 35]: Date: Mon, 14 Jan 2013 09:03:47 GMT [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 12 [ 37]: X-product-Uniqueid: 1358154227.13485 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 13 [ 20]: Alert-Info: Simple-1 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jan 14 09:03:47] VERBOSE[9558] chan_sip.c: Reliably Transmitting (NAT) to xx.xx.46.25:5060: INVITE sip:0000003@xx.xx.46.25:5060 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK060f116f;rport Max-Forwards: 70 From: "A C" ;tag=as7ef11ca5 To: Contact: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 102 INVITE User-Agent: product Date: Mon, 14 Jan 2013 09:03:47 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-product-Uniqueid: 1358154227.13485 Alert-Info: Simple-1 Content-Type: application/sdp Content-Length: 503 v=0 o=root 1865857776 1865857776 IN IP4 xx.xx.46.25 s=Asterisk PBX 1.8.11.1 c=IN IP4 xx.xx.46.25 t=0 0 m=audio 18422 RTP/AVP 9 0 8 10 3 111 5 7 97 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:10 L16/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:7 LPC/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110753 [Jan 14 09:03:47] DEBUG[9558] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:47] VERBOSE[9558] app_dial.c: -- Called SIP/0000003@xx.xx.46.25:5060 [Jan 14 09:03:47] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 09:03:47] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 09:03:47] VERBOSE[9536] app_dial.c: -- Local/0000003@product-phone-456a;1 is ringing [Jan 14 09:03:47] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 2 (In use) [Jan 14 09:03:47] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '2' [Jan 14 09:03:47] VERBOSE[9536] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-853f7459 Record-Route: From: "A C" ;tag=55ccf804248dc50do0 To: "P M" ;tag=as7d887481 Call-ID: 472ee090-fe2c15f1@10.0.0.214 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 14 09:03:47] DEBUG[9536] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:47] DEBUG[5189] app_queue.c: Device 'Local/0000003@product-phone' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 100 Giving a try Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK060f116f;rport=5070 From: "A C" ;tag=as7ef11ca5 To: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 102 INVITE Server: product SIP proxy Content-Length: 0 Warning: 392 xx.xx.46.25:5060 "Noisy feedback tells: pid=24284 req_src_ip=xx.xx.46.25 req_src_port=5070 in_uri=sip:0000003@xx.xx.46.25:5060 out_uri=sip:0000003@10.0.0.213:5060 via_cnt==1" <-------------> [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 0 [ 24]: SIP/2.0 100 Giving a try [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK060f116f;rport=5070 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as7ef11ca5 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 3 [ 35]: To: [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 4 [ 59]: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 6 [ 26]: Server: product SIP proxy [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 8 [190]: Warning: 392 xx.xx.46.25:5060 "Noisy feedback tells: pid=24284 req_src_ip=xx.xx.46.25 req_src_port=5070 in_uri=sip:0000003@xx.xx.46.25:5060 out_uri=sip:0000003@10.0.0.213:5060 via_cnt==1" [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: = Looking for Call ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 (Checking To) --From tag as7ef11ca5 --To-tag [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: *** SIP TIMER: Cancelling retransmission #110753 - INVITE (got response) [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070' Request 102: Found [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: SIP response 100 to standard invite [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 180 Ringing To: ;tag=c5f4ffd76b09728ai0 From: "A C" ;tag=as7ef11ca5 Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK060f116f;rport=5070 Record-Route: Contact: "P M" Server: Cisco/SPA502G-7.5.3 Content-Length: 0 <-------------> [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 1 [ 58]: To: ;tag=c5f4ffd76b09728ai0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as7ef11ca5 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 3 [ 59]: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 5 [ 90]: Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK060f116f;rport=5070 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 6 [ 54]: Record-Route: [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 7 [ 57]: Contact: "P M" [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 8 [ 27]: Server: Cisco/SPA502G-7.5.3 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: --- (10 headers 0 lines) --- [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: = Looking for Call ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 (Checking To) --From tag as7ef11ca5 --To-tag c5f4ffd76b09728ai0 [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070' Request 102: Found [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: SIP response 180 to standard invite [Jan 14 09:03:47] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 09:03:47] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 09:03:47] VERBOSE[9558] app_dial.c: -- SIP/xx.xx.46.25:5060-00001714 is ringing [Jan 14 09:03:47] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - xx.xx.46.25:5060 [Jan 14 09:03:47] DEBUG[5161] chan_sip.c: Checking device state for peer xx.xx.46.25:5060 [Jan 14 09:03:47] VERBOSE[9536] app_dial.c: -- Local/0000003@product-phone-456a;1 is ringing [Jan 14 09:03:47] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' AND host = 'dynamic' [Jan 14 09:03:47] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:47] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 09:03:47] DEBUG[5161] devicestate.c: Changing state for SIP/xx.xx.46.25:5060 - state 6 (Ringing) [Jan 14 09:03:47] DEBUG[5161] devicestate.c: device 'SIP/xx.xx.46.25:5060' state '6' [Jan 14 09:03:47] DEBUG[5189] app_queue.c: Device 'SIP/xx.xx.46.25:5060' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 14 09:03:47] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:49] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:55439 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:56521;branch=z9hG4bK.2c394b77;rport;alias From: sip:sipsak@xx.xx.46.25:56521;tag=53eeb61e To: sip:xx.xx.46.25:5070 Call-ID: 1408153118@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:56521 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:56521;branch=z9hG4bK.2c394b77;rport;alias [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:56521;tag=53eeb61e [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1408153118@xx.xx.46.25 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:56521 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1408153118@xx.xx.46.25 (Checking From) --From tag 53eeb61e --To-tag [Jan 14 09:03:49] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1408153118@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 09:03:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:56521' into... [Jan 14 09:03:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:55439 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:56521;branch=z9hG4bK.2c394b77;alias;received=xx.xx.46.25;rport=55439 From: sip:sipsak@xx.xx.46.25:56521;tag=53eeb61e To: sip:xx.xx.46.25:5070;tag=as18b1c482 Call-ID: 1408153118@xx.xx.46.25 CSeq: 1 OPTIONS Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:55439 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1408153118@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 200 OK To: ;tag=c5f4ffd76b09728ai0 From: "A C" ;tag=as7ef11ca5 Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK060f116f;rport=5070 Record-Route: Contact: "P M" Server: Cisco/SPA502G-7.5.3 Content-Length: 254 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 57710070 57710070 IN IP4 10.0.0.213 s=- c=IN IP4 yy.yy.10.241 t=0 0 m=audio 16470 RTP/AVP 9 101 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv a=direction:active a=oldmediaip:10.0.0.213 <-------------> [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 1 [ 58]: To: ;tag=c5f4ffd76b09728ai0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as7ef11ca5 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 3 [ 59]: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 5 [ 90]: Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK060f116f;rport=5070 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 6 [ 54]: Record-Route: [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 7 [ 57]: Contact: "P M" [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 8 [ 27]: Server: Cisco/SPA502G-7.5.3 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 9 [ 19]: Content-Length: 254 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 10 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 11 [ 19]: Supported: replaces [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Header 13 [ 0]: [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 1 [ 39]: o=- 57710070 57710070 IN IP4 10.0.0.213 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 3 [ 22]: c=IN IP4 yy.yy.10.241 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 5 [ 27]: m=audio 16470 RTP/AVP 9 101 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 11 [ 18]: a=direction:active [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Body 12 [ 23]: a=oldmediaip:10.0.0.213 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: --- (13 headers 13 lines) --- [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: = Looking for Call ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 (Checking To) --From tag as7ef11ca5 --To-tag c5f4ffd76b09728ai0 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Acked pending invite 102 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Stopping retransmission on '73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070' of Request 102: Match Found [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: SIP response 200 to standard invite [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 57710070 57710070 IN IP4 10.0.0.213... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] netsock2.c: Splitting 'yy.yy.10.241' into... [Jan 14 09:03:49] DEBUG[5183] netsock2.c: ...host 'yy.yy.10.241' and port ''. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 yy.yy.10.241... OK. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598db0 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598db0 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:10.0.0.213... UNSUPPORTED. [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598db0 [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598db0 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Capabilities: us - 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722), peer - audio=0x1000 (g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x1000 (g722) [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 09:03:49] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c80492a8' [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port yy.yy.10.241:16470 [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598db0 to 0x2b74c8049470 [Jan 14 09:03:49] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598db0 to 0x2b74c8049470 [Jan 14 09:03:49] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74c80492a8' [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x1000 (g722) [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: We have an owner, now see if we need to change this call [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Updating call counter for outgoing call [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 09:03:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: set_destination: set destination to xx.xx.46.25:5060 [Jan 14 09:03:49] VERBOSE[5183] chan_sip.c: Transmitting (NAT) to xx.xx.46.25:5060: ACK sip:0000003@yy.yy.10.241:59990 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK4763f920;rport Route: Max-Forwards: 70 From: "A C" ;tag=as7ef11ca5 To: ;tag=c5f4ffd76b09728ai0 Contact: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 102 ACK User-Agent: product Content-Length: 0 --- [Jan 14 09:03:49] DEBUG[5183] chan_sip.c: Trying to put 'ACK sip:000' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:49] VERBOSE[9558] app_dial.c: -- SIP/xx.xx.46.25:5060-00001714 answered Local/0000003@product-phone-456a;2 [Jan 14 09:03:49] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - xx.xx.46.25:5060 [Jan 14 09:03:49] DEBUG[5161] chan_sip.c: Checking device state for peer xx.xx.46.25:5060 [Jan 14 09:03:49] DEBUG[9558] pbx.c: Result of 'ARG1' is '0' [Jan 14 09:03:49] DEBUG[9558] pbx.c: Result of 'ARG2' is '1358154227.13485' [Jan 14 09:03:49] DEBUG[9558] pbx.c: Result of 'ARG3' is NULL [Jan 14 09:03:49] DEBUG[9558] pbx.c: Result of 'ARG4' is NULL [Jan 14 09:03:49] DEBUG[9558] pbx.c: Launching 'AGI' [Jan 14 09:03:49] VERBOSE[9558] pbx.c: -- Executing [s@macro-product-answered:1] AGI("SIP/xx.xx.46.25:5060-00001714", "agi://127.0.0.1/answered?screen=0&puniqueid=1358154227.13485&pcallid=&snumber=") in new stack [Jan 14 09:03:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' AND host = 'dynamic' [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_network_script: answered?screen=0&puniqueid=1358154227.13485&pcallid=&snumber= [Jan 14 09:03:49] DEBUG[9558] res_agi.c: Wow, connected! [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/answered?screen=0&puniqueid=1358154227.13485&pcallid=&snumber= [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_channel: SIP/xx.xx.46.25:5060-00001714 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_uniqueid: 1358154227.13488 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:03:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_callerid: 0000004 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_calleridname: A C [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:03:49] DEBUG[5161] devicestate.c: Changing state for SIP/xx.xx.46.25:5060 - state 2 (In use) [Jan 14 09:03:49] DEBUG[5161] devicestate.c: device 'SIP/xx.xx.46.25:5060' state '2' [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_dnid: unknown [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_context: macro-product-answered [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_extension: s [Jan 14 09:03:49] DEBUG[5189] app_queue.c: Device 'SIP/xx.xx.46.25:5060' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> agi_threadid: 47780369794816 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:03:49 2013 (1358154229)" 9 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: > agi://127.0.0.1/answered?screen=0&puniqueid=1358154227.13485&pcallid=&snumber=: AGI starting at Mon Jan 14 09:03:49 2013 (1358154229) [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:03:49] DEBUG[9558] pbx.c: Result of 'product-CALLID' is '1358154227.13485' [Jan 14 09:03:49] VERBOSE[9558] res_agi.c: AGI Tx >> 200 result=1 (1358154227.13485) [Jan 14 09:03:49] DEBUG[9558] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c80492a8' [Jan 14 09:03:49] DEBUG[9558] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address yy.yy.10.241:20121 [Jan 14 09:03:50] VERBOSE[9558] res_agi.c: AGI Rx << SET VARIABLE MACRO_RESULT "" [Jan 14 09:03:50] VERBOSE[9558] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:50] VERBOSE[9558] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFERRED-BY [Jan 14 09:03:50] DEBUG[9558] pbx.c: Result of 'product-TRANSFERRED-BY' is NULL [Jan 14 09:03:50] VERBOSE[9558] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:50] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:51] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1062659034@xx.xx.46.25' [Jan 14 09:03:51] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1062659034@xx.xx.46.25 [Jan 14 09:03:51] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1062659034@xx.xx.46.25' Method: OPTIONS [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> INVITE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.0 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-190879bb From: ;tag=69b5ad378179cfafo0 To: Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 102 INVITE Max-Forwards: 69 Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@hostname.example.com",algorithm=MD5,response="7dd62c1effb3d6517960cfd5253e0ab4" Contact: Expires: 240 User-Agent: Cisco/SPA502G-7.4.9c Content-Length: 447 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp X-product-RURI: sip:123@hostname.example.com X-product-Source: zz.zz.74.210:30259 v=0 o=- 345555195 345555195 IN IP4 192.168.1.33 s=- c=IN IP4 zz.zz.74.210 t=0 0 m=audio 16478 RTP/AVP 9 0 2 8 18 96 97 98 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv a=direction:active a=oldmediaip:192.168.1.33 <-------------> [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 0 [ 54]: INVITE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-190879bb [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 4 [ 61]: From: ;tag=69b5ad378179cfafo0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 5 [ 32]: To: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 6 [ 39]: Call-ID: 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 9 [221]: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@hostname.example.com",algorithm=MD5,response="7dd62c1effb3d6517960cfd5253e0ab4" [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 10 [ 40]: Contact: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 11 [ 12]: Expires: 240 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 12 [ 32]: User-Agent: Cisco/SPA502G-7.4.9c [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 13 [ 19]: Content-Length: 447 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 14 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 15 [ 19]: Supported: replaces [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 16 [ 29]: Content-Type: application/sdp [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 17 [ 43]: X-product-RURI: sip:123@hostname.example.com [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 18 [ 36]: X-product-Source: zz.zz.74.210:30259 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 19 [ 0]: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 1 [ 43]: o=- 345555195 345555195 IN IP4 192.168.1.33 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 3 [ 20]: c=IN IP4 zz.zz.74.210 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 5 [ 45]: m=audio 16478 RTP/AVP 9 0 2 8 18 96 97 98 101 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 17 [ 10]: a=sendrecv [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 18 [ 18]: a=direction:active [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Body 19 [ 25]: a=oldmediaip:192.168.1.33 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: --- (19 headers 20 lines) --- [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: = Looking for Call ID: 870281d7-89b2038f@192.168.1.33 (Checking From) --From tag 69b5ad378179cfafo0 --To-tag [Jan 14 09:03:52] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 870281d7-89b2038f@192.168.1.33 - INVITE (No RTP) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 09:03:52] DEBUG[5183] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 14 09:03:52] DEBUG[5183] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 14 09:03:52] DEBUG[5183] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 14 09:03:52] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:52] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Initializing initreq for method INVITE - callid 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Using INVITE request as basis request - 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:52] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:52] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:52] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:52] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0646061' AND host = 'dynamic' [Jan 14 09:03:52] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:52] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0646061' [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found peer 'product-local' for '0646061' from xx.xx.46.25:5060 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74bc010758' [Jan 14 09:03:52] DEBUG[5183] res_rtp_asterisk.c: Allocated port 19260 for RTP instance '0x2b74bc010758' [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: RTP instance '0x2b74bc010758' is setup and ready to go [Jan 14 09:03:52] DEBUG[5183] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74bc010758' [Jan 14 09:03:52] VERBOSE[5183] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Setting NAT on RTP to On [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 345555195 345555195 IN IP4 192.168.1.33... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] netsock2.c: Splitting 'zz.zz.74.210' into... [Jan 14 09:03:52] DEBUG[5183] netsock2.c: ...host 'zz.zz.74.210' and port ''. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 zz.zz.74.210... OK. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 0 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 0 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 2 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 8 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 8 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 18 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 18 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 96 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 97 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 97 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 98 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 98 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format G726-32 for ID 2 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format G729a for ID 18 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Unsetting payload 96 on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-40 for ID 96 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Unsetting payload 97 on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-24 for ID 97 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Unsetting payload 98 on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-16 for ID 98 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:192.168.1.33... UNSUPPORTED. [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 0 on 0x2b74bb598290 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 2 on 0x2b74bb598290 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 8 on 0x2b74bb598290 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598290 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 18 on 0x2b74bb598290 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598290 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Capabilities: us - 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722), peer - audio=0x190c (ulaw|alaw|g726|g729|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 09:03:52] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc010758' [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port zz.zz.74.210:16478 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 0 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 2 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 8 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 18 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598290 to 0x2b74bc010920 [Jan 14 09:03:52] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74bc010758' [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Checking SIP call limits for device [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Updating call counter for incoming call [Jan 14 09:03:52] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:52] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:52] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:52] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: Looking for 123 in from-internal (domain xx.xx.46.25) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: *** Joint capabilities are 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: This channel will not be able to handle video. [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: SIP/product-local-00001715: New call is still down.... Trying... [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-190879bb Record-Route: From: ;tag=69b5ad378179cfafo0 To: Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:52] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:52] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:52] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:52] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:52] DEBUG[9621] pbx.c: Launching 'AGI' [Jan 14 09:03:52] VERBOSE[9621] pbx.c: -- Executing [123@from-internal:1] AGI("SIP/product-local-00001715", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 14 09:03:52] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_network_script: product?stype=internal [Jan 14 09:03:52] DEBUG[9621] res_agi.c: Wow, connected! [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-00001715 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_uniqueid: 1358154232.13489 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callerid: 0646061 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_dnid: 123 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_extension: 123 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> agi_threadid: 47780441097984 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:03:52 2013 (1358154232)" 9 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/product?stype=internal: AGI starting at Mon Jan 14 09:03:52 2013 (1358154232) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-CALLID' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1358154232.13489" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-SCREEN' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-DIVERTED' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-DIVERSION' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:52] VERBOSE[9621] func_timeout.c: Channel will hangup at 2013-01-15 09:03:52.474 GMT. [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-CUTOFF' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:52] VERBOSE[9621] func_timeout.c: Channel will hangup at 2013-01-15 09:03:52.474 GMT. [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 (870281d7-89b2038f@192.168.1.33) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: 870281d7-89b2038f@192.168.1.33" 9 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-SCUSTOMER' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 (zz.zz.74.210:30259) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-PRESENTATION-INTERNAL' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-PRESENTATION-EXTERNAL' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-External) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-TRANSFER-PHONE' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-CUSTOMER [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-TRANSFER-CUSTOMER' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Proxy-Authorization) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 (Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@hostname.example.com",algorithm=MD5,response="7dd62c1effb3d6517960cfd5253e0ab4") [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "10" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "10" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER01 "Alert-Info: Simple-1" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '123', old '', forward 1 for channel SIP/product-local-00001715" 5 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '123', old '', forward 1 for channel SIP/product-local-00001715 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-DIVERSION "123" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "Resolving type 'phonelogin', number '', old '', forward 2 for channel SIP/product-local-00001715" 5 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type 'phonelogin', number '', old '', forward 2 for channel SIP/product-local-00001715 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 14 09:03:52] DEBUG[9621] pbx.c: Result of 'product-QUEUE' is NULL [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 (870281d7-89b2038f@192.168.1.33) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 () [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1358154232.13489, phone:0646061 - phonelogin:." 9 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1358154232.13489, phone:0646061 - phonelogin:. [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:52] VERBOSE[9621] func_timeout.c: Channel will hangup at 2013-01-15 09:03:52.501 GMT. [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "15" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "phonelogin" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "0646061" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "15" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "86400" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Rx << EXEC Answer "" [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: -- AGI Script Executing Application: (Answer) Options: () [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: SIP answering channel: SIP/product-local-00001715 [Jan 14 09:03:52] DEBUG[9621] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 09:03:52] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:52] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:52] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:52] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: Setting framing from config on incoming call [Jan 14 09:03:52] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: ** Our capability: 0x190c (ulaw|alaw|g726|g729|g722) Video flag: True Text flag: True [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Audio is at 19260 [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding codec 0x1000 (g722) to SDP [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding codec 0x800 (g726) to SDP [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: Done building SDP. Settling with this capability: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:52] VERBOSE[9621] chan_sip.c: <--- Reliably Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-190879bb Record-Route: From: ;tag=69b5ad378179cfafo0 To: ;tag=as644ee207 Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 357 v=0 o=root 184288282 184288282 IN IP4 xx.xx.46.25 s=Asterisk PBX 1.8.11.1 c=IN IP4 xx.xx.46.25 t=0 0 m=audio 19260 RTP/AVP 9 0 8 2 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110759 [Jan 14 09:03:52] DEBUG[9621] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:52] DEBUG[9621] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc010758' [Jan 14 09:03:52] DEBUG[9621] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address zz.zz.74.210:30467 [Jan 14 09:03:52] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> ACK sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.2 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-ebdfcd0c From: ;tag=69b5ad378179cfafo0 To: ;tag=as644ee207 Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 102 ACK Max-Forwards: 69 Route: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@hostname.example.com",algorithm=MD5,response="7dd62c1effb3d6517960cfd5253e0ab4" Contact: User-Agent: Cisco/SPA502G-7.4.9c Content-Length: 0 X-product-RURI: sip:123@xx.xx.46.25:5070 X-product-Source: zz.zz.74.210:30259 <-------------> [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 0 [ 51]: ACK sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK73e.14a03d56.2 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-ebdfcd0c [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 4 [ 61]: From: ;tag=69b5ad378179cfafo0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 5 [ 47]: To: ;tag=as644ee207 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 6 [ 39]: Call-ID: 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 9 [ 55]: Route: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 10 [221]: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@hostname.example.com",algorithm=MD5,response="7dd62c1effb3d6517960cfd5253e0ab4" [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 11 [ 40]: Contact: [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 12 [ 32]: User-Agent: Cisco/SPA502G-7.4.9c [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 14 [ 42]: X-product-RURI: sip:123@xx.xx.46.25:5070 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Header 15 [ 36]: X-product-Source: zz.zz.74.210:30259 [Jan 14 09:03:52] VERBOSE[5183] chan_sip.c: --- (16 headers 0 lines) --- [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: = Looking for Call ID: 870281d7-89b2038f@192.168.1.33 (Checking From) --From tag 69b5ad378179cfafo0 --To-tag as644ee207 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110759 [Jan 14 09:03:52] DEBUG[5183] chan_sip.c: Stopping retransmission on '870281d7-89b2038f@192.168.1.33' of Response 102: Match Found [Jan 14 09:03:53] VERBOSE[9621] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/enter-phone-account-number-hash 1234567890*# [Jan 14 09:03:53] VERBOSE[9621] res_agi.c: -- Playing '/opt/product/current/sounds/en/enter-phone-account-number-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:03:53] DEBUG[9621] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Jan 14 09:03:53] DEBUG[9621] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Jan 14 09:03:53] DEBUG[9621] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:03:53] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:54] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> BYE sip:0000004@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9a61.5009d424.0 Via: SIP/2.0/UDP 10.0.0.213:5060;rport=59990;received=yy.yy.10.241;branch=z9hG4bK-dc0d8489 From: ;tag=c5f4ffd76b09728ai0 To: "A C" ;tag=as7ef11ca5 Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 101 BYE Max-Forwards: 69 Route: User-Agent: Cisco/SPA502G-7.5.3 Content-Length: 0 X-product-RURI: sip:0000004@xx.xx.46.25:5070 X-product-Source: yy.yy.10.241:59990 <-------------> [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 0 [ 55]: BYE sip:0000004@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9a61.5009d424.0 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 10.0.0.213:5060;rport=59990;received=yy.yy.10.241;branch=z9hG4bK-dc0d8489 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 4 [ 55]: From: ;tag=c5f4ffd76b09728ai0 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 5 [ 61]: To: "A C" ;tag=as7ef11ca5 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 6 [ 59]: Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 101 BYE [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 9 [ 47]: Route: [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 10 [ 31]: User-Agent: Cisco/SPA502G-7.5.3 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 12 [ 46]: X-product-RURI: sip:0000004@xx.xx.46.25:5070 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Header 13 [ 38]: X-product-Source: yy.yy.10.241:59990 [Jan 14 09:03:54] VERBOSE[5183] chan_sip.c: --- (14 headers 0 lines) --- [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: = Looking for Call ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 (Checking From) --From tag c5f4ffd76b09728ai0 --To-tag as7ef11ca5 [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Initializing initreq for method BYE - callid 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:54] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:54] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:54] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Setting SIP_ALREADYGONE on dialog 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 [Jan 14 09:03:54] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c80492a8' [Jan 14 09:03:54] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070' in 32000 ms (Method: BYE) [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Received bye, issuing owner hangup [Jan 14 09:03:54] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9a61.5009d424.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 10.0.0.213:5060;rport=59990;received=yy.yy.10.241;branch=z9hG4bK-dc0d8489 Record-Route: From: ;tag=c5f4ffd76b09728ai0 To: "A C" ;tag=as7ef11ca5 Call-ID: 73d4569b2b7b918136a3bb4e55316db9@xx.xx.46.25:5070 CSeq: 101 BYE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jan 14 09:03:54] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:54] DEBUG[9558] res_agi.c: SIP/xx.xx.46.25:5060-00001714 hungup [Jan 14 09:03:54] VERBOSE[9558] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:54] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:30467 [Jan 14 09:03:55] DTMF[9621] channel.c: DTMF begin '#' received on SIP/product-local-00001715 [Jan 14 09:03:55] DTMF[9621] channel.c: DTMF begin ignored '#' on SIP/product-local-00001715 [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:30467 [Jan 14 09:03:55] DTMF[9621] channel.c: DTMF end '#' received on SIP/product-local-00001715, duration 118 ms [Jan 14 09:03:55] DTMF[9621] channel.c: DTMF end passthrough '#' on SIP/product-local-00001715 [Jan 14 09:03:55] DEBUG[9621] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:03:55] DEBUG[9621] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:03:55] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=35 endpos=11840 [Jan 14 09:03:55] VERBOSE[9621] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/you-are-now-logged-out 1234567890*# [Jan 14 09:03:55] VERBOSE[9621] res_agi.c: -- Playing '/opt/product/current/sounds/en/you-are-now-logged-out' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:03:55] DEBUG[9621] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] DEBUG[9621] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:03:55] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> BYE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK83e.a3cffd23.0 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-2a83ab3d From: ;tag=69b5ad378179cfafo0 To: ;tag=as644ee207 Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 103 BYE Max-Forwards: 69 Route: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@xx.xx.46.25:5070",algorithm=MD5,response="56a3cb03f2c9eeb9063d57b0e2e70895" User-Agent: Cisco/SPA502G-7.4.9c Content-Length: 0 X-product-RURI: sip:123@xx.xx.46.25:5070 X-product-Source: zz.zz.74.210:30259 <-------------> [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 0 [ 51]: BYE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 2 [ 58]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK83e.a3cffd23.0 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-2a83ab3d [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 4 [ 61]: From: ;tag=69b5ad378179cfafo0 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 5 [ 47]: To: ;tag=as644ee207 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 6 [ 39]: Call-ID: 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 103 BYE [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 9 [ 55]: Route: [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 10 [220]: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1600001257922ae879969dcacfb353e11d39eb5599",uri="sip:123@xx.xx.46.25:5070",algorithm=MD5,response="56a3cb03f2c9eeb9063d57b0e2e70895" [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 11 [ 32]: User-Agent: Cisco/SPA502G-7.4.9c [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 13 [ 42]: X-product-RURI: sip:123@xx.xx.46.25:5070 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Header 14 [ 36]: X-product-Source: zz.zz.74.210:30259 [Jan 14 09:03:55] VERBOSE[5183] chan_sip.c: --- (15 headers 0 lines) --- [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: = Looking for Call ID: 870281d7-89b2038f@192.168.1.33 (Checking From) --From tag 69b5ad378179cfafo0 --To-tag as644ee207 [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Initializing initreq for method BYE - callid 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:55] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:55] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:55] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Setting SIP_ALREADYGONE on dialog 870281d7-89b2038f@192.168.1.33 [Jan 14 09:03:55] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc010758' [Jan 14 09:03:55] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '870281d7-89b2038f@192.168.1.33' in 32000 ms (Method: BYE) [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Received bye, issuing owner hangup [Jan 14 09:03:55] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK83e.a3cffd23.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-2a83ab3d Record-Route: From: ;tag=69b5ad378179cfafo0 To: ;tag=as644ee207 Call-ID: 870281d7-89b2038f@192.168.1.33 CSeq: 103 BYE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jan 14 09:03:55] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:55] DEBUG[9621] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:03:55] DEBUG[9621] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:03:55] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=-1 endpos=5280 [Jan 14 09:03:55] DEBUG[9621] res_agi.c: SIP/product-local-00001715 hungup [Jan 14 09:03:55] VERBOSE[9621] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> CANCEL sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 From: "A C" ;tag=55ccf804248dc50do0 Call-ID: 472ee090-fe2c15f1@10.0.0.214 To: "P M" CSeq: 102 CANCEL Max-Forwards: 70 User-Agent: product SIP proxy Content-Length: 0 <-------------> [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 0 [ 58]: CANCEL sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 2 [ 77]: From: "A C" ;tag=55ccf804248dc50do0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 3 [ 37]: Call-ID: 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 4 [ 51]: To: "P M" [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 5 [ 16]: CSeq: 102 CANCEL [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 7 [ 30]: User-Agent: product SIP proxy [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: = Looking for Call ID: 472ee090-fe2c15f1@10.0.0.214 (Checking From) --From tag 55ccf804248dc50do0 --To-tag [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Jan 14 09:03:56] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:56] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Setting SIP_ALREADYGONE on dialog 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:56] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c40415f8' [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: <--- Reliably Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-853f7459 From: "A C" ;tag=55ccf804248dc50do0 To: "P M" ;tag=as7d887481 Call-ID: 472ee090-fe2c15f1@10.0.0.214 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110763 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0;received=xx.xx.46.25;rport=5060 From: "A C" ;tag=55ccf804248dc50do0 To: "P M" ;tag=as7d887481 Call-ID: 472ee090-fe2c15f1@10.0.0.214 CSeq: 102 CANCEL Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> ACK sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 From: "A C" ;tag=55ccf804248dc50do0 Call-ID: 472ee090-fe2c15f1@10.0.0.214 To: "P M" ;tag=as7d887481 CSeq: 102 ACK Max-Forwards: 70 User-Agent: product SIP proxy Content-Length: 0 <-------------> [Jan 14 09:03:56] DEBUG[9536] channel.c: Hanging up channel 'Local/0000003@product-phone-456a;1' [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 0 [ 55]: ACK sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bKa8f5.0a1c59a1.0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 2 [ 77]: From: "A C" ;tag=55ccf804248dc50do0 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 3 [ 37]: Call-ID: 472ee090-fe2c15f1@10.0.0.214 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 4 [ 66]: To: "P M" ;tag=as7d887481 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 7 [ 30]: User-Agent: product SIP proxy [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jan 14 09:03:56] DEBUG[9536] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Jan 14 09:03:56] VERBOSE[5183] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 09:03:56] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=-1 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: = Looking for Call ID: 472ee090-fe2c15f1@10.0.0.214 (Checking From) --From tag 55ccf804248dc50do0 --To-tag as7d887481 [Jan 14 09:03:56] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 09:03:56] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 1 (Not in use) [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 09:03:56] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '1' [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110763 [Jan 14 09:03:56] DEBUG[5183] chan_sip.c: Stopping retransmission on '472ee090-fe2c15f1@10.0.0.214' of Response 102: Match Found [Jan 14 09:03:56] DEBUG[9536] res_agi.c: SIP/product-local-00001713 hungup [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:56] DEBUG[5189] app_queue.c: Device 'Local/0000003@product-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-PHONE "" [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jan 14 09:03:56] DEBUG[9536] pbx.c: Result of 'DIALSTATUS' is 'CANCEL' [Jan 14 09:03:56] VERBOSE[9536] res_agi.c: AGI Tx >> 200 result=1 (CANCEL) [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 4 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:56] ERROR[9621] utils.c: write() returned error: Broken pipe [Jan 14 09:03:56] DEBUG[9621] pbx.c: Spawn extension (from-internal,123,1) exited non-zero on 'SIP/product-local-00001715' [Jan 14 09:03:56] VERBOSE[9621] pbx.c: == Spawn extension (from-internal, 123, 1) exited non-zero on 'SIP/product-local-00001715' [Jan 14 09:03:56] DEBUG[9621] channel.c: Soft-Hanging up channel 'SIP/product-local-00001715' [Jan 14 09:03:56] DEBUG[9621] pbx.c: Launching 'AGI' [Jan 14 09:03:56] VERBOSE[9621] pbx.c: -- Executing [h@from-internal:1] AGI("SIP/product-local-00001715", "agi://127.0.0.1/end") in new stack [Jan 14 09:03:56] DEBUG[9621] res_agi.c: Hungup channel detected, running agi in dead mode. [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_network_script: end [Jan 14 09:03:56] DEBUG[9621] res_agi.c: Wow, connected! [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/end [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-00001715 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_uniqueid: 1358154232.13489 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callerid: 0646061 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_dnid: 123 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_extension: h [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> agi_threadid: 47780441097984 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:03:56 2013 (1358154236)" 9 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: > agi://127.0.0.1/end: AGI starting at Mon Jan 14 09:03:56 2013 (1358154236) [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:03:56] DEBUG[9621] pbx.c: Result of 'product-CALLID' is '1358154232.13489' [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=1 (1358154232.13489) [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE ANSWEREDTIME [Jan 14 09:03:56] DEBUG[9621] pbx.c: Result of 'ANSWEREDTIME' is NULL [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jan 14 09:03:56] DEBUG[9621] pbx.c: Result of 'DIALSTATUS' is NULL [Jan 14 09:03:56] VERBOSE[9621] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9621] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 14 09:03:57] VERBOSE[9621] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:03:57] DEBUG[9621] channel.c: Hanging up channel 'SIP/product-local-00001715' [Jan 14 09:03:57] DEBUG[9621] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 09:03:57] DEBUG[9621] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc010758' [Jan 14 09:03:57] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:57] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:57] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:57] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:57] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:57] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> INVITE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.0 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-5eaa0a5d From: ;tag=5aeed506b57ab425o0 To: Call-ID: c5d97b5a-b06e21e1@192.168.1.33 CSeq: 102 INVITE Max-Forwards: 69 Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1b000012584931088368cee89c9bbaa835309be21d",uri="sip:123@hostname.example.com",algorithm=MD5,response="4d0d81acdf99f5da991a04da9bcfab3f" Contact: Expires: 240 User-Agent: Cisco/SPA502G-7.4.9c Content-Length: 447 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp X-product-RURI: sip:123@hostname.example.com X-product-Source: zz.zz.74.210:30259 v=0 o=- 345555700 345555700 IN IP4 192.168.1.33 s=- c=IN IP4 zz.zz.74.210 t=0 0 m=audio 16480 RTP/AVP 9 0 2 8 18 96 97 98 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv a=direction:active a=oldmediaip:192.168.1.33 <-------------> [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 0 [ 54]: INVITE sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-5eaa0a5d [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 4 [ 61]: From: ;tag=5aeed506b57ab425o0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 5 [ 32]: To: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 6 [ 39]: Call-ID: c5d97b5a-b06e21e1@192.168.1.33 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 9 [221]: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1b000012584931088368cee89c9bbaa835309be21d",uri="sip:123@hostname.example.com",algorithm=MD5,response="4d0d81acdf99f5da991a04da9bcfab3f" [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 10 [ 40]: Contact: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 11 [ 12]: Expires: 240 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 12 [ 32]: User-Agent: Cisco/SPA502G-7.4.9c [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 13 [ 19]: Content-Length: 447 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 14 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 15 [ 19]: Supported: replaces [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 16 [ 29]: Content-Type: application/sdp [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 17 [ 43]: X-product-RURI: sip:123@hostname.example.com [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 18 [ 36]: X-product-Source: zz.zz.74.210:30259 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 19 [ 0]: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 1 [ 43]: o=- 345555700 345555700 IN IP4 192.168.1.33 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 3 [ 20]: c=IN IP4 zz.zz.74.210 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 5 [ 45]: m=audio 16480 RTP/AVP 9 0 2 8 18 96 97 98 101 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 17 [ 10]: a=sendrecv [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 18 [ 18]: a=direction:active [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Body 19 [ 25]: a=oldmediaip:192.168.1.33 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: --- (19 headers 20 lines) --- [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: = Looking for Call ID: c5d97b5a-b06e21e1@192.168.1.33 (Checking From) --From tag 5aeed506b57ab425o0 --To-tag [Jan 14 09:03:57] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for c5d97b5a-b06e21e1@192.168.1.33 - INVITE (No RTP) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 09:03:57] DEBUG[5183] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 14 09:03:57] DEBUG[5183] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 14 09:03:57] DEBUG[5183] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 14 09:03:57] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:03:57] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Initializing initreq for method INVITE - callid c5d97b5a-b06e21e1@192.168.1.33 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Using INVITE request as basis request - c5d97b5a-b06e21e1@192.168.1.33 [Jan 14 09:03:57] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:57] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:57] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:57] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0646061' AND host = 'dynamic' [Jan 14 09:03:57] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 09:03:57] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0646061' [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found peer 'product-local' for '0646061' from xx.xx.46.25:5060 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] DEBUG[5183] res_rtp_asterisk.c: Allocated port 17138 for RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: RTP instance '0x2b74a055a9d8' is setup and ready to go [Jan 14 09:03:57] DEBUG[5183] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] VERBOSE[5183] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Setting NAT on RTP to On [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 345555700 345555700 IN IP4 192.168.1.33... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] netsock2.c: Splitting 'zz.zz.74.210' into... [Jan 14 09:03:57] DEBUG[5183] netsock2.c: ...host 'zz.zz.74.210' and port ''. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 zz.zz.74.210... OK. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 0 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 2 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 8 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 8 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 18 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 18 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 96 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 97 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 97 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 98 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 98 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format G726-32 for ID 2 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format G729a for ID 18 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Unsetting payload 96 on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-40 for ID 96 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Unsetting payload 97 on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-24 for ID 97 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Unsetting payload 98 on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-16 for ID 98 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:192.168.1.33... UNSUPPORTED. [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 0 on 0x2b74bb598290 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 2 on 0x2b74bb598290 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 8 on 0x2b74bb598290 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598290 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 18 on 0x2b74bb598290 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598290 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Capabilities: us - 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722), peer - audio=0x190c (ulaw|alaw|g726|g729|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 09:03:57] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port zz.zz.74.210:16480 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 0 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 2 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 8 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 18 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598290 to 0x2b74a055aba0 [Jan 14 09:03:57] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Checking SIP call limits for device [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Updating call counter for incoming call [Jan 14 09:03:57] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:57] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:57] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 09:03:57] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: Looking for 123 in from-internal (domain xx.xx.46.25) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: *** Joint capabilities are 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: This channel will not be able to handle video. [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: SIP/product-local-00001716: New call is still down.... Trying... [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-5eaa0a5d Record-Route: From: ;tag=5aeed506b57ab425o0 To: Call-ID: c5d97b5a-b06e21e1@192.168.1.33 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:57] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:57] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:57] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:57] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:57] DEBUG[9666] pbx.c: Launching 'AGI' [Jan 14 09:03:57] VERBOSE[9666] pbx.c: -- Executing [123@from-internal:1] AGI("SIP/product-local-00001716", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 14 09:03:57] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_network_script: product?stype=internal [Jan 14 09:03:57] DEBUG[9666] res_agi.c: Wow, connected! [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-00001716 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_uniqueid: 1358154237.13490 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callerid: 0646061 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_dnid: 123 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_extension: 123 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> agi_threadid: 47780441097984 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:03:57 2013 (1358154237)" 9 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/product?stype=internal: AGI starting at Mon Jan 14 09:03:57 2013 (1358154237) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-CALLID' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1358154237.13490" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-SCREEN' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-DIVERTED' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-DIVERSION' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:57] VERBOSE[9666] func_timeout.c: Channel will hangup at 2013-01-15 09:03:57.531 GMT. [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-CUTOFF' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:57] VERBOSE[9666] func_timeout.c: Channel will hangup at 2013-01-15 09:03:57.532 GMT. [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 (c5d97b5a-b06e21e1@192.168.1.33) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: c5d97b5a-b06e21e1@192.168.1.33" 9 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: c5d97b5a-b06e21e1@192.168.1.33 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-SCUSTOMER' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 (zz.zz.74.210:30259) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-PRESENTATION-INTERNAL' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-PRESENTATION-EXTERNAL' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-External) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-TRANSFER-PHONE' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-CUSTOMER [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-TRANSFER-CUSTOMER' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Proxy-Authorization) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 (Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1b000012584931088368cee89c9bbaa835309be21d",uri="sip:123@hostname.example.com",algorithm=MD5,response="4d0d81acdf99f5da991a04da9bcfab3f") [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "10" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "10" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER01 "Alert-Info: Simple-1" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '123', old '', forward 1 for channel SIP/product-local-00001716" 5 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '123', old '', forward 1 for channel SIP/product-local-00001716 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-DIVERSION "123" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "Resolving type 'phonelogin', number '', old '', forward 2 for channel SIP/product-local-00001716" 5 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type 'phonelogin', number '', old '', forward 2 for channel SIP/product-local-00001716 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 14 09:03:57] DEBUG[9666] pbx.c: Result of 'product-QUEUE' is NULL [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 (c5d97b5a-b06e21e1@192.168.1.33) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 () [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1358154237.13490, phone:0646061 - phonelogin:." 9 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1358154237.13490, phone:0646061 - phonelogin:. [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 09:03:57] VERBOSE[9666] func_timeout.c: Channel will hangup at 2013-01-15 09:03:57.547 GMT. [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "15" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "phonelogin" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "0646061" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "15" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "86400" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Rx << EXEC Answer "" [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: -- AGI Script Executing Application: (Answer) Options: () [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: SIP answering channel: SIP/product-local-00001716 [Jan 14 09:03:57] DEBUG[9666] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 09:03:57] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 09:03:57] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 09:03:57] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 09:03:57] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: Setting framing from config on incoming call [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: ** Our capability: 0x190c (ulaw|alaw|g726|g729|g722) Video flag: True Text flag: True [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Audio is at 17138 [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding codec 0x1000 (g722) to SDP [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding codec 0x800 (g726) to SDP [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: Done building SDP. Settling with this capability: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 09:03:57] DEBUG[5189] app_queue.c: 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. [Jan 14 09:03:57] VERBOSE[9666] chan_sip.c: <--- Reliably Transmitting (NAT) to xx.xx.46.25:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.0;received=xx.xx.46.25;rport=5060 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-5eaa0a5d Record-Route: From: ;tag=5aeed506b57ab425o0 To: ;tag=as61778f90 Call-ID: c5d97b5a-b06e21e1@192.168.1.33 CSeq: 102 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 359 v=0 o=root 1256416588 1256416588 IN IP4 xx.xx.46.25 s=Asterisk PBX 1.8.11.1 c=IN IP4 xx.xx.46.25 t=0 0 m=audio 17138 RTP/AVP 9 0 8 2 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110765 [Jan 14 09:03:57] DEBUG[9666] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 09:03:57] DEBUG[9666] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74a055a9d8' [Jan 14 09:03:57] DEBUG[9666] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address zz.zz.74.210:4309 [Jan 14 09:03:57] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> ACK sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.2 Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-d2c1a6cb From: ;tag=5aeed506b57ab425o0 To: ;tag=as61778f90 Call-ID: c5d97b5a-b06e21e1@192.168.1.33 CSeq: 102 ACK Max-Forwards: 69 Route: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1b000012584931088368cee89c9bbaa835309be21d",uri="sip:123@hostname.example.com",algorithm=MD5,response="4d0d81acdf99f5da991a04da9bcfab3f" Contact: User-Agent: Cisco/SPA502G-7.4.9c Content-Length: 0 X-product-RURI: sip:123@xx.xx.46.25:5070 X-product-Source: zz.zz.74.210:30259 <-------------> [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 0 [ 51]: ACK sip:123@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK9ff5.ea853731.2 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 3 [ 91]: Via: SIP/2.0/UDP 192.168.1.33:5060;rport=30259;received=zz.zz.74.210;branch=z9hG4bK-d2c1a6cb [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 4 [ 61]: From: ;tag=5aeed506b57ab425o0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 5 [ 47]: To: ;tag=as61778f90 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 6 [ 39]: Call-ID: c5d97b5a-b06e21e1@192.168.1.33 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 9 [ 55]: Route: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 10 [221]: Proxy-Authorization: Digest username="0646061",realm="hostname.example.com",nonce="50f3ca1b000012584931088368cee89c9bbaa835309be21d",uri="sip:123@hostname.example.com",algorithm=MD5,response="4d0d81acdf99f5da991a04da9bcfab3f" [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 11 [ 40]: Contact: [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 12 [ 32]: User-Agent: Cisco/SPA502G-7.4.9c [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 14 [ 42]: X-product-RURI: sip:123@xx.xx.46.25:5070 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Header 15 [ 36]: X-product-Source: zz.zz.74.210:30259 [Jan 14 09:03:57] VERBOSE[5183] chan_sip.c: --- (16 headers 0 lines) --- [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: = Looking for Call ID: c5d97b5a-b06e21e1@192.168.1.33 (Checking From) --From tag 5aeed506b57ab425o0 --To-tag as61778f90 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110765 [Jan 14 09:03:57] DEBUG[5183] chan_sip.c: Stopping retransmission on 'c5d97b5a-b06e21e1@192.168.1.33' of Response 102: Match Found [Jan 14 09:03:58] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/enter-phone-account-number-hash 1234567890*# [Jan 14 09:03:58] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/enter-phone-account-number-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:03:58] DEBUG[9666] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Jan 14 09:03:58] DEBUG[9666] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Jan 14 09:03:58] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:03:58] VERBOSE[9260] asterisk.c: -- Remote UNIX connection disconnected [Jan 14 09:03:59] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:03:59] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:34316 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:40113;branch=z9hG4bK.79644730;rport;alias From: sip:sipsak@xx.xx.46.25:40113;tag=42051686 To: sip:xx.xx.46.25:5070 Call-ID: 1107629702@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:40113 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:40113;branch=z9hG4bK.79644730;rport;alias [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:40113;tag=42051686 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1107629702@xx.xx.46.25 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:40113 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 09:03:59] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1107629702@xx.xx.46.25 (Checking From) --From tag 42051686 --To-tag [Jan 14 09:03:59] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1107629702@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 09:03:59] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:03:59] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:59] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:40113' into... [Jan 14 09:03:59] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:03:59] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 09:03:59] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:34316 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:40113;branch=z9hG4bK.79644730;alias;received=xx.xx.46.25;rport=34316 From: sip:sipsak@xx.xx.46.25:40113;tag=42051686 To: sip:xx.xx.46.25:5070;tag=as3da4a721 Call-ID: 1107629702@xx.xx.46.25 CSeq: 1 OPTIONS Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Jan 14 09:03:59] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:34316 [Jan 14 09:03:59] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1107629702@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:03:59] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:03:59] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:03:59] DTMF[9666] channel.c: DTMF begin '1' received on SIP/product-local-00001716 [Jan 14 09:03:59] DTMF[9666] channel.c: DTMF begin ignored '1' on SIP/product-local-00001716 [Jan 14 09:03:59] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end '1' received on SIP/product-local-00001716, duration 78 ms [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end passthrough '1' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=49 endpos=9920 [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 50 (2), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin '2' received on SIP/product-local-00001716 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin ignored '2' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 50 (2), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end '2' received on SIP/product-local-00001716, duration 68 ms [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end passthrough '2' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=50 endpos=1600 [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 51 (3), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin '3' received on SIP/product-local-00001716 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin ignored '3' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 51 (3), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end '3' received on SIP/product-local-00001716, duration 60 ms [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end passthrough '3' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=51 endpos=1280 [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 52 (4), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin '4' received on SIP/product-local-00001716 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin ignored '4' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 52 (4), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end '4' received on SIP/product-local-00001716, duration 70 ms [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end passthrough '4' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=52 endpos=1760 [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 57 (9), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin '9' received on SIP/product-local-00001716 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin ignored '9' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 57 (9), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end '9' received on SIP/product-local-00001716, duration 70 ms [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF end passthrough '9' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=57 endpos=1760 [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:00] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:00] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000009 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 53 (5), at zz.zz.74.210:4309 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin '5' received on SIP/product-local-00001716 [Jan 14 09:04:00] DTMF[9666] channel.c: DTMF begin ignored '5' on SIP/product-local-00001716 [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:00] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 53 (5), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end '5' received on SIP/product-local-00001716, duration 58 ms [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end passthrough '5' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=53 endpos=1440 [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 55 (7), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin '7' received on SIP/product-local-00001716 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin ignored '7' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 55 (7), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end '7' received on SIP/product-local-00001716, duration 58 ms [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end passthrough '7' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=55 endpos=1440 [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000007 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin '#' received on SIP/product-local-00001716 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin ignored '#' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end '#' received on SIP/product-local-00001716, duration 68 ms [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF end passthrough '#' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=35 endpos=1600 [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/enter-pin-hash 1234567890*# [Jan 14 09:04:01] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/enter-pin-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:01] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:01] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1251508559@xx.xx.46.25' [Jan 14 09:04:01] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1251508559@xx.xx.46.25 [Jan 14 09:04:01] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1251508559@xx.xx.46.25' Method: OPTIONS [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 48 (0), at zz.zz.74.210:4309 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin '0' received on SIP/product-local-00001716 [Jan 14 09:04:01] DTMF[9666] channel.c: DTMF begin ignored '0' on SIP/product-local-00001716 [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:01] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 48 (0), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end '0' received on SIP/product-local-00001716, duration 90 ms [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end passthrough '0' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=48 endpos=5280 [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin '1' received on SIP/product-local-00001716 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin ignored '1' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end '1' received on SIP/product-local-00001716, duration 58 ms [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end passthrough '1' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=49 endpos=1920 [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9115] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin '1' received on SIP/product-local-00001716 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin ignored '1' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 49 (1), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end '1' received on SIP/product-local-00001716, duration 90 ms [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end passthrough '1' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=49 endpos=1280 [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 52 (4), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin '4' received on SIP/product-local-00001716 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin ignored '4' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 52 (4), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end '4' received on SIP/product-local-00001716, duration 68 ms [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF end passthrough '4' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=52 endpos=2080 [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/silence/1 1234567890*# [Jan 14 09:04:02] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/silence/1' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:02] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 00000004 (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:4309 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin '#' received on SIP/product-local-00001716 [Jan 14 09:04:02] DTMF[9666] channel.c: DTMF begin ignored '#' on SIP/product-local-00001716 [Jan 14 09:04:02] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:03] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:03] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:03] DEBUG[9666] res_rtp_asterisk.c: Sending dtmf: 35 (#), at zz.zz.74.210:4309 [Jan 14 09:04:03] DTMF[9666] channel.c: DTMF end '#' received on SIP/product-local-00001716, duration 60 ms [Jan 14 09:04:03] DTMF[9666] channel.c: DTMF end passthrough '#' on SIP/product-local-00001716 [Jan 14 09:04:03] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:03] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:03] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=35 endpos=2720 [Jan 14 09:04:03] VERBOSE[9666] res_agi.c: AGI Rx << STREAM FILE /opt/product/current/sounds/en/you-are-now-logged-in 1234567890*# [Jan 14 09:04:03] VERBOSE[9666] res_agi.c: -- Playing '/opt/product/current/sounds/en/you-are-now-logged-in' (escape_digits=1234567890*#) (sample_offset 0) [Jan 14 09:04:03] DEBUG[9666] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 14 09:04:03] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:03] DEBUG[9666] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [Jan 14 09:04:04] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:04:04] DEBUG[9666] channel.c: Scheduling timer at (727 requested / 727 actual) timer ticks per second [Jan 14 09:04:04] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:04] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:04] DEBUG[9666] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 14 09:04:04] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 endpos=14251 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:04:05] VERBOSE[9666] pbx.c: -- Auto fallthrough, channel 'SIP/product-local-00001716' status is 'UNKNOWN' [Jan 14 09:04:05] DEBUG[9666] channel.c: Soft-Hanging up channel 'SIP/product-local-00001716' [Jan 14 09:04:05] DEBUG[9666] pbx.c: Launching 'AGI' [Jan 14 09:04:05] VERBOSE[9666] pbx.c: -- Executing [h@from-internal:1] AGI("SIP/product-local-00001716", "agi://127.0.0.1/end") in new stack [Jan 14 09:04:05] DEBUG[9666] res_agi.c: Hungup channel detected, running agi in dead mode. [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_network_script: end [Jan 14 09:04:05] DEBUG[9666] res_agi.c: Wow, connected! [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/end [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-00001716 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_language: en [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_uniqueid: 1358154237.13490 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callerid: 0646061 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_dnid: 123 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_extension: h [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> agi_threadid: 47780441097984 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 09:04:05 2013 (1358154245)" 9 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: > agi://127.0.0.1/end: AGI starting at Mon Jan 14 09:04:05 2013 (1358154245) [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 09:04:05] DEBUG[9666] pbx.c: Result of 'product-CALLID' is '1358154237.13490' [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=1 (1358154237.13490) [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE ANSWEREDTIME [Jan 14 09:04:05] DEBUG[9666] pbx.c: Result of 'ANSWEREDTIME' is NULL [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jan 14 09:04:05] DEBUG[9666] pbx.c: Result of 'DIALSTATUS' is NULL [Jan 14 09:04:05] VERBOSE[9666] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 09:04:06] VERBOSE[9666] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 14 09:04:06] VERBOSE[9666] res_agi.c: AGI Tx >> HANGUP [Jan 14 09:04:06] DEBUG[9666] channel.c: Hanging up channel 'SIP/product-local-00001716' [Jan 14 09:04:06] DEBUG[9666] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 09:04:06] DEBUG[9666] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74a055a9d8' [Jan 14 09:04:06] VERBOSE[9666] chan_sip.c: Scheduling destruction of SIP dialog 'c5d97b5a-b06e21e1@192.168.1.33' in 32000 ms (Method: ACK) [Jan 14 09:04:06] VERBOSE[9666] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 09:04:06] DEBUG[9666] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 09:04:06] DEBUG[9666] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:04:06] VERBOSE[9666] chan_sip.c: set_destination: set destination to xx.xx.46.25:5060 [Jan 14 09:04:06] VERBOSE[9666] chan_sip.c: Reliably Transmitting (NAT) to xx.xx.46.25:5060: