From wang@basis-audionet.com Tue Mar  2 20:37:37 2010
From: Min Wang <wang@basis-audionet.com>
To: sr-dev@lists.kamailio.org
Subject:
 [sr-dev] How to contruct ACK/BYE correctly in dialog with NATed	client
Date: Tue, 02 Mar 2010 20:36:42 +0100
Message-ID:
 <04A856F26940EE42A7D6129D5073F24A022BDAE2@BASIS001152003.basis-audionet.de>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============2053345370=="

--===============2053345370==
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: 7bit

Hi

My issue is how to construct ACK correctly in the dialog in case of
NATed  client.  ( please see
http://lists.sip-router.org/pipermail/sr-dev/2010-February/006145.html
for the scenario detail )


nated-u1(bob)---> P1 --> nated-u2 (alice)


e.g:  bob calls alcie,

(A) In the normal case,

     U1 ---> P1 ---> U2
           Invite->
     <--200 OK
	     ACK -->	

The good ACK msg capted from P1 to U2 is:
#
U 67.154.255.47:4060 (P1) -> 67.154.250.3:2051 ( public ip/port for U2)
ACK sip:alice(a)172.16.8.42:2051;line=e96ci3a9 SIP/2.0.


(B) In the abormal case,

     U1 ---> P1 ---> U2
           Invite->
     	     ACK -->	
	     BYE -->
        <--488

P1 check something and need to send ACK/BYE to u2

The pseudo code try to use dialog module function: 

     dialog.request_inside(&method_ACK,&reqbuf,NULL, d,cb,cbp)

>From the log file:
DEBUG:tm:t_uac: next_hop=<sip:alice(a)centercall.net>


The captured ACK msg:

U 67.154.255.47:4060 (P1) -> 67.154.255.44:5060 (i-cscf)
ACK sip:alice(a)centercall.net SIP/2.0.


The two ACK msg is different. 


Questions:

(1) How can I generate the correct ACK msg in this case?

(2) The issue with second ACK need more explaination ( from openims
point of view):

i-cscf ---- s-cscf  
         |        
 U1 --> P1 --> U2

(i/s-cscf is sip proxy)

With this kind of ACK, the ACK first goes to i-cscf, which choose
s-cscf, then goes back to P1, P1 will try to relay the ACK

route[Term_Subsequent]{
   ...
	if (!P_security_relay())
	   P_NAT_relay();

	t_relay()
  ...
}

The log shows:

22106 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_funcs.c:184]: tm: put_on_wait: transaction 0xb59834b4 already on wait

It seems the tm module put this new ACK (the P1-generated ACK loop back
to P1 now )  on hold, NOT relaying to U2. 

>From sniffed packets, the ACK never reaches the U2.

Any good way to resolve the issue?


Just FYI the BYE can reach U2 as it is a new tm transaction.

#
U 67.154.255.47:4060 -> 67.154.255.44:5060
BYE sip:alice(a)centercall.net SIP/2.0.

22512 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_lookup.c:711]: DEBUG: t_lookup_request: no transaction found
22558 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_funcs.c:388]: SER: new transaction fwd'ed



/////////detailed log for ACK in Term_Subsequent ///////////////
21997 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[parser/msg_parser.c:627]: SIP Request:
21998 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[parser/msg_parser.c:629]:  method:  <ACK>
21999 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[parser/msg_parser.c:631]:  uri:     <sip:alice(a)172.16.8.42      

:2051;line=otkb9mdz>
22000 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[parser/msg_parser.c:633]:  version: <SIP/2.0>

22091 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: NOTICE: <script>: >>
Term_Subsequent before relay
22092 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:366]: qm_malloc(0x8272e60, 36) called from pcscf: 

registration.c: P_security_relay(1086)
22093 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:406]: qm_malloc(0x8272e60, 36) returns address 

0x82e2140 frag. 0x82e2128 (size=36) on 1 -th hit
22094 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: pcscf
[registration.c:1104]: ERR:P-CSCF:P_security_relay: we cannot find the 

contact or its IPSec/TLS SAs for <0://172.16.8.42:2051>.
22095 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:428]: qm_free(0x8272e60, 0x82e2140), called from pcscf: 

registration.c: P_security_relay(1107)
22096 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:450]: qm_free: freeing frag. 0x82e2128 alloc'ed from 

pcscf: registration.c: P_security_relay(1086)
22097 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:366]: qm_malloc(0x8272e60, 41) called from pcscf: 

registration.c: get_NAT_dst_uri(921)
22098 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[mem/q_malloc.c:406]: qm_malloc(0x8272e60, 44) returns address 

0x830605c frag. 0x8306044 (size=52) on 1 -th hit
22099 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: INFO: pcscf
[registration.c:1031]: INFO:P-CSCF:P_NAT_relay: <sip:67.154.250.3:2051>
22100 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_lookup.c:1387]: DEBUG: t_newtran: msg id=77 , global msg id=76 , T on


entrance=0xffffffff
22101 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_lookup.c:528]: t_lookup_request: start searching: hash=37128, isACK=1
22102 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_lookup.c:470]: DEBUG: RFC3261 transaction matched,
tid=8019.82c67232.0
22103 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_lookup.c:728]: DEBUG: t_lookup_request: transaction found (T
=0xb59834b4)
22104 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_reply.c:1420]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
22105 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: <core>
[timer.c:595]: timer_add called on an active timer 0xb59834fc 

(0xb5842c2c, 0xb5842c2c), flags 201
22106 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: DEBUG: tm
[t_funcs.c:184]: tm: put_on_wait: transaction 0xb59834b4 already on wait
 Mar  2 11:06:25 im1 /usr/sbin/ser[27551]: NOTICE: <script>: >>
Term_Subsequent end





Kind Regards
 
Min Wang









.










--===============2053345370==--