From kbdfck@gmail.com Thu Apr 16 19:23:42 2015
From: Dmitry Sytchev <kbdfck@gmail.com>
To: sr-users@lists.kamailio.org
Subject: [SR-Users] Kamailio relays ACK of 200 OK to itself
Date: Thu, 16 Apr 2015 20:23:36 +0300
Message-ID:
 <CA+GmxbaXxLbWBhq0_Y2EHYvF5oHqRbyYKDcsesFNFbB41iBqmQ@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============1473706591=="

--===============1473706591==
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable

Hi all!

I can't make my Kamailio to correctly relay stateful   ACKs for 200
OK. It takes URI from Route: header and trying relay it to itself
instead of sending it to host sent 200 OK.
I don't understand why it can't match transaction and relay to correct host.

Seems BYEs aren't relayed correctly either...

192.168.4.218 -> NAT 1.2.2.94 -> Kamailo (1.2.3.46, 1.2.2.219) -> 172.19.126.=
105

192.168.4.218 sends INVITE to 1.2.3.45 which relays it to 172.19.126.105.

After 172.19.126.105 answers with 200 OK, it never gets ACK for it
back. Instead, ACK relayed by proxy to 1.2.3.46 (one of proxy
addresses).

Example of original ACK:
ACK sip:89211234567(a)172.19.126.105:5060 SIP/2.0.
Via: SIP/2.0/UDP 192.168.4.218:5062;branch=3Dz9hG4bK1161188624.
Route: <sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes>.
From: "0099977" <sip:0099977(a)1.2.3.46>;tag=3D259196205.
To: <sip:89211234567(a)1.2.3.46>;tag=3Das6bfd1fa1.
Call-ID: 910089142(a)192.168.4.218.
CSeq: 2 ACK.
Contact: <sip:0099977(a)192.168.4.218:5062>.
Max-Forwards: 70.
User-Agent: Yealink SIP-T46G 28.71.14.4.
Content-Length: 0.

It sees that host is not local: check_self: host !=3D me
I think the problem is somewhere in my NAT handling script code, but
seems I'm stuck and can't get what am I doing wrong, so I'll greatly
appreciate any help.

Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq
<CSeq>: <2> <ACK>
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: maxfwd
[mf_funcs.c:85]: is_maxfwd_present(): value =3D 70
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body :
content_length=3D0
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[parser/msg_parser.c:106]: get_hdr_field(): found end of header
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: sanity
[mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: INFO: <script>:
Nat detected
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: siputils
[sipops.c:161]: w_is_first_hop(): no 2nd via found - first hop
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: INFO: <script>:
Set contact alias
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[dset.c:774]: uri_add_rcv_alias(): encoded
<sip:0099977(a)192.168.4.218:5062> =3D>
[sip:0099977(a)192.168.4.218:5062;alias
=3D1.2.2.94~58542~1]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: INFO: <script>:
Request in dialog
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: rr
[loose.c:90]: is_preloaded(): is_preloaded: No
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D9 && [172.19.126.105] =3D=3D [127.0.0.
1]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D12 && [172.19.126.105] =3D=3D [1.2.
2.219]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D11 && [172.19.126.105] =3D=3D [1.2.
3.46]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D9 && [172.19.126.105] =3D=3D [127.0.0.
1]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D12 && [172.19.126.105] =3D=3D [1.2.
2.219]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 14=3D=3D11 && [172.19.126.105] =3D=3D [1.2.
3.46]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[forward.c:448]: check_self(): check_self: host !=3D me
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: rr
[loose.c:674]: after_strict(): Next hop:
'sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes' is loose router
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: rr
[loose.c:724]: after_strict(): The last route URI:
'sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes'
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: outbound
[ob_mod.c:496]: use_outbound(): Analysing ACK for outbound markers
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 11=3D=3D9 && [1.2.3.46] =3D=3D [127.0.0.1]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 11=3D=3D12 && [1.2.3.46] =3D=3D [1.2.2.2
19]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if
host=3D=3Dus: 11=3D=3D11 && [1.2.3.46] =3D=3D [1.2.3.4
6]
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if
port 5060 (advertise 0) matches port 5060
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: outbound
[ob_mod.c:466]: use_outbound_non_reg(): outbound not used
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: NOTICE:
<script>: REL: ACK sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes ->
sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: tm
[t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=3D59 , global
msg id=3D58 , T on entrance=3D0xffffffff
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: tm
[t_lookup.c:527]: t_lookup_request(): t_lookup_request: start
searching: hash=3D37956, isACK=3D1
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: tm
[t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching
failed
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: tm
[t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no
transaction found
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: tm
[t_funcs.c:312]: t_relay_to(): SER: forwarding ACK  statelessly
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated:
2132d578ec20fa9b478ada51e9f2965f
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[forward.c:211]: get_out_socket(): DEBUG: get_out_socket: socket
determined: 0xf6e777ec
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[msg_translator.c:206]: check_via_address():
check_via_address(1.2.2.94, 192.168.4.218, 0)
Apr 16 19:21:33 kam-sbc-1-01 /usr/sbin/kamailio[9178]: DEBUG: <core>
[forward.c:592]: forward_request(): Sending:#012ACK
sip:1.2.3.46;lr=3Don;ftag=3D259196205;nat=3Dyes SIP/2.0#015#012Record-Route:
<sip:1.2.3.46;lr=3Don;ftag=3D259196205>#015#012Via: SIP/2.0/UDP
1.2.3.46;branch=3Dz9hG4bK4449.2132d578ec20fa9b478ada51e9f2965f.0#015#012Via:
SIP/2.0/UDP 192.168.4.218:5062;rport=3D58542;received=3D1.2.2.94;branch=3Dz9h=
G4bK1161188624#015#012From:
"0099977" <sip:0099977(a)1.2.3.46>;tag=3D259196205#015#012To:
<sip:89215572714(a)1.2.3.46>;tag=3Das6bfd1fa1#015#012Call-ID:
910089142(a)192.168.4.218#015#012CSeq: 2 ACK#015#012Contact:
<sip:0099977(a)192.168.4.218:5062;alias=3D1.2.2.94~58542~1>#015#012Max-Forwar=
ds:
69#015#012User-Agent: Yealink SIP-T46G
28.71.14.4#015#012Content-Length: 0#015#012#015#012.







--=20
Best regards,

Dmitry Sytchev,
IT Engineer


--===============1473706591==--