Hi Wim,

Check this:

Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed

Maybe is related rrs. Add it to your sipp scenarios.

 <!-- By adding rrs="true" (Record Route Sets), the route sets         -->
  <!-- are saved and used for following messages sent. Useful to test   -->
  <!-- against stateful SIP proxies/B2BUAs.                             -->
  <recv rrs="true" request="INVITE" crlf="true">


Diego

2016-12-15 11:13 GMT-03:00 Wim Van Cauwenbergh <wimvc73@gmail.com>:
Hi, I have setup kamailio with the dispatcher module and have a problem with the ACK in response to 200OK not being forwarded by kamailio:

Scenario is very simple:
sipp(.219) --> kamailio (.220) --> sipp(.239)

SIP trace:

root@DNS-enum-8Gb-3:/var/log# ngrep -W byline -d eth0 port 5060
interface: eth0 (10.57.26.0/255.255.255.0)
filter: (ip or ip6) and ( port 5060 )
#
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
CSeq: 1 INVITE.
Max-Forwards: 70.
Subject: Performance Test.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.219.
s=-.
c=IN IP4 10.57.26.219.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
SIP/2.0 100 trying -- your call is important to us.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
CSeq: 1 INVITE.
Server: kamailio (4.2.0 (x86_64/linux)).
Content-Length: 0.
.

#
Record-Route: <sip:10.57.26.220;lr>.
Via: SIP/2.0/UDP 10.57.26.220;branch=z9hG4bKf92d.33550a94aa52aef3978cb507902d8aaa.0.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
CSeq: 1 INVITE.
Max-Forwards: 69.
Subject: Performance Test.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.219.
s=-.
c=IN IP4 10.57.26.219.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 10.57.26.220;branch=z9hG4bKf92d.33550a94aa52aef3978cb507902d8aaa.0, SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Length: 0.
.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.220;branch=z9hG4bKf92d.33550a94aa52aef3978cb507902d8aaa.0, SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Length: 0.
.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
ACK sip:10.57.26.239:5060;transport=UDP SIP/2.0.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-5.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 ACK.
Max-Forwards: 70.
Subject: Performance Test.
XContactinOK: <sip:10.57.26.239:5060;transport=UDP>.
Content-Length: 0.
.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.220;branch=z9hG4bKf92d.33550a94aa52aef3978cb507902d8aaa.0, SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
ACK sip:10.57.26.239:5060;transport=UDP SIP/2.0.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-5.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 ACK.
Max-Forwards: 70.
Subject: Performance Test.
XContactinOK: <sip:10.57.26.239:5060;transport=UDP>.
Content-Length: 0.
.

#
BYE sip:10.57.26.239:5060;transport=UDP SIP/2.0.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-7.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 2 BYE.
Max-Forwards: 70.
Subject: Performance Test.
Content-Length: 0.
.

#
SIP/2.0 404 Not here.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-7.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 2 BYE.
Server: kamailio (4.2.0 (x86_64/linux)).
Content-Length: 0.
.

#
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1--1.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 3 BYE.
Max-Forwards: 70.
Contact: <sip:sipp@10.57.26.219:5060;transport=UDP>.
Content-Length: 0.
.

#
SIP/2.0 404 Not here.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1--1.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 3 BYE.
Server: kamailio (4.2.0 (x86_64/linux)).
Content-Length: 0.
.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.220;branch=z9hG4bKf92d.33550a94aa52aef3978cb507902d8aaa.0, SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.

#
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.57.26.219:5060;branch=z9hG4bK-15698-1-0.
From: sipp <sip:sipp@10.57.26.219:5060>;tag=15698SIPpTag021.
To: sut <sip:service@10.57.26.220:5060>;tag=14783SIPpTag018.
CSeq: 1 INVITE.
Contact: <sip:10.57.26.239:5060;transport=UDP>.
Content-Type: application/sdp.
Content-Length:   135.
.
v=0.
o=user1 53655765 2353687637 IN IP4 10.57.26.239.
s=-.
c=IN IP4 10.57.26.239.
t=0 0.
m=audio 6000 RTP/AVP 0.
a=rtpmap:0 PCMU/8000.


kamailio.conf:

# ----- mi_fifo params -----
modparam("mi_fifo", "fifo_name", "/var/run/kamailio/kamailio_fifo")
modparam("ctl", "binrpc", "unix:/var/run/kamailio/kamailio_ctl")

# ----- rr params -----
# add value to ;lr param to cope with most of the UAs
modparam("rr", "enable_full_lr", 0)
# do not append from tag to the RR (no need for this script)
modparam("rr", "append_fromtag", 0)


