//// Twinkle (200) calls to extension 51 of Asterisk. //// pedantic = yes [Nov 19 21:19:45] VERBOSE[12348] logger.c: <--- SIP read from 85.58.121.104:53546 ---> INVITE sip:51@80.95.0.111 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.129;rport;branch=z9hG4bKkxxatffy Max-Forwards: 70 To: From: "200" ;tag=dfryb Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 998 INVITE Contact: Content-Type: application/sdp Authorization: Digest username="200",realm="asterisk",nonce="0a8371d3",uri="sip:51@80.95.0.111",response="6b4ad88ce8cb545b6f3c530f4d7d3637",algorithm=MD5 Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO,MESSAGE Supported: replaces,norefersub,100rel User-Agent: Twinkle/1.1 Content-Length: 306 v=0 o=200 1373033016 248966847 IN IP4 192.168.0.129 s=- c=IN IP4 192.168.0.129 t=0 0 m=audio 8000 RTP/AVP 98 97 8 0 3 101 a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 <-------------> [Nov 19 21:19:45] VERBOSE[12348] logger.c: --- (14 headers 14 lines) --- [Nov 19 21:19:45] VERBOSE[12348] logger.c: Sending to 85.58.121.104 : 53546 (NAT) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Initializing initreq for method INVITE - callid glkonjpqbrtqvgd@192.168.0.129 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Using INVITE request as basis request - glkonjpqbrtqvgd@192.168.0.129 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found user '200' for '200' [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Setting NAT on RTP to On [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 98 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 97 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 8 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 0 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 3 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found RTP audio format 101 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Peer audio RTP is at port 192.168.0.129:8000 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format speex for ID 98 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format speex for ID 97 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format PCMA for ID 8 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format PCMU for ID 0 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format GSM for ID 3 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Found description format telephone-event for ID 101 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Got unsupported a:fmtp in SDP offer [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: T38 state changed to 0 on channel [Nov 19 21:19:45] VERBOSE[12348] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x20e (gsm|ulaw|alaw|speex)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) [Nov 19 21:19:45] VERBOSE[12348] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 19 21:19:45] VERBOSE[12348] logger.c: Peer audio RTP is at port 192.168.0.129:8000 [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Checking SIP call limits for device 200 [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Updating call counter for incoming call [Nov 19 21:19:45] VERBOSE[12348] logger.c: Looking for 51 in desde-usuarios (domain 80.95.0.111) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: This channel will not be able to handle video. [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: build_route: Contact hop: [Nov 19 21:19:45] VERBOSE[12348] logger.c: list_route: hop: [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: SIP/200-0823ef78: New call is still down.... Trying... [Nov 19 21:19:45] VERBOSE[12348] logger.c: <--- Transmitting (NAT) to 85.58.121.104:53546 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.129;branch=z9hG4bKkxxatffy;received=85.58.121.104;rport=53546 From: "200" ;tag=dfryb To: Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 998 INVITE User-Agent: Asterisk SVN trunk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Nov 19 21:19:45] DEBUG[12348] devicestate.c: Notification of state change to be queued on device/channel SIP/200-0823ef78 [Nov 19 21:19:45] DEBUG[12348] pbx.c: Launching 'Answer' [Nov 19 21:19:45] VERBOSE[12348] logger.c: -- Executing [51@desde-usuarios:1] Answer("SIP/200-0823ef78", "") in new stack [Nov 19 21:19:45] DEBUG[12348] devicestate.c: Notification of state change to be queued on device/channel SIP/200-0823ef78 [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: SIP answering channel: SIP/200-0823ef78 [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Setting framing from config on incoming call [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Text flag: True [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 19 21:19:45] VERBOSE[12348] logger.c: Audio is at 80.95.0.111 port 10540 [Nov 19 21:19:45] VERBOSE[12348] logger.c: Adding codec 0x2 (gsm) to SDP [Nov 19 21:19:45] VERBOSE[12348] logger.c: Adding codec 0x4 (ulaw) to SDP [Nov 19 21:19:45] VERBOSE[12348] logger.c: Adding codec 0x8 (alaw) to SDP [Nov 19 21:19:45] VERBOSE[12348] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: -- Done with adding codecs to SDP [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Nov 19 21:19:45] VERBOSE[12348] logger.c: <--- Reliably Transmitting (NAT) to 85.58.121.104:53546 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.129;branch=z9hG4bKkxxatffy;received=85.58.121.104;rport=53546 From: "200" ;tag=dfryb To: ;tag=as246d5c38 Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 998 INVITE User-Agent: Asterisk SVN trunk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 315 v=0 o=root 775617347 775617347 IN IP4 80.95.0.111 s=Asterisk PBX SVN-trunk-r89407 c=IN IP4 80.95.0.111 t=0 0 m=audio 10540 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 19 21:19:45] DEBUG[12348] pbx.c: Launching 'Echo' [Nov 19 21:19:45] VERBOSE[12348] logger.c: -- Executing [51@desde-usuarios:2] Echo("SIP/200-0823ef78", "") in new stack [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Checking device state for peer 200 [Nov 19 21:19:45] DEBUG[12348] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Nov 19 21:19:45] DEBUG[12348] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Checking device state for peer 200 [Nov 19 21:19:45] DEBUG[12348] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Nov 19 21:19:45] DEBUG[12348] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 19 21:19:45] VERBOSE[12348] logger.c: <--- SIP read from 85.58.121.104:53546 ---> ACK sip:51@80.95.0.111 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.129;rport;branch=z9hG4bKmwzoowib Max-Forwards: 70 To: ;tag=as246d5c38 From: "200" ;tag=dfryb Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 998 ACK Authorization: Digest username="200",realm="asterisk",nonce="0a8371d3",uri="sip:51@80.95.0.111",response="6b4ad88ce8cb545b6f3c530f4d7d3637",algorithm=MD5 User-Agent: Twinkle/1.1 Content-Length: 0 <-------------> [Nov 19 21:19:45] VERBOSE[12348] logger.c: --- (10 headers 0 lines) --- [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Stopping retransmission on 'glkonjpqbrtqvgd@192.168.0.129' of Response 998: Match Found [Nov 19 21:19:45] DEBUG[12348] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 85.58.121.104:53547 [Nov 19 21:19:45] DEBUG[12348] rtp.c: Got RTCP report of 40 bytes [Nov 19 21:19:45] DEBUG[12348] rtp.c: RTP NAT: Got audio from other end. Now sending to address 85.58.121.104:53548 [Nov 19 21:19:45] DEBUG[12348] chan_sip.c: Oooh, format changed to 2 [Nov 19 21:19:45] DEBUG[12348] channel.c: Set channel SIP/200-0823ef78 to read format ulaw [Nov 19 21:19:45] DEBUG[12348] channel.c: Set channel SIP/200-0823ef78 to write format ulaw [Nov 19 21:19:45] DEBUG[12348] rtp.c: Ooh, format changed from unknown to gsm [Nov 19 21:19:45] DEBUG[12348] rtp.c: Created smoother: format: 2 ms: 20 len: 33 [Nov 19 21:19:49] DEBUG[12348] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 85.58.121.104:53547 [Nov 19 21:19:49] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:19:55] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:01] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:06] DEBUG[12348] rtp.c: Difference is 1160, ms is 165 [Nov 19 21:20:06] DEBUG[12348] rtp.c: Difference is 1000, ms is 145 [Nov 19 21:20:08] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:15] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:19] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:26] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes //// With a small Ruby code I send an in-dialog OPTIONS (with same RURI as in the received "Contact", same Call-ID and From/To tags. //// Asterisk replies a 200 OK. [Nov 19 21:20:30] VERBOSE[12348] logger.c: <--- SIP read from 85.58.121.104:53500 ---> OPTIONS sip:51@80.95.0.111 SIP/2.0 Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bKnwdpbn User-Agent: Ruby SIP client From: ;tag=dfryb Call-ID: glkonjpqbrtqvgd@192.168.0.129 To: ;tag=as246d5c38 Max-Forwards: 70 CSeq: 1000 OPTIONS Content-Length: 0 <-------------> [Nov 19 21:20:30] VERBOSE[12348] logger.c: --- (9 headers 0 lines) --- [Nov 19 21:20:30] VERBOSE[12348] logger.c: Looking for 51 in desde-usuarios (domain 80.95.0.111) [Nov 19 21:20:30] VERBOSE[12348] logger.c: <--- Transmitting (NAT) to 85.58.121.104:53500 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bKnwdpbn;received=85.58.121.104 From: ;tag=dfryb To: ;tag=as246d5c38 Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 1000 OPTIONS User-Agent: Asterisk SVN trunk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Nov 19 21:20:32] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:36] DEBUG[12348] rtp.c: Difference is 1064, ms is 153 [Nov 19 21:20:36] DEBUG[12348] rtp.c: Difference is 1064, ms is 153 [Nov 19 21:20:39] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes //// Now I change the "Call-ID" and send the in-dialog OPTIONS. //// Asterisk replies a 481 Call/Transaction Does Not Exist. //// I like this answer. Because it's an in-dialog request Asterisk replies 481 since that diaglo doesn't exist. //// But... why it just can reply200 or 481 if the UAC sending the in-dialog OPTIONS can call to the URI/extension indicated in Asterisk's "Contact" header? it has no sense. [Nov 19 21:20:42] VERBOSE[12348] logger.c: <--- SIP read from 85.58.121.104:53500 ---> OPTIONS sip:51@80.95.0.111 SIP/2.0 Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bK8paymq User-Agent: Ruby SIP client From: ;tag=dfryb Call-ID: -------------------------glkonjpqbrtqvgd@192.168.0.129 To: ;tag=as246d5c38 Max-Forwards: 70 CSeq: 1000 OPTIONS Content-Length: 0 <-------------> [Nov 19 21:20:42] VERBOSE[12348] logger.c: --- (9 headers 0 lines) --- [Nov 19 21:20:42] DEBUG[12348] acl.c: Found IP address for this socket [Nov 19 21:20:42] DEBUG[12348] chan_sip.c: Allocating new SIP dialog for -------------------------glkonjpqbrtqvgd@192.168.0.129 - OPTIONS (No RTP) [Nov 19 21:20:42] VERBOSE[12348] logger.c: <--- Transmitting (no NAT) to 85.58.121.104:53500 ---> SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bK8paymq;received=85.58.121.104 From: ;tag=dfryb To: ;tag=as246d5c38 Call-ID: -------------------------glkonjpqbrtqvgd@192.168.0.129 CSeq: 1000 OPTIONS User-Agent: Asterisk SVN trunk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Nov 19 21:20:42] VERBOSE[12348] logger.c: Scheduling destruction of SIP dialog '-------------------------glkonjpqbrtqvgd@192.168.0.129' in 32000 ms (Method: OPTIONS) [Nov 19 21:20:43] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes [Nov 19 21:20:49] DEBUG[12348] rtp.c: Got RTCP report of 108 bytes //// Same now but changing the From tag (in pedantic=no this is no matched). [Nov 19 21:20:53] VERBOSE[12348] logger.c: <--- SIP read from 85.58.121.104:53500 ---> OPTIONS sip:51@80.95.0.111 SIP/2.0 Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bKn28w13 User-Agent: Ruby SIP client From: ;tag=-------------------dfryb Call-ID: glkonjpqbrtqvgd@192.168.0.129 To: ;tag=as246d5c38 Max-Forwards: 70 CSeq: 1000 OPTIONS Content-Length: 0 <-------------> [Nov 19 21:20:53] VERBOSE[12348] logger.c: --- (9 headers 0 lines) --- [Nov 19 21:20:53] DEBUG[12348] acl.c: Found IP address for this socket [Nov 19 21:20:53] DEBUG[12348] chan_sip.c: Allocating new SIP dialog for glkonjpqbrtqvgd@192.168.0.129 - OPTIONS (No RTP) [Nov 19 21:20:53] VERBOSE[12348] logger.c: <--- Transmitting (no NAT) to 85.58.121.104:53500 ---> SIP/2.0 481 Call/Transaction Does Not Exist Via: SIP/2.0/TCP 127.0.0.1:15060;branch=z9hG4bKn28w13;received=85.58.121.104 From: ;tag=-------------------dfryb To: ;tag=as246d5c38 Call-ID: glkonjpqbrtqvgd@192.168.0.129 CSeq: 1000 OPTIONS User-Agent: Asterisk SVN trunk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0