From kbdfck@gmail.com Fri Apr 17 12:13:36 2015
From: Dmitry Sytchev <kbdfck@gmail.com>
To: sr-users@lists.kamailio.org
Subject: Re: [SR-Users] Kamailio relays ACK of 200 OK to itself
Date: Fri, 17 Apr 2015 13:13:30 +0300
Message-ID:
 <CA+GmxbbCM5qpO0rS6iptt7gFJnwbMAuE2tXFaLhuaqZU8ZRyYA@mail.gmail.com>
In-Reply-To: <5530D344.2080704@sipwise.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============0668088306=="

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

Hi Daniel!

I've tried Yealink and Cisco SPA-303
They send very similar ACKs, the problem seems to be not in their SIP stacks.
Original ACK URI is correct uri from 200 OK contact.
Route: header is set to correct value from Record-Route from 200 OK.
Maybe my NAT handling code makes something wrong with original ACK...

There is kinda unusual IP setup on machine - there is quagga daemon,
there are many public IPs and one of machine's public IP addresses is
set as /32 on loopback to be announced with BGP. But routing is
correct, so I don't think there are issues with this.
mhomed =3D 1 in kamailo config.

I'll get full SIP dumps and post it there.

Thanks!




2015-04-17 12:32 GMT+03:00 Daniel Grotti <dgrotti(a)sipwise.com>:
> Hi,
> please also check if you have set aliases (kamailio.cfg global
> parameters) to the IP address in the R-URI.
>
>
> --
> Daniel Grotti
> VoIP Engineer
>
>
> Sipwise GmbH
> Europaring F15 | 2345 Brunn am Gebirge, Austria | www.sipwise.com
>
> On 04/16/2015 07:23 PM, Dmitry Sytchev wrote:
>> 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 hos=
t.
>>
>> 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.1=
26.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-Rout=
e:
>> <sip:1.2.3.46;lr=3Don;ftag=3D259196205>#015#012Via: SIP/2.0/UDP
>> 1.2.3.46;branch=3Dz9hG4bK4449.2132d578ec20fa9b478ada51e9f2965f.0#015#012Vi=
a:
>> SIP/2.0/UDP 192.168.4.218:5062;rport=3D58542;received=3D1.2.2.94;branch=3D=
z9hG4bK1161188624#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-For=
wards:
>> 69#015#012User-Agent: Yealink SIP-T46G
>> 28.71.14.4#015#012Content-Length: 0#015#012#015#012.
>>
>>
>>
>>
>>
>>
>>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users(a)lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users



--=20
Best regards,

Dmitry Sytchev,
IT Engineer


--===============0668088306==--