# ----- acc params -----
modparam("acc", "log_flag", 1)
modparam("acc", "failed_transaction_flag", 3)
modparam("acc", "log_extra", 
"src_user=$fU;src_domain=$fd;dst_ouser=$tU;dst_user=$rU;dst_domain=$rd;src_ip=$si")

# ----- tm params -----
modparam("tm", "fr_timer", 2000)
modparam("tm", "fr_inv_timer", 40000)

# ----- dispatcher params -----
#modparam("dispatcher", "db_url",
# "mysql://openser:openserro@localhost/openser")
modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.list")
modparam("dispatcher", "table_name", "dispatcher")
modparam("dispatcher", "flags", 2)
modparam("dispatcher", "dst_avp", "$avp(AVP_DST)")
modparam("dispatcher", "grp_avp", "$avp(AVP_GRP)")
modparam("dispatcher", "cnt_avp", "$avp(AVP_CNT)")

####### Routing Logic ########


# main request routing logic

route {

# per request initial checks
route(REQINIT);

# handle requests within SIP dialogs
route(WITHINDLG);

### only initial requests (no To tag)

# CANCEL processing
if (is_method("CANCEL"))
{
if (t_check_trans())
t_relay();
exit;
}

t_check_trans();

# record routing for dialog forming requests (in case they are routed)
# - remove preloaded route headers
remove_hf("Route");
if (is_method("INVITE|SUBSCRIBE"))
record_route();

# account only INVITEs
if (is_method("INVITE"))
{
setflag(1); # do accounting
}

# handle presence related requests
route(PRESENCE);

# handle registrations
route(REGISTRAR);

if ($rU==$null)
{
# request with no Username in RURI
sl_send_reply("484","Address Incomplete");
exit;
}

# dispatch destinations
route(DISPATCH);

route(RELAY);
}


route[RELAY] {
if (!t_relay()) {
sl_reply_error();
}
exit;
}

# Per SIP request initial checks
route[REQINIT] {
if (!mf_process_maxfwd_header("15")) {
sl_send_reply("483","Too Many Hops");
exit;
}

# 1= only check the header RURI,  1126 checks some other general stuff 
if(!sanity_check("1126", "1"))
{
xlog("Malformed SIP message from $si:$sp\n");
exit;
}
}

# Handle requests within SIP dialogs
route[WITHINDLG] {
if (has_totag()) {
# sequential request withing a dialog should
# take the path determined by record-routing
xlog("#######WITHINDLG:hastotag $si:$sp\n");
if (loose_route()) {
xlog("#######WITHINDLG:looseroute $si:$sp\n");
if (is_method("BYE")) {
setflag(1); # do accounting ...
setflag(3); # ... even if the transaction fails
}
route(RELAY);
} else {
if (is_method("SUBSCRIBE") && uri == myself) {
# in-dialog subscribe requests
route(PRESENCE);
exit;
}
if ( is_method("ACK") ) {
if ( t_check_trans() ) {
xlog("#######WITHINDLG:ACK transaction found $si:$sp\n");
# non loose-route, but stateful ACK;
# must be ACK after a 487 or e.g. 404 from upstream server
t_relay();
exit;
} else {
# ACK without matching transaction ... ignore and discard.
xlog("#######WITHINDLG:ACK no transaction found so discard $si:$sp\n");
exit;
}
}
sl_send_reply("404","Not here");
}
exit;
}
}


Debug:

Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP Request:
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:625]: parse_msg():  method:  <ACK>
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:627]: parse_msg():  uri:     <sip:10.57.26.239:5060;transport=UDP>
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:629]: parse_msg():  version: <SIP/2.0>
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-15698-1-5>; state=16
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg...
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [receive.c:197]: receive_msg(): preparing to run routing scripts...
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: sl [sl_funcs.c:412]: sl_filter_ACK(): DEBUG : sl_filter_ACK: to late to be a local ACK!
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=14783SIPpTag018
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [57]; uri=[sip:service@10.57.26.220:5060]
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [sut <sip:service@10.57.26.220:5060>]
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <1> <ACK>
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: siputils [checks.c:106]: has_totag(): totag found
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) ERROR: <script>: #######WITHINDLG:hastotag 10.57.26.219:5060
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: rr [loose.c:113]: find_first_route(): No Route headers found
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: rr [loose.c:929]: loose_route(): There is no Route HF
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=(nil)
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=53919, isACK=1
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=(nil)
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) ERROR: <script>: #######WITHINDLG:ACK no transaction found so discard 10.57.26.219:5060
Dec 15 15:12:02 DNS-enum-8Gb-3 kamailio[6864]: 1(6883) DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)





_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users