Hello,
We are trying to use Kamailio 4.2 with RTPEngine 3.3 behind NAT.
Somehow SIP responses (200 OK) are not handled by Kamailio.
The following INVITE is send to the receiving end (WebRTC Client):
INVITE sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com SIP/2.0 Record-Route: sip:104.155.11.255:5060;nat=yes;lr=on Via: SIP/2.0/UDP 104.155.11.255:5060 ;branch=z9hG4bK865.9db0c023bec2f314e89ae0f18b78d2f0.0 Via: SIP/2.0/UDP 10.240.215.73:5060 ;rport=5060;received=146.148.113.245;branch=z9hG4bK644600e2 Max-Forwards: 69 From: "Anonymous" sip:anonymous@anonymous.invalid;tag=as68f0a26a To: sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com Contact: sip:anonymous@10.240.215.73:5060;alias=146.148.113.245~5060~1 Call-ID: 368f6ec901a3552e3b37a70907634f4f@10.240.215.73:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 12.5.0 Date: Fri, 24 Oct 2014 08:38:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 738 P-hint: outbound .......
The client response looks like this:
SIP/2.0 200 OK Via: SIP/2.0/UDP 104.155.11.255:5060 ;branch=z9hG4bK865.9db0c023bec2f314e89ae0f18b78d2f0.0;rport=5060;received=104.155.11.255 , SIP/2.0/UDP 10.240.215.73:5060 ;rport=5060;received=146.148.113.245;branch=z9hG4bK644600e2 From: "Anonymous" sip:anonymous@anonymous.invalid;tag=as68f0a26a To: <sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com
;tag=E2VMB39U5NYHCXLZREFGQV2DAXPCZXNQ6J6P
Contact: <sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com
;tag=E2VMB39U5NYHCXLZREFGQV2DAXPCZXNQ6J6P
Call-ID: 368f6ec901a3552e3b37a70907634f4f@10.240.215.73:5060 CSeq: 102 INVITE Record-Route: sip:104.155.11.255:5060;nat=yes;lr=on Content-Type: application/sdp Content-Length: 938 .......
I have a xlog call as the first statement in kamailio routing script. I can see the request, which get's handled correctly but the response does not appear in kamailio log, though it arrives at the machine.
I am totally helpless, what might be wrong. If we use kamailio on a public accessable machine everything works as expected.
Maybe anyone might have had similiar problems using kamailio behind NAT.
Kind regards, Marko
Le Fri, 24 Oct 2014 10:51:57 +0200, Marko Seidenglanz marko.seidenglanz@gmail.com a écrit :
I have a xlog call as the first statement in kamailio routing script. I can see the request, which get's handled correctly but the response does not appear in kamailio log, though it arrives at the machine.
Hi Marko,
the SIP replies don't fall into the same routing block as the requests. You have to declare an explicit onreply_route to be able to catch replies and do something with them, like logging for example. See http://www.kamailio.org/wiki/cookbooks/4.2.x/core#onreply_route for details.
Cheers,
Hello Camille,
thank you for your fast response.
I have defined a reply route:
onreply_route[REPLY_FROM_WEBRTC] { xlog("L_DEBUG", "<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< SIP WEBRTC_REPLY: $si:$sp ------> $du "); xlog("L_DEBUG", "WEBRTC >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> KAMAILIO");
if(status=~"[12][0-9][0-9]") { rtpengine_manage("force trust-address replace-origin replace-session-connection ICE=remove RTP/AVP"); route(NATMANAGE); } }
And the request get's handled here:
route[TO_WEBRTC] { xlog("L_DEBUG", "KAMAILIO >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> WEBRTC"); rtpengine_manage("rtcp-mux-offer trust-address replace-origin replace-session-connection ICE=force RTP/SAVPF"); t_on_reply("REPLY_FROM_WEBRTC"); }
I've also defined a naked reply handler:
onreply_route { xlog("L_DEBUG", "<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< SIP NAKED REPLY: $si:$sp ------> $du "); }
None of the handler get's called, when kamailio is behind NAT. If I use it without NAT it works:
Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[TO_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=83 a=25 n=t_on_reply Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=72 a=16 n=if Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=71 a=25 n=t_is_set Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=71 a=25 n=t_on_failure Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=77 a=16 n=if Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=74 a=24 n=t_relay Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=(nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=17975, isACK=0 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7f05125345d8, callback type 1, id 0 entered Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: 1192e2bc8b6a8390f99a4a7139cd344e Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_funcs.c:347]: t_relay_to(): SER: new INVITE Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(146.148.113.245, 10.240.215.73, 0) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f051a8ed250: SIP/2.0 100 trying -..., shmem=0x7f0512536f90: SIP/2.0 100 trying - Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(_sip._ udp.whtest3.24dial.com(28), 33), h=536 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [resolve.c:967]: get_record(): get_record: skipping 1 NS (p=0x9e5b1b, end=0x9e5b4d) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [resolve.c:983]: get_record(): get_record: parsing 0 ARs (p=0x9e5b4d, end=0x9e5b4d) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:1772]: dns_get_related(): dns_get_related(0x7f0512537778 (_sip._udp.whtest3.24dial.com, 5), 33, *0x7f051a8ec028) (0) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:1939]: dns_cache_do_request(): dns_cache_do_request: cname detected: ghs.l.google.com (16) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:869]: dns_cache_add_unsafe(): dns_cache_add: adding _sip._ udp.whtest3.24dial.com(28) 5 (flags=0) at 536 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:869]: dns_cache_add_unsafe(): dns_cache_add: adding ghs.google.com(14) 5 (flags=0) at 66 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:2003]: dns_cache_do_request(): dns_cache_do_request: dns_get_entry(cname: ghs.l.google.com (16)) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(ghs.l.google.com(16), 33), h=702 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [resolve.c:770]: get_record(): get_record: lookup(ghs.l.google.com, 33) failed Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:894]: dns_cache_mk_bad_entry(): dns_cache_mk_bad_entry( ghs.l.google.com, 33, 60, 1) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:827]: dns_cache_add(): dns_cache_add: adding ghs.l.google.com(16) 33 (flags=1) at 702 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(whtest3.24dial.com(18), 1), h=452 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [resolve.c:967]: get_record(): get_record: skipping 0 NS (p=0x9e5af4, end=0x9e5af4) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [resolve.c:983]: get_record(): get_record: parsing 0 ARs (p=0x9e5af4, end=0x9e5af4) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:1772]: dns_get_related(): dns_get_related(0x7f0512537978 ( whtest3.24dial.com, 1), 1, *(nil)) (0) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [dns_cache.c:869]: dns_cache_add_unsafe(): dns_cache_add: adding whtest3.24dial.com(18) 1 (flags=0) at 452 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [msg_translator.c:458]: clen_builder(): clen_builder: content-length: 740 (740) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(146.148.113.245, 10.240.215.73, 0) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=77 a=2 n=exit Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [parser/sdp/sdp.c:793]: free_sdp(): _sdp = 0x7f051a908b00 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [parser/sdp/sdp.c:795]: free_sdp(): sdp = 0x7f051a8f7fd8 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[765]: DEBUG: <core> [parser/sdp/sdp.c:797]: free_sdp(): session = 0x7f051a8f8050 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply (status): Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg(): version: <SIP/2.0> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg(): status: <200> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg(): reason: <OK> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK7364.1192e2bc8b6a8390f99a4a7139cd344e.0>; state=6 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <104.155.11.255>; state=16 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:2715]: parse_via(): parse_via: next_via Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <146.148.113.245>; state=6 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK22173743>; state=16 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg... Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: exec: *** cfgtrace:onreply_route=[MANAGE_BRANCH] c=[/usr/local/etc/kamailio/routing.cfg] l=295 a=26 n=xlog Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: pv [pv_core.c:1133]: pv_get_dsturi(): no destination URI Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <script>: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< SIP NAKED REPLY: 104.155.12.183:5060 ------> <null> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=NE99PKCCWL6TCJ6MP4FL9XKM5XS8PLHG28AL Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [89]; uri=[sip:eZFOBx3naIamgwXtSCUi3@whtest3.24dial.com] Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [< sip:eZFOBx3naIamgwXtSCUi3@whtest3.24dial.com>] Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <102> <INVITE> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 17975 label 0 branch 0 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f05125345d8)! Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f05125345d8, callback type 2, id 0 entered Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: acc [acc_logic.c:644]: tmcb_func(): acc callback called for t(0x7f05125345d8) event type 2, reply code 200 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7f05125345d8 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: tm [t_reply.c:2210]: reply_received(): DEBUG: reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: exec: *** cfgtrace:onreply_route=[REPLY_FROM_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=318 a=26 n=xlog Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: pv [pv_core.c:1133]: pv_get_dsturi(): no destination URI Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <script>: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< SIP WEBRTC_REPLY: 104.155.12.183:5060 ------> <null> Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: exec: *** cfgtrace:onreply_route=[REPLY_FROM_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=319 a=26 n=xlog Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <script>: WEBRTC >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> KAMAILIO Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: exec: *** cfgtrace:onreply_route=[REPLY_FROM_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=325 a=16 n=if Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: exec: *** cfgtrace:onreply_route=[REPLY_FROM_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=322 a=25 n=rtpengine_manage Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=727 Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/sdp/sdp_helpr_funcs.c:505]: extract_mediaip(): located IP address [127.0.0.1] in `o=' field Oct 24 15:42:38 h2296799 /usr/local/sbin/kamailio[764]: DEBUG: <core> [parser/sdp/sdp_helpr_funcs.c:505]: extract_mediaip(): located IP address [84.180.121.192] in `c=' field
Behind NAT: Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <script>: KAMAILIO >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> WEBRTC Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[TO_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=82 a=25 n=rtpengine_manage Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp_helpr_funcs.c:505]: extract_mediaip(): located IP address [10.240.215.73] in `o=' field Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp_helpr_funcs.c:505]: extract_mediaip(): located IP address [10.240.215.73] in `c=' field Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp.c:574]: parse_sdp_session(): ignoring unknown type in a= line: `a=maxptime:150#015#012a=sendrecv#015#012' Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: rtpengine [rtpengine_funcs.c:148]: check_content_type(): type <application/sdp> found valid Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: rtpengine [rtpengine.c:1448]: rtpp_function_call(): proxy reply: d3:sdp740:v=0#015#012o=root 2105198325 2105198325 IN IP4 104.155.11.255#015#012s=Asterisk PBX 12.5.0#015#012c=IN IP4 104.155.11.255#015#012t=0 0#015#012a=ice-lite#015#012m=audio 32252 RTP/SAVPF 3 0 8 101#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=maxptime:150#015#012a=sendrecv#015#012a=rtcp:32253#015#012a=rtcp-mux#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:RC/2fFtLO6fLVwOyaBqTK/5PowB/7LNGJOtNS0iD#015#012a=setup:actpass#015#012a=fingerprint:sha-1 D9:26:45:E1:D6:E7:01:A4:04:90:F2:15:AF:A3:AD:01:3C:39:9B:7D#015#012a=ice-ufrag:pP7ALOtu#015#012a=ice-pwd:wsreIk3fR2JTJPvtWGpCu21RP7ry#015#012a=candidate:krhMgLYHbAxWidfK 1 UDP 2130706431 104.155.11.255 32252 typ host#015#012a=candidate:krhMgLYHbAxWidfK 2 UDP 2130706430 104.155.11.255 32253 typ host#015#0126:result2:oke Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[TO_WEBRTC] c=[/usr/local/etc/kamailio/routing.cfg] l=83 a=25 n=t_on_reply Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=72 a=16 n=if Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=71 a=25 n=t_is_set Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=71 a=25 n=t_on_failure Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=77 a=16 n=if Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=74 a=24 n=t_relay Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=(nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=27313, isACK=0 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7f4eb02f8bf8, callback type 1, id 0 entered Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: 30d0d77f27566a4be6ae5a29b9556a1d Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_funcs.c:347]: t_relay_to(): SER: new INVITE Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(146.148.113.245, 10.240.215.73, 0) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f4eb86b55e8: SIP/2.0 100 trying -..., shmem=0x7f4eb02fb828: SIP/2.0 100 trying - Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(_sip._ udp.whtest3.24dial.com(28), 33), h=536 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(ghs.google.com(14), 33), h=66 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(ghs.l.google.com(16), 33), h=702 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [resolve.c:770]: get_record(): get_record: lookup(ghs.l.google.com, 33) failed Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:894]: dns_cache_mk_bad_entry(): dns_cache_mk_bad_entry( ghs.l.google.com, 33, 60, 1) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:827]: dns_cache_add(): dns_cache_add: adding ghs.l.google.com(16) 33 (flags=1) at 702 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [dns_cache.c:566]: _dns_hash_find(): dns_hash_find(whtest3.24dial.com(18), 1), h=452 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [msg_translator.c:458]: clen_builder(): clen_builder: content-length: 740 (740) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(146.148.113.245, 10.240.215.73, 0) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: exec: *** cfgtrace:request_route=[RELAY] c=[/usr/local/etc/kamailio/routing.cfg] l=77 a=2 n=exit Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp.c:793]: free_sdp(): _sdp = 0x7f4eb86d01c0 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp.c:795]: free_sdp(): sdp = 0x7f4eb86c0370 Oct 24 13:51:25 kamailio-test /usr/local/sbin/kamailio[23473]: DEBUG: <core> [parser/sdp/sdp.c:797]: free_sdp(): session = 0x7f4eb86c03e8
And nothing get's received.
2014-10-24 13:32 GMT+02:00 Camille Oudot camille.oudot@orange.com:
Le Fri, 24 Oct 2014 10:51:57 +0200, Marko Seidenglanz marko.seidenglanz@gmail.com a écrit :
I have a xlog call as the first statement in kamailio routing script. I can see the request, which get's handled correctly but the response does not appear in kamailio log, though it arrives at the machine.
Hi Marko,
the SIP replies don't fall into the same routing block as the requests. You have to declare an explicit onreply_route to be able to catch replies and do something with them, like logging for example. See http://www.kamailio.org/wiki/cookbooks/4.2.x/core#onreply_route for details.
Cheers,
-- Camille
Hello,
The problem of kamailio not receiving the packet's is that packet size of 200 response seems to be too large. I removed the SDP from response and it arrives.
Anyone had a similar problem and knows how it might get solved (accept switching to TCP)
Kind regards, Marko
2014-10-24 10:51 GMT+02:00 Marko Seidenglanz marko.seidenglanz@gmail.com:
Hello,
We are trying to use Kamailio 4.2 with RTPEngine 3.3 behind NAT.
Somehow SIP responses (200 OK) are not handled by Kamailio.
The following INVITE is send to the receiving end (WebRTC Client):
INVITE sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com SIP/2.0 Record-Route: sip:104.155.11.255:5060;nat=yes;lr=on Via: SIP/2.0/UDP 104.155.11.255:5060 ;branch=z9hG4bK865.9db0c023bec2f314e89ae0f18b78d2f0.0 Via: SIP/2.0/UDP 10.240.215.73:5060 ;rport=5060;received=146.148.113.245;branch=z9hG4bK644600e2 Max-Forwards: 69 From: "Anonymous" sip:anonymous@anonymous.invalid;tag=as68f0a26a To: sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com Contact: sip:anonymous@10.240.215.73:5060;alias=146.148.113.245~5060~1 Call-ID: 368f6ec901a3552e3b37a70907634f4f@10.240.215.73:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 12.5.0 Date: Fri, 24 Oct 2014 08:38:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 738 P-hint: outbound .......
The client response looks like this:
SIP/2.0 200 OK Via: SIP/2.0/UDP 104.155.11.255:5060 ;branch=z9hG4bK865.9db0c023bec2f314e89ae0f18b78d2f0.0;rport=5060;received=104.155.11.255 , SIP/2.0/UDP 10.240.215.73:5060 ;rport=5060;received=146.148.113.245;branch=z9hG4bK644600e2 From: "Anonymous" sip:anonymous@anonymous.invalid;tag=as68f0a26a To: <sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com
;tag=E2VMB39U5NYHCXLZREFGQV2DAXPCZXNQ6J6P
Contact: <sip:evQzk4l62MdF3G7U6eudj@whtest3.24dial.com
;tag=E2VMB39U5NYHCXLZREFGQV2DAXPCZXNQ6J6P
Call-ID: 368f6ec901a3552e3b37a70907634f4f@10.240.215.73:5060 CSeq: 102 INVITE Record-Route: sip:104.155.11.255:5060;nat=yes;lr=on Content-Type: application/sdp Content-Length: 938 .......
I have a xlog call as the first statement in kamailio routing script. I can see the request, which get's handled correctly but the response does not appear in kamailio log, though it arrives at the machine.
I am totally helpless, what might be wrong. If we use kamailio on a public accessable machine everything works as expected.
Maybe anyone might have had similiar problems using kamailio behind NAT.
Kind regards, Marko