[Jan 14 08:59:06] VERBOSE[7184] config.c: == Parsing '/etc/asterisk/logger.conf': [Jan 14 08:59:06] DEBUG[7184] config.c: Parsing /etc/asterisk/logger.conf [Jan 14 08:59:06] VERBOSE[7184] config.c: == Found [Jan 14 08:59:06] VERBOSE[7184] logger.c: Asterisk Queue Logger restarted [Jan 14 08:59:06] VERBOSE[7015] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 14 08:59:06] VERBOSE[7015] res_agi.c: AGI Tx >> HANGUP [Jan 14 08:59:06] DEBUG[7015] channel.c: Hanging up channel 'SIP/product-local-0000170b' [Jan 14 08:59:06] DEBUG[7015] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 08:59:06] DEBUG[7015] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74a05cb148' [Jan 14 08:59:06] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 08:59:06] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 08:59:06] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 08:59:06] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 08:59:06] 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 08:59:07] VERBOSE[7184] asterisk.c: -- Remote UNIX connection disconnected [Jan 14 08:59:09] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:09] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:49146 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:44128;branch=z9hG4bK.7a797f33;rport;alias From: sip:sipsak@xx.xx.46.25:44128;tag=739fdd86 To: sip:xx.xx.46.25:5070 Call-ID: 1939856774@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:44128 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:44128;branch=z9hG4bK.7a797f33;rport;alias [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:44128;tag=739fdd86 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1939856774@xx.xx.46.25 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:44128 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:09] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1939856774@xx.xx.46.25 (Checking From) --From tag 739fdd86 --To-tag [Jan 14 08:59:09] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1939856774@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:09] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:09] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:09] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:09] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:44128' into... [Jan 14 08:59:09] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:09] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:09] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:49146 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:44128;branch=z9hG4bK.7a797f33;alias;received=xx.xx.46.25;rport=49146 From: sip:sipsak@xx.xx.46.25:44128;tag=739fdd86 To: sip:xx.xx.46.25:5070;tag=as69834d31 Call-ID: 1939856774@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 08:59:09] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:49146 [Jan 14 08:59:09] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1939856774@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 08:59:11] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '576556143@xx.xx.46.25' [Jan 14 08:59:11] DEBUG[5183] chan_sip.c: Destroying SIP dialog 576556143@xx.xx.46.25 [Jan 14 08:59:11] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '576556143@xx.xx.46.25' Method: OPTIONS [Jan 14 08:59:14] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:15] VERBOSE[5159] asterisk.c: -- Remote UNIX connection [Jan 14 08:59:19] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:19] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:44306 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:47994;branch=z9hG4bK.3a2dda3c;rport;alias From: sip:sipsak@xx.xx.46.25:47994;tag=155e9d57 To: sip:xx.xx.46.25:5070 Call-ID: 358522199@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:47994 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:47994;branch=z9hG4bK.3a2dda3c;rport;alias [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:47994;tag=155e9d57 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 4 [ 31]: Call-ID: 358522199@xx.xx.46.25 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:47994 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:19] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: = Looking for Call ID: 358522199@xx.xx.46.25 (Checking From) --From tag 155e9d57 --To-tag [Jan 14 08:59:19] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 358522199@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:19] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:19] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:19] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:19] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:47994' into... [Jan 14 08:59:19] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:19] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:19] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:44306 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:47994;branch=z9hG4bK.3a2dda3c;alias;received=xx.xx.46.25;rport=44306 From: sip:sipsak@xx.xx.46.25:47994;tag=155e9d57 To: sip:xx.xx.46.25:5070;tag=as5c2c31a5 Call-ID: 358522199@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 08:59:19] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:44306 [Jan 14 08:59:19] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '358522199@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 08:59:21] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '544225755@xx.xx.46.25' [Jan 14 08:59:21] DEBUG[5183] chan_sip.c: Destroying SIP dialog 544225755@xx.xx.46.25 [Jan 14 08:59:21] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '544225755@xx.xx.46.25' Method: OPTIONS [Jan 14 08:59:24] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:29] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:29] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:43155 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:41523;branch=z9hG4bK.5d6e7cd9;rport;alias From: sip:sipsak@xx.xx.46.25:41523;tag=693abf43 To: sip:xx.xx.46.25:5070 Call-ID: 1765457731@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:41523 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:41523;branch=z9hG4bK.5d6e7cd9;rport;alias [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:41523;tag=693abf43 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1765457731@xx.xx.46.25 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:41523 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:29] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1765457731@xx.xx.46.25 (Checking From) --From tag 693abf43 --To-tag [Jan 14 08:59:29] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1765457731@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:29] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:29] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:29] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:29] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:41523' into... [Jan 14 08:59:29] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:29] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:29] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:43155 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:41523;branch=z9hG4bK.5d6e7cd9;alias;received=xx.xx.46.25;rport=43155 From: sip:sipsak@xx.xx.46.25:41523;tag=693abf43 To: sip:xx.xx.46.25:5070;tag=as78fbee33 Call-ID: 1765457731@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 08:59:29] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:43155 [Jan 14 08:59:29] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1765457731@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 08:59:31] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1186882450@xx.xx.46.25' [Jan 14 08:59:31] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1186882450@xx.xx.46.25 [Jan 14 08:59:31] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1186882450@xx.xx.46.25' Method: OPTIONS [Jan 14 08:59:34] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:37] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '5659e733-a6a4ec87@192.168.0.82' [Jan 14 08:59:37] DEBUG[5183] chan_sip.c: Destroying SIP dialog 5659e733-a6a4ec87@192.168.0.82 [Jan 14 08:59:37] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '5659e733-a6a4ec87@192.168.0.82' Method: BYE [Jan 14 08:59:37] DEBUG[5183] rtp_engine.c: Destroyed RTP instance '0x2b74a05cb148' [Jan 14 08:59:39] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:39] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:43058 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:41203;branch=z9hG4bK.62b3faa2;rport;alias From: sip:sipsak@xx.xx.46.25:41203;tag=3f9a3cab To: sip:xx.xx.46.25:5070 Call-ID: 1067072683@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:41203 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:41203;branch=z9hG4bK.62b3faa2;rport;alias [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:41203;tag=3f9a3cab [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1067072683@xx.xx.46.25 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:41203 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:39] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1067072683@xx.xx.46.25 (Checking From) --From tag 3f9a3cab --To-tag [Jan 14 08:59:39] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1067072683@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:39] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:39] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:39] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:39] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:41203' into... [Jan 14 08:59:39] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:39] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:39] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:43058 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:41203;branch=z9hG4bK.62b3faa2;alias;received=xx.xx.46.25;rport=43058 From: sip:sipsak@xx.xx.46.25:41203;tag=3f9a3cab To: sip:xx.xx.46.25:5070;tag=as1dcc2c9c Call-ID: 1067072683@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 08:59:39] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:43058 [Jan 14 08:59:39] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1067072683@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 08:59:41] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1939856774@xx.xx.46.25' [Jan 14 08:59:41] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1939856774@xx.xx.46.25 [Jan 14 08:59:41] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1939856774@xx.xx.46.25' Method: OPTIONS [Jan 14 08:59:44] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:45] 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=z9hG4bK2ddb.79083ed1.0 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-71d0dcce From: "A C" ;tag=4a07e34d8c164eo0 To: "P M" Call-ID: 69ee90ac-1b46636@10.0.0.214 CSeq: 102 INVITE Max-Forwards: 69 Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3c91f000011e93c7f11b4f3e9ea9b7218fb15f96f905f",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="5cc7d7f919e6b3cfddbd73c373c3e496" 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=- 42101875 42101875 IN IP4 10.0.0.214 s=- c=IN IP4 yy.yy.10.241 t=0 0 m=audio 16426 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 08:59:45] DEBUG[5183] chan_sip.c: Header 0 [ 58]: INVITE sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 1 [ 60]: Record-Route: [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK2ddb.79083ed1.0 [Jan 14 08:59:45] 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-71d0dcce [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 4 [ 75]: From: "A C" ;tag=4a07e34d8c164eo0 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 5 [ 51]: To: "P M" [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 6 [ 36]: Call-ID: 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 9 [225]: Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3c91f000011e93c7f11b4f3e9ea9b7218fb15f96f905f",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="5cc7d7f919e6b3cfddbd73c373c3e496" [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 10 [ 58]: Contact: "A C" [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 11 [ 12]: Expires: 240 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 12 [ 31]: User-Agent: Cisco/SPA502G-7.5.4 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 13 [ 19]: Content-Length: 443 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 14 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 15 [ 19]: Supported: replaces [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 16 [ 29]: Content-Type: application/sdp [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 17 [ 47]: X-product-RURI: sip:0000003@hostname.example.com [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 18 [ 38]: X-product-Source: yy.yy.10.241:19050 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Header 19 [ 0]: [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 1 [ 39]: o=- 42101875 42101875 IN IP4 10.0.0.214 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 3 [ 22]: c=IN IP4 yy.yy.10.241 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 5 [ 45]: m=audio 16426 RTP/AVP 9 0 2 8 18 96 97 98 101 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 17 [ 10]: a=sendrecv [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 18 [ 18]: a=direction:active [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Body 19 [ 23]: a=oldmediaip:10.0.0.214 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: --- (19 headers 20 lines) --- [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: = Looking for Call ID: 69ee90ac-1b46636@10.0.0.214 (Checking From) --From tag 4a07e34d8c164eo0 --To-tag [Jan 14 08:59:45] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 69ee90ac-1b46636@10.0.0.214 - INVITE (No RTP) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 14 08:59:45] DEBUG[5183] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 14 08:59:45] DEBUG[5183] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 14 08:59:45] DEBUG[5183] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 14 08:59:45] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 08:59:45] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Initializing initreq for method INVITE - callid 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Using INVITE request as basis request - 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:45] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 08:59:45] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 08:59:45] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:45] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0000004' AND host = 'dynamic' [Jan 14 08:59:45] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:45] DEBUG[5183] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '0000004' [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found peer 'product-local' for '0000004' from xx.xx.46.25:5060 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74bc016838' [Jan 14 08:59:45] DEBUG[5183] res_rtp_asterisk.c: Allocated port 10552 for RTP instance '0x2b74bc016838' [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: RTP instance '0x2b74bc016838' is setup and ready to go [Jan 14 08:59:45] DEBUG[5183] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74bc016838' [Jan 14 08:59:45] VERBOSE[5183] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Setting NAT on RTP to On [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 42101875 42101875 IN IP4 10.0.0.214... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] netsock2.c: Splitting 'yy.yy.10.241' into... [Jan 14 08:59:45] DEBUG[5183] netsock2.c: ...host 'yy.yy.10.241' and port ''. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 yy.yy.10.241... OK. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 0 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 0 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 2 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 8 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 8 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 18 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 18 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 96 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 97 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 97 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 98 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 98 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format G726-32 for ID 2 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format PCMA for ID 8 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format G729a for ID 18 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Unsetting payload 96 on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-40 for ID 96 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Unsetting payload 97 on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-24 for ID 97 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Unsetting payload 98 on 0x2b74bb598290 [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found unknown media description format G726-16 for ID 98 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:10.0.0.214... UNSUPPORTED. [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 0 on 0x2b74bb598290 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 2 on 0x2b74bb598290 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 8 on 0x2b74bb598290 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598290 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 18 on 0x2b74bb598290 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598290 [Jan 14 08:59:45] 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 08:59:45] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 08:59:45] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc016838' [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port yy.yy.10.241:16426 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 0 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 2 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 8 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 18 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598290 to 0x2b74bc016a00 [Jan 14 08:59:45] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74bc016838' [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Checking SIP call limits for device [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: Updating call counter for incoming call [Jan 14 08:59:45] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:45] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:45] DEBUG[5183] netsock2.c: Splitting 'hostname.example.com' into... [Jan 14 08:59:45] DEBUG[5183] netsock2.c: ...host 'hostname.example.com' and port ''. [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: Looking for 0000003 in from-internal (domain xx.xx.46.25) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: *** Joint capabilities are 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: This channel will not be able to handle video. [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 08:59:45] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 08:59:45] DEBUG[5183] chan_sip.c: SIP/product-local-0000170c: New call is still down.... Trying... [Jan 14 08:59:45] 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=z9hG4bK2ddb.79083ed1.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-71d0dcce Record-Route: From: "A C" ;tag=4a07e34d8c164eo0 To: "P M" Call-ID: 69ee90ac-1b46636@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 08:59:45] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:45] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 08:59:45] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 08:59:45] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 08:59:45] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 08:59:45] DEBUG[7514] pbx.c: Launching 'AGI' [Jan 14 08:59:45] 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 08:59:45] VERBOSE[7514] pbx.c: -- Executing [0000003@from-internal:1] AGI("SIP/product-local-0000170c", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_network_script: product?stype=internal [Jan 14 08:59:45] DEBUG[7514] res_agi.c: Wow, connected! [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-0000170c [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_language: en [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_uniqueid: 1358153985.13474 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callerid: 0000004 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_calleridname: A C [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_dnid: 0000003 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_extension: 0000003 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> agi_threadid: 47780446193408 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 08:59:45 2013 (1358153985)" 9 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/product?stype=internal: AGI starting at Mon Jan 14 08:59:45 2013 (1358153985) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-CALLID' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1358153985.13474" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-SCREEN' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-DIVERTED' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-DIVERSION' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 08:59:45] VERBOSE[7514] func_timeout.c: Channel will hangup at 2013-01-15 08:59:45.887 GMT. [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-CUTOFF' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 08:59:45] VERBOSE[7514] func_timeout.c: Channel will hangup at 2013-01-15 08:59:45.887 GMT. [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (69ee90ac-1b46636@10.0.0.214) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: 69ee90ac-1b46636@10.0.0.214" 9 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/product?stype=internal: SIP Call-ID is: 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-SCUSTOMER' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (yy.yy.10.241:19050) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-PRESENTATION-INTERNAL' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-PRESENTATION-EXTERNAL' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-External) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-TRANSFER-PHONE' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-CUSTOMER [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-TRANSFER-CUSTOMER' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Proxy-Authorization) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (Digest username="0000004",realm="hostname.example.com",nonce="50f3c91f000011e93c7f11b4f3e9ea9b7218fb15f96f905f",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="5cc7d7f919e6b3cfddbd73c373c3e496") [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "10" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "10" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER01 "Alert-Info: Simple-1" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '0000003', old '', forward 1 for channel SIP/product-local-0000170c" 5 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '0000003', old '', forward 1 for channel SIP/product-local-0000170c [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "Starting recording group '1' expires '1359363585' file '/var/lib/product/recordings/2/1/2013/01/14/record_135815398513474_13619'" 9 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/product?stype=internal: Starting recording group '1' expires '1359363585' file '/var/lib/product/recordings/2/1/2013/01/14/record_135815398513474_13619' [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << EXEC Monitor gsm,/var/lib/product/recordings/2/1/2013/01/14/record_135815398513474_13619 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: -- AGI Script Executing Application: (Monitor) Options: (gsm,/var/lib/product/recordings/2/1/2013/01/14/record_135815398513474_13619) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 14 08:59:45] DEBUG[7514] pbx.c: Result of 'product-QUEUE' is NULL [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (69ee90ac-1b46636@10.0.0.214) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (A C) [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1358153985.13474, phone:0000004 - phone:0000003." 9 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/product?stype=internal: Writing entry to active table for 1358153985.13474, phone:0000004 - phone:0000003. [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jan 14 08:59:45] VERBOSE[7514] func_timeout.c: Channel will hangup at 2013-01-15 08:59:45.988 GMT. [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "2" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "phone" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "0000003" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "0000004" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "2" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "86400" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-PHONE-DOMAIN "xx.xx.46.25:5060" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-PHONE-OPTS "ortM(product-answered^0^1358153985.13474)" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __SIPADDHEADER11 "X-product-Uniqueid: 1358153985.13474" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-PHONE "0000003" [Jan 14 08:59:45] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:46] VERBOSE[7514] res_agi.c: AGI Rx << EXEC Dial Local/0000003@product-phone/n,20,o [Jan 14 08:59:46] VERBOSE[7514] res_agi.c: -- AGI Script Executing Application: (Dial) Options: (Local/0000003@product-phone/n,20,o) [Jan 14 08:59:46] DEBUG[7514] rtp_engine.c: Can't find native functions for channel 'Local/0000003@product-phone-bca4;1' [Jan 14 08:59:46] DEBUG[7514] rtp_engine.c: Seeded SDP of 'Local/0000003@product-phone-bca4;1' with that of 'SIP/product-local-0000170c' [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable DIALEDTIME. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable ANSWEREDTIME. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable DIALEDPEERNAME. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable DIALSTATUS. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-TRANSFER-PHONE. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable SIPADDHEADER11. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-PHONE-OPTS. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-PHONE-DOMAIN. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-CUTOFF. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-PRESENTATION-EXTERNAL. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-PRESENTATION-INTERNAL. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-TRANSFER-CUSTOMER. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-DNUMBER. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-DTYPE. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-DCUSTOMER. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable MONITORED. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable SIPADDHEADER01. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-MUSIC. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 14 08:59:46] DEBUG[7514] channel.c: Copying hard-transferable variable product-CALLID. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable SIPCALLID. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable SIPDOMAIN. [Jan 14 08:59:46] DEBUG[7514] channel.c: Not copying variable SIPURI. [Jan 14 08:59:46] VERBOSE[7514] app_dial.c: -- Called Local/0000003@product-phone/n [Jan 14 08:59:46] DEBUG[7537] pbx.c: Result of 'product-MUSIC' is '10' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Expression result is '0' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Launching 'GotoIf' [Jan 14 08:59:46] VERBOSE[7537] pbx.c: -- Executing [0000003@product-phone:1] GotoIf("Local/0000003@product-phone-bca4;2", "0?3") in new stack [Jan 14 08:59:46] DEBUG[7537] pbx.c: Not taking any branch [Jan 14 08:59:46] DEBUG[7537] pbx.c: Result of 'product-MUSIC' is '10' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Launching 'SetMusicOnHold' [Jan 14 08:59:46] VERBOSE[7537] pbx.c: -- Executing [0000003@product-phone:2] SetMusicOnHold("Local/0000003@product-phone-bca4;2", "10") in new stack [Jan 14 08:59:46] DEBUG[7537] pbx.c: Result of 'EXTEN' is '0000003' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Result of 'product-PHONE-DOMAIN' is 'xx.xx.46.25:5060' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Result of 'product-PHONE-OPTS' is 'ortM(product-answered^0^1358153985.13474)' [Jan 14 08:59:46] DEBUG[7537] pbx.c: Launching 'Dial' [Jan 14 08:59:46] VERBOSE[7537] pbx.c: -- Executing [0000003@product-phone:3] Dial("Local/0000003@product-phone-bca4;2", "SIP/0000003@xx.xx.46.25:5060,3600,ortM(product-answered^0^1358153985.13474)") in new stack [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Asked to create a SIP channel with formats: 0x1000 (g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Allocating new SIP dialog for 2ca943fe34d4fa057aa5a7f33244f17f@xx.xx.46.25:5070 - INVITE (No RTP) [Jan 14 08:59:46] DEBUG[7537] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:46] DEBUG[7537] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' AND host = 'dynamic' [Jan 14 08:59:46] DEBUG[7537] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:46] DEBUG[7537] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 08:59:46] DEBUG[7537] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2b74c400c248' [Jan 14 08:59:46] DEBUG[7537] res_rtp_asterisk.c: Allocated port 16054 for RTP instance '0x2b74c400c248' [Jan 14 08:59:46] DEBUG[7537] rtp_engine.c: RTP instance '0x2b74c400c248' is setup and ready to go [Jan 14 08:59:46] DEBUG[7537] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2b74c400c248' [Jan 14 08:59:46] VERBOSE[7537] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Setting NAT on RTP to On [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jan 14 08:59:46] DEBUG[7537] netsock2.c: Splitting 'xx.xx.46.25:5060' into... [Jan 14 08:59:46] DEBUG[7537] netsock2.c: ...host 'xx.xx.46.25' and port '5060'. [Jan 14 08:59:46] DEBUG[7537] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: *** Our native formats are 0x1000 (g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: *** Joint capabilities are 0x1000 (g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: *** Our capabilities are 0x1fee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: *** Our preferred formats from the incoming channel are 0x1000 (g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: This channel will not be able to handle video. [Jan 14 08:59:46] DEBUG[7537] channel.c: Not copying variable DIALEDTIME. [Jan 14 08:59:46] DEBUG[7537] channel.c: Not copying variable ANSWEREDTIME. [Jan 14 08:59:46] DEBUG[7537] channel.c: Not copying variable DIALEDPEERNAME. [Jan 14 08:59:46] DEBUG[7537] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 14 08:59:46] DEBUG[7537] channel.c: Not copying variable DIALSTATUS. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-TRANSFER-PHONE. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable SIPADDHEADER11. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-PHONE-OPTS. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-PHONE-DOMAIN. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-CUTOFF. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-PRESENTATION-EXTERNAL. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-PRESENTATION-INTERNAL. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-TRANSFER-CUSTOMER. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-DNUMBER. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-DTYPE. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-DCUSTOMER. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable MONITORED. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable SIPADDHEADER01. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-MUSIC. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [Jan 14 08:59:46] DEBUG[7537] channel.c: Copying hard-transferable variable product-CALLID. [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Outgoing Call for 0000003 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Updating call counter for outgoing call [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Adding SIP Header "X-product-Uniqueid" with content :1358153985.13474: [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Adding SIP Header "Alert-Info" with content :Simple-1: [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: ** Our capability: 0x1dee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g722) Video flag: False Text flag: False [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: ** Our prefcodec: 0x1000 (g722) [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Audio is at 16054 [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x1000 (g722) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x40 (slin) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x2 (gsm) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x800 (g726) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x20 (adpcm) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x80 (lpc10) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x400 (ilbc) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 14 08:59:46] VERBOSE[7537] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Done building SDP. Settling with this capability: 0x1dee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|ilbc|g722) [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Initializing initreq for method INVITE - callid 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 0 [ 44]: INVITE sip:0000003@xx.xx.46.25:5060 SIP/2.0 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK710eb270;rport [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 3 [ 68]: From: "A C" ;tag=as46e6fe28 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 4 [ 35]: To: [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 5 [ 40]: Contact: [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 6 [ 59]: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 8 [ 20]: User-Agent: product [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 9 [ 35]: Date: Mon, 14 Jan 2013 08:59:46 GMT [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 12 [ 37]: X-product-Uniqueid: 1358153985.13474 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 13 [ 20]: Alert-Info: Simple-1 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jan 14 08:59:46] VERBOSE[7537] 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=z9hG4bK710eb270;rport Max-Forwards: 70 From: "A C" ;tag=as46e6fe28 To: Contact: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 CSeq: 102 INVITE User-Agent: product Date: Mon, 14 Jan 2013 08:59:46 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-product-Uniqueid: 1358153985.13474 Alert-Info: Simple-1 Content-Type: application/sdp Content-Length: 501 v=0 o=root 835795556 835795556 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 16054 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 08:59:46] DEBUG[7537] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110699 [Jan 14 08:59:46] DEBUG[7537] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:46] VERBOSE[7537] app_dial.c: -- Called SIP/0000003@xx.xx.46.25:5060 [Jan 14 08:59:46] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 08:59:46] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 08:59:46] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 2 (In use) [Jan 14 08:59:46] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '2' [Jan 14 08:59:46] 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 08:59:46] VERBOSE[7514] app_dial.c: -- Local/0000003@product-phone-bca4;1 is ringing [Jan 14 08:59:46] 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=z9hG4bK710eb270;rport=5070 From: "A C" ;tag=as46e6fe28 To: Call-ID: 768af463211d72c301aa3c0270a1bd70@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 08:59:46] DEBUG[5183] chan_sip.c: Header 0 [ 24]: SIP/2.0 100 Giving a try [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK710eb270;rport=5070 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as46e6fe28 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 3 [ 35]: To: [Jan 14 08:59:46] VERBOSE[7514] 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=z9hG4bK2ddb.79083ed1.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-71d0dcce Record-Route: From: "A C" ;tag=4a07e34d8c164eo0 To: "P M" ;tag=as10c2d221 Call-ID: 69ee90ac-1b46636@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 08:59:46] DEBUG[5183] chan_sip.c: Header 4 [ 59]: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 6 [ 26]: Server: product SIP proxy [Jan 14 08:59:46] DEBUG[7514] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:46] 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 08:59:46] VERBOSE[5183] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: = Looking for Call ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 (Checking To) --From tag as46e6fe28 --To-tag [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: *** SIP TIMER: Cancelling retransmission #110699 - INVITE (got response) [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070' Request 102: Found [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: SIP response 100 to standard invite [Jan 14 08:59:46] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 180 Ringing To: ;tag=c4ed28be5805287ei0 From: "A C" ;tag=as46e6fe28 Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK710eb270;rport=5070 Record-Route: Contact: "P M" Server: Cisco/SPA502G-7.5.3 Content-Length: 0 <-------------> [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 1 [ 58]: To: ;tag=c4ed28be5805287ei0 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as46e6fe28 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 3 [ 59]: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 5 [ 90]: Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK710eb270;rport=5070 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 6 [ 54]: Record-Route: [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 7 [ 57]: Contact: "P M" [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 8 [ 27]: Server: Cisco/SPA502G-7.5.3 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jan 14 08:59:46] VERBOSE[5183] chan_sip.c: --- (10 headers 0 lines) --- [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: = Looking for Call ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 (Checking To) --From tag as46e6fe28 --To-tag c4ed28be5805287ei0 [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070' Request 102: Found [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: SIP response 180 to standard invite [Jan 14 08:59:46] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 08:59:46] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 08:59:46] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - xx.xx.46.25:5060 [Jan 14 08:59:46] DEBUG[5161] chan_sip.c: Checking device state for peer xx.xx.46.25:5060 [Jan 14 08:59:46] VERBOSE[7537] app_dial.c: -- SIP/xx.xx.46.25:5060-0000170d is ringing [Jan 14 08:59:46] VERBOSE[7514] app_dial.c: -- Local/0000003@product-phone-bca4;1 is ringing [Jan 14 08:59:46] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:46] 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 08:59:46] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:46] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 08:59:46] DEBUG[5161] devicestate.c: Changing state for SIP/xx.xx.46.25:5060 - state 6 (Ringing) [Jan 14 08:59:46] DEBUG[5161] devicestate.c: device 'SIP/xx.xx.46.25:5060' state '6' [Jan 14 08:59:46] 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 08:59:49] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 200 OK To: ;tag=c4ed28be5805287ei0 From: "A C" ;tag=as46e6fe28 Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 CSeq: 102 INVITE Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK710eb270;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=- 57685925 57685925 IN IP4 10.0.0.213 s=- c=IN IP4 yy.yy.10.241 t=0 0 m=audio 16468 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 08:59:49] DEBUG[5183] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 1 [ 58]: To: ;tag=c4ed28be5805287ei0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "A C" ;tag=as46e6fe28 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 3 [ 59]: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jan 14 08:59: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=z9hG4bK710eb270;rport=5070 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 6 [ 54]: Record-Route: [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 7 [ 57]: Contact: "P M" [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 8 [ 27]: Server: Cisco/SPA502G-7.5.3 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 9 [ 19]: Content-Length: 254 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 10 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 11 [ 19]: Supported: replaces [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 13 [ 0]: [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 0 [ 3]: v=0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 1 [ 39]: o=- 57685925 57685925 IN IP4 10.0.0.213 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 2 [ 3]: s=- [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 3 [ 22]: c=IN IP4 yy.yy.10.241 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 5 [ 27]: m=audio 16468 RTP/AVP 9 101 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 6 [ 20]: a=rtpmap:9 G722/8000 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 11 [ 18]: a=direction:active [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Body 12 [ 23]: a=oldmediaip:10.0.0.213 [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: --- (13 headers 13 lines) --- [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: = Looking for Call ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 (Checking To) --From tag as46e6fe28 --To-tag c4ed28be5805287ei0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Acked pending invite 102 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Stopping retransmission on '768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070' of Request 102: Match Found [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: SIP response 200 to standard invite [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing session-level SDP o=- 57685925 57685925 IN IP4 10.0.0.213... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] netsock2.c: Splitting 'yy.yy.10.241' into... [Jan 14 08:59:49] DEBUG[5183] netsock2.c: ...host 'yy.yy.10.241' and port ''. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing session-level SDP c=IN IP4 yy.yy.10.241... OK. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Found RTP audio format 9 [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Setting payload 9 based on m type on 0x2b74bb598db0 [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Found RTP audio format 101 [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Setting payload 101 based on m type on 0x2b74bb598db0 [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Found audio description format G722 for ID 9 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Found audio description format telephone-event for ID 101 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=direction:active... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Processing media-level (audio) SDP a=oldmediaip:10.0.0.213... UNSUPPORTED. [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Incorporating payload 9 on 0x2b74bb598db0 [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Incorporating payload 101 on 0x2b74bb598db0 [Jan 14 08:59: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 08:59:49] VERBOSE[5183] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Jan 14 08:59:49] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c400c248' [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Peer audio RTP is at port yy.yy.10.241:16468 [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Copying payload 9 from 0x2b74bb598db0 to 0x2b74c400c410 [Jan 14 08:59:49] DEBUG[5183] rtp_engine.c: Copying payload 101 from 0x2b74bb598db0 to 0x2b74c400c410 [Jan 14 08:59:49] DEBUG[5183] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x2b74c400c248' [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: We're settling with these formats: 0x1000 (g722) [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: We have an owner, now see if we need to change this call [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Updating call counter for outgoing call [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: build_route: Record-Route hop: [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: list_route: hop: [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 08:59:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 08:59:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: set_destination: set destination to xx.xx.46.25:5060 [Jan 14 08:59: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=z9hG4bK7b3d3b77;rport Route: Max-Forwards: 70 From: "A C" ;tag=as46e6fe28 To: ;tag=c4ed28be5805287ei0 Contact: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 CSeq: 102 ACK User-Agent: product Content-Length: 0 --- [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Trying to put 'ACK sip:000' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:49] VERBOSE[7537] app_dial.c: -- SIP/xx.xx.46.25:5060-0000170d answered Local/0000003@product-phone-bca4;2 [Jan 14 08:59:49] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - xx.xx.46.25:5060 [Jan 14 08:59:49] DEBUG[5161] chan_sip.c: Checking device state for peer xx.xx.46.25:5060 [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'ARG1' is '0' [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'ARG2' is '1358153985.13474' [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'ARG3' is NULL [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'ARG4' is NULL [Jan 14 08:59:49] DEBUG[7537] pbx.c: Launching 'AGI' [Jan 14 08:59:49] VERBOSE[7537] pbx.c: -- Executing [s@macro-product-answered:1] AGI("SIP/xx.xx.46.25:5060-0000170d", "agi://127.0.0.1/answered?screen=0&puniqueid=1358153985.13474&pcallid=&snumber=") in new stack [Jan 14 08:59:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 08:59: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 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_network_script: answered?screen=0&puniqueid=1358153985.13474&pcallid=&snumber= [Jan 14 08:59:49] DEBUG[7537] res_agi.c: Wow, connected! [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/answered?screen=0&puniqueid=1358153985.13474&pcallid=&snumber= [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_channel: SIP/xx.xx.46.25:5060-0000170d [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_language: en [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_uniqueid: 1358153986.13477 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 08:59:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:49] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_callerid: 0000004 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_calleridname: A C [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 08:59:49] DEBUG[5161] devicestate.c: Changing state for SIP/xx.xx.46.25:5060 - state 2 (In use) [Jan 14 08:59:49] DEBUG[5161] devicestate.c: device 'SIP/xx.xx.46.25:5060' state '2' [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 08:59: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 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_dnid: unknown [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_context: macro-product-answered [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_extension: s [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> agi_threadid: 47780441609984 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 08:59:49 2013 (1358153989)" 9 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: > agi://127.0.0.1/answered?screen=0&puniqueid=1358153985.13474&pcallid=&snumber=: AGI starting at Mon Jan 14 08:59:49 2013 (1358153989) [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'product-CALLID' is '1358153985.13474' [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> 200 result=1 (1358153985.13474) [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c400c248' [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address yy.yy.10.241:55484 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Rx << SET VARIABLE MACRO_RESULT "" [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFERRED-BY [Jan 14 08:59:49] DEBUG[7537] pbx.c: Result of 'product-TRANSFERRED-BY' is NULL [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> 200 result=0 [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:58957 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:39116;branch=z9hG4bK.1b43c2d3;rport;alias From: sip:sipsak@xx.xx.46.25:39116;tag=7fea8178 To: sip:xx.xx.46.25:5070 Call-ID: 2146075000@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:39116 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:39116;branch=z9hG4bK.1b43c2d3;rport;alias [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:39116;tag=7fea8178 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 2146075000@xx.xx.46.25 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:39116 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: = Looking for Call ID: 2146075000@xx.xx.46.25 (Checking From) --From tag 7fea8178 --To-tag [Jan 14 08:59:49] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 2146075000@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:49] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:49] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:39116' into... [Jan 14 08:59:49] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:58957 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:39116;branch=z9hG4bK.1b43c2d3;alias;received=xx.xx.46.25;rport=58957 From: sip:sipsak@xx.xx.46.25:39116;tag=7fea8178 To: sip:xx.xx.46.25:5070;tag=as74b52c34 Call-ID: 2146075000@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 08:59:49] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:58957 [Jan 14 08:59:49] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '2146075000@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: -- AGI Script agi://127.0.0.1/answered?screen=0&puniqueid=1358153985.13474&pcallid=&snumber= completed, returning 0 [Jan 14 08:59:49] VERBOSE[7537] res_agi.c: AGI Tx >> HANGUP [Jan 14 08:59:49] DEBUG[7537] app_macro.c: Executed application: AGI [Jan 14 08:59:49] DEBUG[7537] app_dial.c: Macro exited with status 0 [Jan 14 08:59:49] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 08:59:49] DEBUG[7537] features.c: bridge answer set, chan answer set [Jan 14 08:59:49] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 08:59:49] DEBUG[7537] features.c: Removing dialed interfaces datastore on SIP/xx.xx.46.25:5060-0000170d since we're bridging [Jan 14 08:59:49] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 2 (In use) [Jan 14 08:59:49] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '2' [Jan 14 08:59:49] VERBOSE[7514] app_dial.c: -- Local/0000003@product-phone-bca4;1 stopped sounds [Jan 14 08:59:49] VERBOSE[7514] app_dial.c: -- Local/0000003@product-phone-bca4;1 answered SIP/product-local-0000170c [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: SIP answering channel: SIP/product-local-0000170c [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 08:59:49] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 08:59:49] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 2 (In use) [Jan 14 08:59:49] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '2' [Jan 14 08:59:49] 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 08:59:49] DEBUG[7514] chan_sip.c: Setting framing from config on incoming call [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: ** Our capability: 0x190c (ulaw|alaw|g726|g729|g722) Video flag: True Text flag: True [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 14 08:59:49] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Audio is at 10552 [Jan 14 08:59:49] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Adding codec 0x1000 (g722) to SDP [Jan 14 08:59:49] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Jan 14 08:59:49] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Adding codec 0x800 (g726) to SDP [Jan 14 08:59:49] 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 08:59:49] VERBOSE[7514] chan_sip.c: Adding codec 0x100 (g729) to SDP [Jan 14 08:59:49] VERBOSE[7514] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: -- Done with adding codecs to SDP [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: Done building SDP. Settling with this capability: 0x190c (ulaw|alaw|g726|g729|g722) [Jan 14 08:59:49] 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 08:59:49] VERBOSE[7514] 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=z9hG4bK2ddb.79083ed1.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-71d0dcce Record-Route: From: "A C" ;tag=4a07e34d8c164eo0 To: "P M" ;tag=as10c2d221 Call-ID: 69ee90ac-1b46636@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-Type: application/sdp Content-Length: 357 v=0 o=root 304694905 304694905 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 10552 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 08:59:49] DEBUG[7514] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110704 [Jan 14 08:59:49] DEBUG[7514] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:49] DEBUG[7514] features.c: bridge answer set, chan answer set [Jan 14 08:59:49] DEBUG[7514] features.c: Removing dialed interfaces datastore on Local/0000003@product-phone-bca4;1 since we're bridging [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7514] channel.c: Got a FRAME_CONTROL (-1) frame on channel Local/0000003@product-phone-bca4;1 [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7514] channel.c: Bridge stops bridging channels SIP/product-local-0000170c and Local/0000003@product-phone-bca4;1 [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7537] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Jan 14 08:59:49] DEBUG[7514] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x2b74bc016838' [Jan 14 08:59:50] 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 Record-Route: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK2ddb.79083ed1.2 Via: SIP/2.0/UDP 10.0.0.214:5060;rport=19050;received=yy.yy.10.241;branch=z9hG4bK-ab2950f3 From: "A C" ;tag=4a07e34d8c164eo0 To: "P M" ;tag=as10c2d221 Call-ID: 69ee90ac-1b46636@10.0.0.214 CSeq: 102 ACK Max-Forwards: 69 Route: Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3c91f000011e93c7f11b4f3e9ea9b7218fb15f96f905f",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="5cc7d7f919e6b3cfddbd73c373c3e496" Contact: "A C" User-Agent: Cisco/SPA502G-7.5.4 Content-Length: 0 X-product-RURI: sip:0000003@xx.xx.46.25:5070 X-product-Source: yy.yy.10.241:19050 <-------------> [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 0 [ 55]: ACK sip:0000003@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 1 [ 60]: Record-Route: [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK2ddb.79083ed1.2 [Jan 14 08:59:50] 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-ab2950f3 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 4 [ 75]: From: "A C" ;tag=4a07e34d8c164eo0 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 5 [ 66]: To: "P M" ;tag=as10c2d221 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 6 [ 36]: Call-ID: 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 102 ACK [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 9 [ 53]: Route: [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 10 [225]: Proxy-Authorization: Digest username="0000004",realm="hostname.example.com",nonce="50f3c91f000011e93c7f11b4f3e9ea9b7218fb15f96f905f",uri="sip:0000003@hostname.example.com",algorithm=MD5,response="5cc7d7f919e6b3cfddbd73c373c3e496" [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 11 [ 58]: Contact: "A C" [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 12 [ 31]: User-Agent: Cisco/SPA502G-7.5.4 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 14 [ 46]: X-product-RURI: sip:0000003@xx.xx.46.25:5070 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Header 15 [ 38]: X-product-Source: yy.yy.10.241:19050 [Jan 14 08:59:50] VERBOSE[5183] chan_sip.c: --- (16 headers 0 lines) --- [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: = Looking for Call ID: 69ee90ac-1b46636@10.0.0.214 (Checking From) --From tag 4a07e34d8c164eo0 --To-tag as10c2d221 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110704 [Jan 14 08:59:50] DEBUG[5183] chan_sip.c: Stopping retransmission on '69ee90ac-1b46636@10.0.0.214' of Response 102: Match Found [Jan 14 08:59:50] DEBUG[7514] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc016838' [Jan 14 08:59:50] DEBUG[7514] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address yy.yy.10.241:41781 [Jan 14 08:59:50] DEBUG[7537] res_rtp_asterisk.c: Ooh, format changed from unknown to g722 [Jan 14 08:59:50] DEBUG[7537] res_rtp_asterisk.c: Created smoother: format: g722 ms: 20 len: 160 [Jan 14 08:59:51] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '358522199@xx.xx.46.25' [Jan 14 08:59:51] DEBUG[5183] chan_sip.c: Destroying SIP dialog 358522199@xx.xx.46.25 [Jan 14 08:59:51] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '358522199@xx.xx.46.25' Method: OPTIONS [Jan 14 08:59:53] 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=z9hG4bK6f9e.d9f5ea53.0 Via: SIP/2.0/UDP 10.0.0.213:5060;rport=59990;received=yy.yy.10.241;branch=z9hG4bK-3097454e From: ;tag=c4ed28be5805287ei0 To: "A C" ;tag=as46e6fe28 Call-ID: 768af463211d72c301aa3c0270a1bd70@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 08:59:53] DEBUG[5183] chan_sip.c: Header 0 [ 55]: BYE sip:0000004@xx.xx.46.25:5070;transport=udp SIP/2.0 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 1 [ 62]: Record-Route: [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 2 [ 59]: Via: SIP/2.0/UDP xx.xx.46.25;branch=z9hG4bK6f9e.d9f5ea53.0 [Jan 14 08:59:53] 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-3097454e [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 4 [ 55]: From: ;tag=c4ed28be5805287ei0 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 5 [ 61]: To: "A C" ;tag=as46e6fe28 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 6 [ 59]: Call-ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 7 [ 13]: CSeq: 101 BYE [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 9 [ 47]: Route: [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 10 [ 31]: User-Agent: Cisco/SPA502G-7.5.3 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 12 [ 46]: X-product-RURI: sip:0000004@xx.xx.46.25:5070 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Header 13 [ 38]: X-product-Source: yy.yy.10.241:59990 [Jan 14 08:59:53] VERBOSE[5183] chan_sip.c: --- (14 headers 0 lines) --- [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: = Looking for Call ID: 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 (Checking From) --From tag c4ed28be5805287ei0 --To-tag as46e6fe28 [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Initializing initreq for method BYE - callid 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:53] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 08:59:53] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:53] VERBOSE[5183] chan_sip.c: Sending to xx.xx.46.25:5060 (NAT) [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Setting SIP_ALREADYGONE on dialog 768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070 [Jan 14 08:59:53] DEBUG[5183] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c400c248' [Jan 14 08:59:53] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '768af463211d72c301aa3c0270a1bd70@xx.xx.46.25:5070' in 32000 ms (Method: BYE) [Jan 14 08:59:53] DEBUG[5183] chan_sip.c: Received bye, issuing owner hangup [Jan 14 08:59:53] 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=z9hG4bK6f9e.d9f5ea53.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-3097454e Record-Route: From: ;tag=c4ed28be5805287ei0 To: "A C" ;tag=as46e6fe28 Call-ID: 768af463211d72c301aa3c0270a1bd70@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 08:59:53] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:53] DEBUG[7537] channel.c: Didn't get a frame from channel: SIP/xx.xx.46.25:5060-0000170d [Jan 14 08:59:53] DEBUG[7537] channel.c: Bridge stops bridging channels Local/0000003@product-phone-bca4;2 and SIP/xx.xx.46.25:5060-0000170d [Jan 14 08:59:53] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:53] DEBUG[7537] channel.c: Hanging up channel 'SIP/xx.xx.46.25:5060-0000170d' [Jan 14 08:59:53] DEBUG[7537] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 08:59:53] DEBUG[7537] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74c400c248' [Jan 14 08:59:53] DEBUG[7537] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 14 08:59:53] DEBUG[7537] pbx.c: Spawn extension (product-phone,0000003,3) exited non-zero on 'Local/0000003@product-phone-bca4;2' [Jan 14 08:59:53] VERBOSE[7537] pbx.c: == Spawn extension (product-phone, 0000003, 3) exited non-zero on 'Local/0000003@product-phone-bca4;2' [Jan 14 08:59:53] DEBUG[7537] channel.c: Soft-Hanging up channel 'Local/0000003@product-phone-bca4;2' [Jan 14 08:59:53] DEBUG[7537] channel.c: Hanging up channel 'Local/0000003@product-phone-bca4;2' [Jan 14 08:59:53] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - xx.xx.46.25:5060 [Jan 14 08:59:53] DEBUG[5161] chan_sip.c: Checking device state for peer xx.xx.46.25:5060 [Jan 14 08:59:53] DEBUG[7514] channel.c: Didn't get a frame from channel: Local/0000003@product-phone-bca4;1 [Jan 14 08:59:53] DEBUG[7514] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 14 08:59:53] DEBUG[7514] channel.c: Bridge stops bridging channels SIP/product-local-0000170c and Local/0000003@product-phone-bca4;1 [Jan 14 08:59:53] DEBUG[7514] channel.c: Soft-Hanging up channel 'SIP/product-local-0000170c' [Jan 14 08:59:53] DEBUG[7514] pbx.c: Launching 'AGI' [Jan 14 08:59:53] VERBOSE[7514] pbx.c: -- Executing [h@from-internal:1] AGI("SIP/product-local-0000170c", "agi://127.0.0.1/end") in new stack [Jan 14 08:59:53] DEBUG[7514] res_agi.c: Hungup channel detected, running agi in dead mode. [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_network: yes [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_network_script: end [Jan 14 08:59:53] DEBUG[7514] res_agi.c: Wow, connected! [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/end [Jan 14 08:59:53] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:53] 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 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-0000170c [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_language: en [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_type: SIP [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_uniqueid: 1358153985.13474 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_version: 1.8.11.1 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callerid: 0000004 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_calleridname: A C [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 14 08:59:53] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Connection okay. [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 14 08:59:53] DEBUG[5161] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = 'xx.xx.46.25:5060' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_dnid: 0000003 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_extension: h [Jan 14 08:59:53] DEBUG[5161] devicestate.c: Changing state for SIP/xx.xx.46.25:5060 - state 0 (Unknown) [Jan 14 08:59:53] DEBUG[5161] devicestate.c: device 'SIP/xx.xx.46.25:5060' state '0' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_accountcode: [Jan 14 08:59:53] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 08:59:53] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> agi_threadid: 47780446193408 [Jan 14 08:59:53] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 2 (In use) [Jan 14 08:59:53] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '2' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> [Jan 14 08:59:53] DEBUG[5189] app_queue.c: Device 'SIP/xx.xx.46.25:5060' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jan 14 08:59:53] 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 08:59:53] VERBOSE[7514] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 14 08:59:53 2013 (1358153993)" 9 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: > agi://127.0.0.1/end: AGI starting at Mon Jan 14 08:59:53 2013 (1358153993) [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) en [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 14 08:59:53] DEBUG[7514] pbx.c: Result of 'product-CALLID' is '1358153985.13474' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (1358153985.13474) [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE ANSWEREDTIME [Jan 14 08:59:53] DEBUG[7514] pbx.c: Result of 'ANSWEREDTIME' is '4' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (4) [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jan 14 08:59:53] DEBUG[7514] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [Jan 14 08:59:53] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (ANSWER) [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> HANGUP [Jan 14 08:59:54] DEBUG[7514] channel.c: Hanging up channel 'Local/0000003@product-phone-bca4;1' [Jan 14 08:59:54] DEBUG[7514] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=-1 [Jan 14 08:59:54] DEBUG[7514] res_agi.c: SIP/product-local-0000170c hungup [Jan 14 08:59:54] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for Local - 0000003@product-phone [Jan 14 08:59:54] DEBUG[5161] chan_local.c: Checking if extension 0000003@product-phone exists (devicestate) [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> HANGUP [Jan 14 08:59:54] DEBUG[5161] devicestate.c: Changing state for Local/0000003@product-phone - state 1 (Not in use) [Jan 14 08:59:54] DEBUG[5161] devicestate.c: device 'Local/0000003@product-phone' state '1' [Jan 14 08:59:54] 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 08:59:54] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-PHONE "" [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jan 14 08:59:54] DEBUG[7514] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> 200 result=1 (ANSWER) [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 4 [Jan 14 08:59:54] VERBOSE[7514] res_agi.c: AGI Tx >> HANGUP [Jan 14 08:59:54] ERROR[7514] utils.c: write() returned error: Broken pipe [Jan 14 08:59:54] DEBUG[7514] pbx.c: Spawn extension (from-internal,0000003,1) exited non-zero on 'SIP/product-local-0000170c' [Jan 14 08:59:54] VERBOSE[7514] pbx.c: == Spawn extension (from-internal, 0000003, 1) exited non-zero on 'SIP/product-local-0000170c' [Jan 14 08:59:54] DEBUG[7514] channel.c: Soft-Hanging up channel 'SIP/product-local-0000170c' [Jan 14 08:59:54] DEBUG[7514] channel.c: Hanging up channel 'SIP/product-local-0000170c' [Jan 14 08:59:54] DEBUG[7514] chan_sip.c: Hanging up zombie call. Be scared. [Jan 14 08:59:54] DEBUG[7514] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2b74bc016838' [Jan 14 08:59:54] VERBOSE[7514] chan_sip.c: Scheduling destruction of SIP dialog '69ee90ac-1b46636@10.0.0.214' in 32000 ms (Method: ACK) [Jan 14 08:59:54] VERBOSE[7514] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 14 08:59:54] DEBUG[7514] netsock2.c: Splitting 'xx.xx.46.25' into... [Jan 14 08:59:54] DEBUG[7514] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:54] VERBOSE[7514] chan_sip.c: set_destination: set destination to xx.xx.46.25:5060 [Jan 14 08:59:54] VERBOSE[7514] chan_sip.c: Reliably Transmitting (NAT) to xx.xx.46.25:5060: BYE sip:0000004@yy.yy.10.241:19050 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:5070;branch=z9hG4bK1e75a5d0;rport Route: Max-Forwards: 70 From: "P M" ;tag=as10c2d221 To: "A C" ;tag=4a07e34d8c164eo0 Call-ID: 69ee90ac-1b46636@10.0.0.214 CSeq: 102 BYE User-Agent: product X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jan 14 08:59:54] DEBUG[7514] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #110708 [Jan 14 08:59:54] DEBUG[7514] chan_sip.c: Trying to put 'BYE sip:000' onto UDP socket destined for xx.xx.46.25:5060 [Jan 14 08:59:54] DEBUG[5161] devicestate.c: No provider found, checking channel drivers for SIP - product-local [Jan 14 08:59:54] DEBUG[5161] chan_sip.c: Checking device state for peer product-local [Jan 14 08:59:54] DEBUG[5161] devicestate.c: Changing state for SIP/product-local - state 1 (Not in use) [Jan 14 08:59:54] DEBUG[5161] devicestate.c: device 'SIP/product-local' state '1' [Jan 14 08:59:54] 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 08:59:54] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:5060 ---> SIP/2.0 200 OK To: "A C" ;tag=4a07e34d8c164eo0 From: "P M" ;tag=as10c2d221 Call-ID: 69ee90ac-1b46636@10.0.0.214 CSeq: 102 BYE Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK1e75a5d0;rport=5070 Record-Route: Server: Cisco/SPA502G-7.5.4 Content-Length: 0 <-------------> [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 1 [ 73]: To: "A C" ;tag=4a07e34d8c164eo0 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 2 [ 68]: From: "P M" ;tag=as10c2d221 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 3 [ 36]: Call-ID: 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 4 [ 13]: CSeq: 102 BYE [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 5 [ 90]: Via: SIP/2.0/UDP xx.xx.46.25:5070;received=xx.xx.46.25;branch=z9hG4bK1e75a5d0;rport=5070 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 6 [ 54]: Record-Route: [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 7 [ 27]: Server: Cisco/SPA502G-7.5.4 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jan 14 08:59:54] VERBOSE[5183] chan_sip.c: --- (9 headers 0 lines) --- [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: = Looking for Call ID: 69ee90ac-1b46636@10.0.0.214 (Checking To) --From tag as10c2d221 --To-tag 4a07e34d8c164eo0 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #110708 [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Stopping retransmission on '69ee90ac-1b46636@10.0.0.214' of Request 102: Match Found [Jan 14 08:59:54] VERBOSE[5183] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jan 14 08:59:54] DEBUG[5183] chan_sip.c: Destroying SIP dialog 69ee90ac-1b46636@10.0.0.214 [Jan 14 08:59:54] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '69ee90ac-1b46636@10.0.0.214' Method: ACK [Jan 14 08:59:54] DEBUG[5183] rtp_engine.c: Destroyed RTP instance '0x2b74bc016838' [Jan 14 08:59:57] VERBOSE[7283] asterisk.c: -- Remote UNIX connection disconnected [Jan 14 08:59:59] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 08:59:59] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:51414 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:35689;branch=z9hG4bK.222578c6;rport;alias From: sip:sipsak@xx.xx.46.25:35689;tag=62fc6f37 To: sip:xx.xx.46.25:5070 Call-ID: 1660710711@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:35689 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:35689;branch=z9hG4bK.222578c6;rport;alias [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:35689;tag=62fc6f37 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1660710711@xx.xx.46.25 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:35689 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 08:59:59] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1660710711@xx.xx.46.25 (Checking From) --From tag 62fc6f37 --To-tag [Jan 14 08:59:59] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1660710711@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 08:59:59] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 08:59:59] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 08:59:59] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:59] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:35689' into... [Jan 14 08:59:59] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 08:59:59] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 08:59:59] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:51414 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:35689;branch=z9hG4bK.222578c6;alias;received=xx.xx.46.25;rport=51414 From: sip:sipsak@xx.xx.46.25:35689;tag=62fc6f37 To: sip:xx.xx.46.25:5070;tag=as2c44cf5e Call-ID: 1660710711@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 08:59:59] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:51414 [Jan 14 08:59:59] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1660710711@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:00:01] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1765457731@xx.xx.46.25' [Jan 14 09:00:01] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1765457731@xx.xx.46.25 [Jan 14 09:00:01] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1765457731@xx.xx.46.25' Method: OPTIONS [Jan 14 09:00:04] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:00:09] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:00:09] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:51779 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:38287;branch=z9hG4bK.25d78945;rport;alias From: sip:sipsak@xx.xx.46.25:38287;tag=c05358a To: sip:xx.xx.46.25:5070 Call-ID: 201667978@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:38287 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:38287;branch=z9hG4bK.25d78945;rport;alias [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 2 [ 47]: From: sip:sipsak@xx.xx.46.25:38287;tag=c05358a [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 4 [ 31]: Call-ID: 201667978@xx.xx.46.25 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:38287 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 09:00:09] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: = Looking for Call ID: 201667978@xx.xx.46.25 (Checking From) --From tag c05358a --To-tag [Jan 14 09:00:09] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 201667978@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 09:00:09] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 09:00:09] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:00:09] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:00:09] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:38287' into... [Jan 14 09:00:09] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:00:09] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 09:00:09] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:51779 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:38287;branch=z9hG4bK.25d78945;alias;received=xx.xx.46.25;rport=51779 From: sip:sipsak@xx.xx.46.25:38287;tag=c05358a To: sip:xx.xx.46.25:5070;tag=as23ec278e Call-ID: 201667978@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:00:09] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:51779 [Jan 14 09:00:09] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '201667978@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:00:11] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '1067072683@xx.xx.46.25' [Jan 14 09:00:11] DEBUG[5183] chan_sip.c: Destroying SIP dialog 1067072683@xx.xx.46.25 [Jan 14 09:00:11] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '1067072683@xx.xx.46.25' Method: OPTIONS [Jan 14 09:00:14] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:00:19] VERBOSE[5183] chan_sip.c: <--- SIP read from UDP:xx.xx.46.25:49841 ---> OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx.46.25:43890;branch=z9hG4bK.5fa0b68d;rport;alias From: sip:sipsak@xx.xx.46.25:43890;tag=739fb3b7 To: sip:xx.xx.46.25:5070 Call-ID: 1939846071@xx.xx.46.25 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx.46.25:43890 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 0 [ 37]: OPTIONS sip:xx.xx.46.25:5070 SIP/2.0 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP xx.xx.46.25:43890;branch=z9hG4bK.5fa0b68d;rport;alias [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 2 [ 48]: From: sip:sipsak@xx.xx.46.25:43890;tag=739fb3b7 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 3 [ 25]: To: sip:xx.xx.46.25:5070 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 4 [ 32]: Call-ID: 1939846071@xx.xx.46.25 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 5 [ 15]: CSeq: 1 OPTIONS [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 6 [ 38]: Contact: sip:sipsak@xx.xx.46.25:43890 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 9 [ 24]: User-Agent: sipsak 0.9.6 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Header 10 [ 18]: Accept: text/plain [Jan 14 09:00:19] VERBOSE[5183] chan_sip.c: --- (11 headers 0 lines) --- [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: = Looking for Call ID: 1939846071@xx.xx.46.25 (Checking From) --From tag 739fb3b7 --To-tag [Jan 14 09:00:19] DEBUG[5183] acl.c: For destination 'xx.xx.46.25', our source address is 'xx.xx.46.25'. [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Setting SIP_TRANSPORT_UDP with address xx.xx.46.25:5070 [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: Allocating new SIP dialog for 1939846071@xx.xx.46.25 - OPTIONS (No RTP) [Jan 14 09:00:19] DEBUG[5183] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 14 09:00:19] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:5070' into... [Jan 14 09:00:19] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:00:19] DEBUG[5183] netsock2.c: Splitting 'xx.xx.46.25:43890' into... [Jan 14 09:00:19] DEBUG[5183] netsock2.c: ...host 'xx.xx.46.25' and port ''. [Jan 14 09:00:19] VERBOSE[5183] chan_sip.c: Looking for s in from-external (domain xx.xx.46.25) [Jan 14 09:00:19] VERBOSE[5183] chan_sip.c: <--- Transmitting (NAT) to xx.xx.46.25:49841 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx.46.25:43890;branch=z9hG4bK.5fa0b68d;alias;received=xx.xx.46.25;rport=49841 From: sip:sipsak@xx.xx.46.25:43890;tag=739fb3b7 To: sip:xx.xx.46.25:5070;tag=as69a3c0da Call-ID: 1939846071@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:00:19] DEBUG[5183] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for xx.xx.46.25:49841 [Jan 14 09:00:19] VERBOSE[5183] chan_sip.c: Scheduling destruction of SIP dialog '1939846071@xx.xx.46.25' in 32000 ms (Method: OPTIONS) [Jan 14 09:00:19] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 14 09:00:21] DEBUG[5183] chan_sip.c: Auto destroying SIP dialog '2146075000@xx.xx.46.25' [Jan 14 09:00:21] DEBUG[5183] chan_sip.c: Destroying SIP dialog 2146075000@xx.xx.46.25 [Jan 14 09:00:21] VERBOSE[5183] chan_sip.c: Really destroying SIP dialog '2146075000@xx.xx.46.25' Method: OPTIONS [Jan 14 09:00:24] DEBUG[6547] res_rtp_asterisk.c: Got RTCP report of 64 bytes