<--- SIP read from UDP:xx.xx91.45:5060 ---> INVITE sip:1000101@xx.xx91.45:5070;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK31ba.8f3b7a31.0 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK753855570 From: ;tag=1219354547 To: Call-ID: 1397077645 CSeq: 21 INVITE Contact: Proxy-Authorization: Digest username="1000103", realm="xx.xx91.45", nonce="URBhS1EQYB+KVAQO/pn8kwmiB9FM16DC", uri="sip:1000101@xx.xx91.45", response="b62741cee21e91f71f6c2ec9fc702bd2", algorithm=MD5 Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 69 User-Agent: Linphone/3.3.2 (eXosip2/3.3.0) Subject: Phone call Content-Length: 203 X-product-RURI: sip:1000101@xx.xx91.45 X-product-Source: yy.yy.21.197:5061 v=0 o=1000103 123456 654321 IN IP4 192.168.1.40 s=A conversation c=IN IP4 192.168.1.40 t=0 0 m=audio 7078 RTP/AVP 3 101 a=rtpmap:3 GSM/8000/1 a=rtpmap:101 telephone-event/8000/1 a=fmtp:101 0-11 <-------------> --- (18 headers 9 lines) --- [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 1397077645 - INVITE (No RTP) Sending to xx.xx91.45:5060 (NAT) [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:22486 handle_request_invite: Initializing initreq for method INVITE - callid 1397077645 Using INVITE request as basis request - 1397077645 [Feb 5 12:28:23] DEBUG[2306]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Feb 5 12:28:23] DEBUG[2306]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000103' AND host = 'dynamic' [Feb 5 12:28:23] DEBUG[2306]: res_config_mysql.c:1626 mysql_reconnect: MySQL RealTime: Connection okay. [Feb 5 12:28:23] DEBUG[2306]: res_config_mysql.c:381 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sippeers WHERE name = '1000103' Found peer 'product-local' for '1000103' from xx.xx91.45:5060 [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x8ad7430' [Feb 5 12:28:23] DEBUG[2306]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 16978 for RTP instance '0x8ad7430' [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0x8ad7430' is setup and ready to go [Feb 5 12:28:23] DEBUG[2306]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0x8ad7430' == Using SIP RTP CoS mark 5 [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to On Found RTP audio format 3 [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x40d77440 Found RTP audio format 101 [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x40d77440 Found audio description format GSM for ID 3 Found audio description format telephone-event for ID 101 [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 3 on 0x40d77440 [Feb 5 12:28:23] DEBUG[2306]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x40d77440 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0x2 (gsm)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 5 12:28:23] DEBUG[2306]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8ad7430' Peer audio RTP is at port 192.168.1.40:7078 [Feb 5 12:28:23] DEBUG[2306]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x8ad7430' [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:22623 handle_request_invite: Checking SIP call limits for device Looking for 1000101 in from-internal (domain xx.xx91.45) [Feb 5 12:28:23] DEBUG[2306]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Feb 5 12:28:23] DEBUG[2306]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 list_route: hop: <--- Transmitting (NAT) to xx.xx91.45:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK31ba.8f3b7a31.0;received=xx.xx91.45;rport=5060 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK753855570 Record-Route: From: ;tag=1219354547 To: Call-ID: 1397077645 CSeq: 21 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Feb 5 12:28:23] DEBUG[16152]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [1000101@from-internal:1] AGI("SIP/product-local-0000033c", "call_phone.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/call_phone.agi AGI Tx >> agi_request: call_phone.agi AGI Tx >> agi_channel: SIP/product-local-0000033c AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1360027703.1763 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: unknown AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 1000101 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: from-internal AGI Tx >> agi_extension: 1000101 AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1096301456 AGI Tx >> AGI Rx << EXEC Dial "SIP/1000101@xx.xx91.45/n,20,ortM(test-answered)" -- AGI Script Executing Application: (Dial) Options: (SIP/1000101@xx.xx91.45/n,20,ortM(test-answered)) [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:26465 sip_request_call: Asked to create a SIP channel with formats: 0x2 (gsm) [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 5a1d8f7311e4a1c43ad92f95355c876f@xx.xx91.45:5070 - INVITE (No RTP) [Feb 5 12:28:23] NOTICE[16152]: chan_sip.c:26547 sip_request_call: Conflicting extension values given. Using '1000101' and not 'n' [Feb 5 12:28:23] DEBUG[16152]: rtp_engine.c:346 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x89ef868' [Feb 5 12:28:23] DEBUG[16152]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 15162 for RTP instance '0x89ef868' [Feb 5 12:28:23] DEBUG[16152]: rtp_engine.c:355 ast_rtp_instance_new: RTP instance '0x89ef868' is setup and ready to go [Feb 5 12:28:23] DEBUG[16152]: res_rtp_asterisk.c:2516 ast_rtp_prop_set: Setup RTCP on RTP instance '0x89ef868' == Using SIP RTP CoS mark 5 [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:5092 do_setnat: Setting NAT on RTP to On [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:3144 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 5 12:28:23] DEBUG[16152]: dsp.c:471 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Feb 5 12:28:23] DEBUG[16152]: dsp.c:471 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 5 12:28:23] DEBUG[16152]: channel.c:6146 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:5637 sip_call: Outgoing Call for 1000101 [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:11344 add_sdp: ** Our capability: 0x1cee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|ilbc|g722) Video flag: False Text flag: False [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x2 (gsm) Audio is at 15162 Adding codec 0x2 (gsm) to SDP Adding codec 0x1000 (g722) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding codec 0x40 (slin) to SDP Adding codec 0x800 (g726) to SDP Adding codec 0x20 (adpcm) to SDP Adding codec 0x80 (lpc10) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 5 12:28:23] DEBUG[16152]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method INVITE - callid 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 Reliably Transmitting (NAT) to xx.xx91.45:5060: INVITE sip:1000101@xx.xx91.45 SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK1c938201;rport Max-Forwards: 70 From: "1000103" ;tag=as070f809c To: Contact: Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 CSeq: 102 INVITE User-Agent: product Date: Tue, 05 Feb 2013 01:28:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 454 v=0 o=root 1284083942 1284083942 IN IP4 xx.xx91.45 s=Asterisk PBX 1.8.12.0 c=IN IP4 xx.xx91.45 t=0 0 m=audio 15162 RTP/AVP 3 9 0 8 10 111 5 7 97 101 a=rtpmap:3 GSM/8000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:10 L16/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:7 LPC/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- -- Called SIP/1000101@xx.xx91.45/n <--- Transmitting (NAT) to xx.xx91.45:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK31ba.8f3b7a31.0;received=xx.xx91.45;rport=5060 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK753855570 Record-Route: From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 21 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> <--- SIP read from UDP:xx.xx91.45:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK1c938201;rport=5070 From: "1000103" ;tag=as070f809c To: Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 CSeq: 102 INVITE Server: product SIP proxy Content-Length: 0 <-------------> --- (8 headers 0 lines) --- [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' Request 102: Found <--- SIP read from UDP:xx.xx91.45:52963 ---> OPTIONS sip:xx.xx91.45:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45:51703;branch=z9hG4bK.5c16ab7a;rport;alias From: sip:sipsak@xx.xx91.45:51703;tag=17be939f To: sip:xx.xx91.45:5070 Call-ID: 398365599@xx.xx91.45 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx91.45:51703 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> --- (11 headers 0 lines) --- [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 398365599@xx.xx91.45 - OPTIONS (No RTP) Looking for s in from-external (domain xx.xx91.45) <--- Transmitting (NAT) to xx.xx91.45:52963 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP xx.xx91.45:51703;branch=z9hG4bK.5c16ab7a;alias;received=xx.xx91.45;rport=52963 From: sip:sipsak@xx.xx91.45:51703;tag=17be939f To: sip:xx.xx91.45:5070;tag=as60d78a59 Call-ID: 398365599@xx.xx91.45 CSeq: 1 OPTIONS Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '398365599@xx.xx91.45' in 32000 ms (Method: OPTIONS) <--- SIP read from UDP:xx.xx91.45:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK1c938201;rport=5070 From: "1000103" ;tag=as070f809c To: ;tag=00170ec855f5014757ea47c8-28e15be4 Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 Date: Tue, 05 Feb 2013 01:28:44 GMT CSeq: 102 INVITE Server: Cisco-CP7960G/8.0 Contact: Record-Route: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes Content-Length: 0 <-------------> --- (13 headers 0 lines) --- [Feb 5 12:28:23] DEBUG[2306]: chan_sip.c:4070 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' Request 102: Found list_route: hop: -- SIP/xx.xx91.45-0000033d is ringing <--- Transmitting (NAT) to xx.xx91.45:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK31ba.8f3b7a31.0;received=xx.xx91.45;rport=5060 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK753855570 Record-Route: From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 21 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> <--- SIP read from UDP:xx.xx91.45:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK1c938201;rport=5070 From: "1000103" ;tag=as070f809c To: ;tag=00170ec855f5014757ea47c8-28e15be4 Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 Date: Tue, 05 Feb 2013 01:28:45 GMT CSeq: 102 INVITE Server: Cisco-CP7960G/8.0 Contact: Record-Route: Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE Remote-Party-ID: "1000101" ;party=called;id-type=subscriber;privacy=off;screen=yes Supported: replaces,join,norefersub Content-Length: 209 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 19676 0 IN IP4 yy.yy.21.197 s=SIP Call t=0 0 m=audio 18366 RTP/AVP 8 101 c=IN IP4 yy.yy.21.197 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> --- (16 headers 10 lines) --- [Feb 5 12:28:25] DEBUG[2306]: chan_sip.c:3991 __sip_ack: Acked pending invite 102 [Feb 5 12:28:25] DEBUG[2306]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' of Request 102: Match Found Found RTP audio format 8 [Feb 5 12:28:25] DEBUG[2306]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x40d77110 Found RTP audio format 101 [Feb 5 12:28:25] DEBUG[2306]: rtp_engine.c:537 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x40d77110 Found audio description format PCMA for ID 8 Found audio description format telephone-event for ID 101 [Feb 5 12:28:25] DEBUG[2306]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x40d77110 Feb 5 12:28:25] DEBUG[2306]: rtp_engine.c:640 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x40d77110 Capabilities: us - 0x1eee (gsm|ulaw|alaw|g726|adpcm|slin|lpc10|speex|ilbc|g722), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 5 12:28:25] DEBUG[2306]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x89ef868' Peer audio RTP is at port yy.yy.21.197:18366 [Feb 5 12:28:25] DEBUG[2306]: res_rtp_asterisk.c:2482 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x89ef868' [Feb 5 12:28:25] DEBUG[2306]: chan_sip.c:9366 process_sdp: Oooh, we need to change our audio formats since our peer supports only 0x8 (alaw) and not 0x2 (gsm) [Feb 5 12:28:25] DEBUG[2306]: channel.c:5171 set_format: Set channel SIP/xx.xx91.45-0000033d to read format gsm [Feb 5 12:28:25] DEBUG[2306]: channel.c:5171 set_format: Set channel SIP/xx.xx91.45-0000033d to write format gsm list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to xx.xx91.45:5060 Transmitting (NAT) to xx.xx91.45:5060: ACK sip:1000101@yy.yy.21.197:5065;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK71dfb028;rport Route: Max-Forwards: 70 From: "1000103" ;tag=as070f809c To: ;tag=00170ec855f5014757ea47c8-28e15be4 Contact: Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 CSeq: 102 ACK User-Agent: product Content-Length: 0 --- -- SIP/xx.xx91.45-0000033d answered SIP/product-local-0000033c [Feb 5 12:28:25] DEBUG[16152]: pbx.c:4230 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-test-answered:1] AGI("SIP/xx.xx91.45-0000033d", "test_fork.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/test_fork.agi AGI Tx >> agi_request: test_fork.agi AGI Tx >> agi_channel: SIP/xx.xx91.45-0000033d AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1360027703.1764 AGI Tx >> agi_version: 1.8.12.0 AGI Tx >> agi_callerid: 1000103 AGI Tx >> agi_calleridname: unknown AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: unknown AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: macro-test-answered AGI Tx >> agi_extension: s AGI Tx >> agi_priority: 1 AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: AGI Tx >> agi_threadid: 1096301456 AGI Tx >> Really destroying SIP dialog '1539287818@xx.xx91.45' Method: OPTIONS <--- SIP read from UDP:xx.xx91.45:35468 ---> OPTIONS sip:xx.xx91.45:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45:39599;branch=z9hG4bK.6f71ccce;rport;alias From: sip:sipsak@xx.xx91.45:39599;tag=250ec72 To: sip:xx.xx91.45:5070 Call-ID: 38857842@xx.xx91.45 CSeq: 1 OPTIONS Contact: sip:sipsak@xx.xx91.45:39599 Content-Length: 0 Max-Forwards: 70 User-Agent: sipsak 0.9.6 Accept: text/plain <-------------> --- (11 headers 0 lines) --- [Feb 5 12:28:34] DEBUG[2306]: chan_sip.c:7769 sip_alloc: Allocating new SIP dialog for 38857842@xx.xx91.45 - OPTIONS (No RTP) Looking for s in from-external (domain xx.xx91.45) <--- Transmitting (NAT) to xx.xx91.45:35468 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP xx.xx91.45:39599;branch=z9hG4bK.6f71ccce;alias;received=xx.xx91.45;rport=35468 From: sip:sipsak@xx.xx91.45:39599;tag=250ec72 To: sip:xx.xx91.45:5070;tag=as17368ed2 Call-ID: 38857842@xx.xx91.45 CSeq: 1 OPTIONS Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '38857842@xx.xx91.45' in 32000 ms (Method: OPTIONS) -- AGI Script test_fork.agi completed, returning 0 [Feb 5 12:28:35] DEBUG[16152]: app_macro.c:435 _macro_exec: Executed application: AGI [Feb 5 12:28:35] DEBUG[16152]: app_dial.c:2654 dial_exec_full: Macro exited with status 0 [Feb 5 12:28:35] DEBUG[16152]: chan_sip.c:6474 sip_answer: SIP answering channel: SIP/product-local-0000033c [Feb 5 12:28:35] DEBUG[16152]: chan_sip.c:11745 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 5 12:28:35] DEBUG[16152]: chan_sip.c:11344 add_sdp: ** Our capability: 0x2 (gsm) Video flag: True Text flag: True [Feb 5 12:28:35] DEBUG[16152]: chan_sip.c:11345 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 16978 Adding codec 0x2 (gsm) to SDP Adding non-codec 0x1 (telephone-event) to SDP <--- Reliably Transmitting (NAT) to xx.xx91.45:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK31ba.8f3b7a31.0;received=xx.xx91.45;rport=5060 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK753855570 Record-Route: From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 21 INVITE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 232 v=0 o=root 195395003 195395003 IN IP4 xx.xx91.45 s=Asterisk PBX 1.8.12.0 c=IN IP4 xx.xx91.45 t=0 0 m=audio 16978 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Feb 5 12:28:35] DEBUG[16152]: features.c:3809 clear_dialed_interfaces: Removing dialed interfaces datastore on SIP/xx.xx91.45-0000033d since we're bridging [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to gsm [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: gsm ms: 20 len: 33 [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:1253 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x8ad7430' <--- SIP read from UDP:xx.xx91.45:5060 ---> ACK sip:1000101@xx.xx91.45:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bKcydzigwkX Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK1920909370 From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 21 ACK Contact: Proxy-Authorization: Digest username="1000103", realm="xx.xx91.45", nonce="URBhS1EQYB+KVAQO/pn8kwmiB9FM16DC", uri="sip:1000101@xx.xx91.45", response="b62741cee21e91f71f6c2ec9fc702bd2", algorithm=MD5 Max-Forwards: 69 User-Agent: Linphone/3.3.2 (eXosip2/3.3.0) Content-Length: 0 X-product-RURI: sip:1000101@xx.xx91.45:5070 X-product-Source: yy.yy.21.197:5061 <-------------> --- (14 headers 0 lines) --- [Feb 5 12:28:35] DEBUG[2306]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '1397077645' of Response 21: Match Found Really destroying SIP dialog '1951529606@xx.xx91.45' Method: OPTIONS [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8ad7430' [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:2212 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address yy.yy.21.197:7078 [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:1357 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 5 12:28:35] DEBUG[16152]: res_rtp_asterisk.c:1388 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160 [Feb 5 12:28:40] DEBUG[16152]: res_rtp_asterisk.c:1791 ast_rtcp_read: Got RTCP report of 140 bytes Really destroying SIP dialog '1831159652@xx.xx91.45' Method: OPTIONS <--- SIP read from UDP:xx.xx91.45:5060 ---> BYE sip:1000101@xx.xx91.45:5070 SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK01ba.0fcd3b71.0 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK986902640 From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 22 BYE Contact: Max-Forwards: 69 User-Agent: Linphone/3.3.2 (eXosip2/3.3.0) Content-Length: 0 X-product-RURI: sip:1000101@xx.xx91.45:5070 X-product-Source: yy.yy.21.197:5061 <-------------> --- (13 headers 0 lines) --- [Feb 5 12:28:46] DEBUG[2306]: chan_sip.c:23795 handle_request_bye: Initializing initreq for method BYE - callid 1397077645 Sending to xx.xx91.45:5060 (NAT) [Feb 5 12:28:46] DEBUG[2306]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8ad7430' Scheduling destruction of SIP dialog '1397077645' in 32000 ms (Method: BYE) <--- Transmitting (NAT) to xx.xx91.45:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx91.45;branch=z9hG4bK01ba.0fcd3b71.0;received=xx.xx91.45;rport=5060 Via: SIP/2.0/UDP 192.168.1.40:5061;received=yy.yy.21.197;rport=5061;branch=z9hG4bK986902640 From: ;tag=1219354547 To: ;tag=as709f065d Call-ID: 1397077645 CSeq: 22 BYE Server: product Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Feb 5 12:28:46] DEBUG[16152]: channel.c:7093 ast_generic_bridge: Didn't get a frame from channel: SIP/product-local-0000033c [Feb 5 12:28:46] DEBUG[16152]: channel.c:7552 ast_channel_bridge: Bridge stops bridging channels SIP/product-local-0000033c and SIP/xx.xx91.45-0000033d [Feb 5 12:28:46] DEBUG[16152]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/xx.xx91.45-0000033d' [Feb 5 12:28:46] DEBUG[16152]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Feb 5 12:28:46] DEBUG[16152]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x89ef868' Scheduling destruction of SIP dialog '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' in 32000 ms (Method: INVITE) set_destination: Parsing for address/port to send to set_destination: set destination to xx.xx91.45:5060 Reliably Transmitting (NAT) to xx.xx91.45:5060: BYE sip:1000101@yy.yy.21.197:5065;transport=udp SIP/2.0 Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK167a84af;rport Route: Max-Forwards: 70 From: "1000103" ;tag=as070f809c To: ;tag=00170ec855f5014757ea47c8-28e15be4 Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 CSeq: 103 BYE User-Agent: product X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Feb 5 12:28:46] DEBUG[16152]: app_dial.c:2960 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Feb 5 12:28:46] DEBUG[16152]: res_agi.c:3507 run_agi: SIP/product-local-0000033c hungup -- AGI Script call_phone.agi completed, returning 4 [Feb 5 12:28:46] DEBUG[16152]: pbx.c:5047 __ast_pbx_run: Spawn extension (from-internal,1000101,1) exited non-zero on 'SIP/product-local-0000033c' == Spawn extension (from-internal, 1000101, 1) exited non-zero on 'SIP/product-local-0000033c' [Feb 5 12:28:46] DEBUG[16152]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/product-local-0000033c' [Feb 5 12:28:46] DEBUG[16152]: channel.c:2831 ast_hangup: Hanging up channel 'SIP/product-local-0000033c' [Feb 5 12:28:46] DEBUG[16152]: chan_sip.c:6271 sip_hangup: Hanging up zombie call. Be scared. [Feb 5 12:28:46] DEBUG[16152]: res_rtp_asterisk.c:2556 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x8ad7430' <--- SIP read from UDP:xx.xx91.45:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP xx.xx91.45:5070;branch=z9hG4bK167a84af;rport=5070 From: "1000103" ;tag=as070f809c To: ;tag=00170ec855f5014757ea47c8-28e15be4 Call-ID: 6aaa29c171a163e35d4814881d5caf19@xx.xx91.45 Date: Tue, 05 Feb 2013 01:29:06 GMT CSeq: 103 BYE Server: Cisco-CP7960G/8.0 Content-Length: 0 RTP-RxStat: Dur=??,Pkt=??,Oct=??,LatePkt=??,LostPkt=??,AvgJit=?? RTP-TxStat: Dur=??,Pkt=??,Oct=?? <-------------> --- (11 headers 0 lines) --- [Feb 5 12:28:46] DEBUG[2306]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' of Request 103: Match Found Really destroying SIP dialog '6aaa29c171a163e35d4814881d5caf19@xx.xx91.45' Method: INVITE [Feb 5 12:28:46] DEBUG[2306]: rtp_engine.c:294 instance_destructor: Destroyed RTP instance '0x89ef868'