11 Nov
2021
11 Nov
'21
8:35 p.m.
Working on a proof of concept with Kamailio 5.5.2 (Installed via
kamailio-5.5.2-0.el8.centos.x86_64 RPM from rpm.kamailio.org).
Also note that this is using the LUA interface
Running a simple SIPp scenario without registration. Routing is set with in Lua:
KSR.dbg("EP: ksr_route_relay Check for Base Route\n");
if KSR.is_INVITE() and KSR.siputils.has_totag() < 0 then
KSR.dbg("EP: ksr_route_relay Base Route\n");
--KSR.sl.send_reply("503", "OLGX Debug");
KSR.setdsturi("sip:192.168.1.14:5060");
--KSR.pv.sets("$du", "sip:192.168.1.12:5062");
end
The problem is that Kamailio is dropping the ACK to the 200 OK from the UAS. Wireshark
shows that the UAS is retransmitting the 200 OK and the ACK is not being forwarded from
the UAC to the UAS.
Within the Lua config script:
-- Handle requests within SIP dialogs
function ksr_route_withindlg()
if KSR.siputils.has_totag() < 0 then return 1; end
KSR.dbg("EP: ksr_route_withindlg has to-tag, it is within a dialog\n");
-- sequential request within a dialog should
-- take the path determined by record-routing
if KSR.rr.loose_route() > 0 then
ksr_route_dlguri();
if KSR.is_BYE() then
KSR.setflag(FLT_ACC); -- do accounting ...
KSR.setflag(FLT_ACCFAILED); -- ... even if the transaction fails
elseif KSR.is_ACK() then
-- ACK is forwarded statelessly
KSR.dbg("EP: ksr_route_withindlg Forwarding ACK\n");
ksr_route_natmanage();
elseif KSR.is_NOTIFY() then
-- Add Record-Route for in-dialog NOTIFY as per RFC 6665.
KSR.rr.record_route();
end
KSR.dbg("EP: ksr_route_withindlg loose route calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
end
if KSR.is_ACK() then
if KSR.tm.t_check_trans() > 0 then
-- no loose-route, but stateful ACK;
-- must be an ACK after a 487
-- or e.g. 404 from upstream server
KSR.dbg("EP: ksr_route_withindlg is ACK calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
else
-- ACK without matching transaction ... ignore and discard
KSR.dbg("EP: ksr_route_withindlg Unknown ACK exit\n");
KSR.x.exit();
end
end
KSR.sl.sl_send_reply(404, "Not here");
KSR.dbg("EP: ksr_route_withindlg exit after 404\n");
KSR.x.exit();
end
And logs for the ACK:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/385) [[ACK
sip:service@192.168.1.15:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP
192.168.1.12:5060;branch=z9hG4bK-1091869]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:679]: parse_msg(): method: <ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): uri:
<sip:service@192.168.1.15:5060>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type
1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> =
<z9hG4bK-1091869-1-5>; state=16
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type
4
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=4088926SIPpTag014
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:173]: get_hdr_field(): <To> [63];
uri=[sip:service@192.168.1.15:5060]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:176]: get_hdr_field(): to body (39)[service
<sip:service@192.168.1.15:5060>], to tag (17)[4088926SIPpTag014]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID]
type 6
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type
5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1> <ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core> [core/receive.c:387]:
receive_msg(): --- received sip message - request - call-id: [1-1091869(a)192.168.1.12] -
cseq: [1 ACK]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:259]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:457]: receive_msg(): preparing to run routing scripts...
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sl [sl_funcs.c:443]:
sl_filter_ACK(): too late to be a local ACK!
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:489]: sr_lua_reload_script(): No need to reload
[/etc/kamailio/kamailio.lua] is version 0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:673]: app_lua_run_ex(): executing Lua function: [[ksr_request_route]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:675]: app_lua_run_ex(): lua top index is: 21
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Contact]
type 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name
[Max-Forwards] type 8
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Subject]
type 27
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name
[Content-Length] type 12
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: process_maxfwd is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd [mf_funcs.c:74]:
is_maxfwd_present(): value = 70
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: is_maxfwd_lt is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd [maxfwd.c:187]:
ki_is_maxfwd_lt(): value = 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: sanity_check is int: 1511
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[1] for: sanity_check is int: 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:247]:
check_ruri_sip_version(): check_ruri_sip_version entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:270]:
check_ruri_sip_version(): check_ruri_sip_version passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:277]:
check_ruri_scheme(): check_ruri_scheme entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:297]:
check_ruri_scheme(): check_ruri_scheme passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:318]:
check_required_headers(): check_required_headers entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:340]:
check_required_headers(): check_required_headers passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:506]:
check_cseq_method(): check_cseq_method entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:539]:
check_cseq_method(): check_cseq_method passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:548]:
check_cseq_value(): check_cseq_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:576]:
check_cseq_value(): check_cseq_value passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:585]:
check_cl(): check_cl entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:610]:
check_cl(): check_cl passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:622]:
check_expires_value(): check_expires_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:659]:
check_expires_value(): no expires header found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:759]:
check_parse_uris(): check_parse_uris entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:763]:
check_parse_uris(): parsing ruri
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:777]:
check_parse_uris(): looking up From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:791]:
check_parse_uris(): parsing From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=1091869SIPpTag001
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:817]:
check_parse_uris(): parsing From URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:835]:
check_parse_uris(): looking up To header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:857]:
check_parse_uris(): check_parse_uris(): parsing To URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:902]:
check_parse_uris(): check_parse_uris passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: siputils
[checks.c:123]: has_totag(): totag found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg has to-tag, it is within a dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg has to-tag, it is within a
dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr [loose.c:108]:
find_first_route(): No Route headers found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr [loose.c:1006]:
loose_route_mode(): There is no Route HF
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1034]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=1/2414 T start=0xffffffffffffffff
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:497]:
t_lookup_request(): start searching: hash=12314, isACK=1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:455]:
matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-1091869-1-5]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:675]:
t_lookup_request(): no transaction found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1103]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=2/2414 T end=(ni
l)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1 with no name
returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/577) [[SIP/2.0
200 OK 0D 0A Via: SIP/2.0/UDP
192.168.1.15;branch=z9hG4bKa103.32dd17e8a1a3458280dbbe34442737e7.0,]]
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 2 (reply(status))
flags 1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:687]: parse_msg(): SIP Reply (status):
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:689]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:691]: parse_msg(): status: <200>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:693]: parse_msg(): reason: <OK>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type
1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> =
<z9hG4bKa103.3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1103]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=2/2414 T end=(nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1 with no name
returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
The ACK is this:
ACK sip:service@192.168.1.15:5060 SIP/2.0\r\n
Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK-1091869-1-5\r\n
From: sipp <sip:sipp@192.168.1.12:5060>;tag=1091869SIPpTag001\r\n
To: service <sip:service@192.168.1.15:5060>;tag=4088926SIPpTag014\r\n
Call-ID: 1-1091869(a)192.168.1.12\r\n
CSeq: 1 ACK\r\n
Contact: sip:sipp@192.168.1.12:5060\r\n
Max-Forwards: 70\r\n
Subject: Performance Test\r\n
Content-Length: 0\r\n
\r\n
I’ve been trying to figure this out for days and don’t know what’s wrong here.
Thanks
12 Nov
12 Nov
7:49 a.m.
You’re right that SIPp is not adding record route.
I tried adding the ‘rrs’ flag as shown on the default scenarios but did not work.
Working SIPp scenarios would be appreciated.
Thanks
On Nov 11, 2021, at 2:42 PM, M S <shaheryarkh(a)gmail.com> wrote:
Seems you forgot to add record route to invite, as a result there is no Route header in
ACK, so loose route fails.
Additionally there is no contact alias, so routing via alias also fails.
Also it seems you are not creating SIP transactions and dialogs in script, you just
blindly receiving sip request from one end and throwing it out to the other end!
So only possible way to route ACK is to set destination URI, same way you do for INVITE.
You will have to do that for EVERY sip request, unless you make your script intelligent
enough to create and recognize sip transactions & dialogs properly.
Hope this helps.
--
Muhammad Shahzad Shafi
Tel: +49 176 99 83 10 85
Sent from my Huawei P40 5G phone
-------- Original message --------
From: Emilio Panighetti <emiliop(a)operalogic.com
<mailto:emiliop@operalogic.com>>
Date: Thu, 11 Nov 2021, 18:44
To: "Kamailio (SER) - Users Mailing List" <sr-users(a)lists.kamailio.org
<mailto:sr-users@lists.kamailio.org>>
Subject: [SR-Users] Kamailio dropping ACKs
Working on a proof of concept with Kamailio 5.5.2 (Installed via
kamailio-5.5.2-0.el8.centos.x86_64 RPM from rpm.kamailio.org
<http://rpm.kamailio.org/>).
Also note that this is using the LUA interface
Running a simple SIPp scenario without registration. Routing is set with in Lua:
KSR.dbg("EP: ksr_route_relay Check for Base Route\n");
if KSR.is_INVITE() and KSR.siputils.has_totag() < 0 then
KSR.dbg("EP: ksr_route_relay Base Route\n");
--KSR.sl.send_reply("503", "OLGX Debug");
KSR.setdsturi("sip:192.168.1.14:5060");
--KSR.pv.sets("$du", "sip:192.168.1.12:5062");
end
The problem is that Kamailio is dropping the ACK to the 200 OK from the UAS. Wireshark
shows that the UAS is retransmitting the 200 OK and the ACK is not being forwarded from
the UAC to the UAS.
<PastedGraphic-2.png>
Within the Lua config script:
-- Handle requests within SIP dialogs
function ksr_route_withindlg()
if KSR.siputils.has_totag() < 0 then return 1; end
KSR.dbg("EP: ksr_route_withindlg has to-tag, it is within a dialog\n");
-- sequential request within a dialog should
-- take the path determined by record-routing
if KSR.rr.loose_route() > 0 then
ksr_route_dlguri();
if KSR.is_BYE() then
KSR.setflag(FLT_ACC); -- do accounting ...
KSR.setflag(FLT_ACCFAILED); -- ... even if the transaction fails
elseif KSR.is_ACK() then
-- ACK is forwarded statelessly
KSR.dbg("EP: ksr_route_withindlg Forwarding ACK\n");
ksr_route_natmanage();
elseif KSR.is_NOTIFY() then
-- Add Record-Route for in-dialog NOTIFY as per RFC 6665.
KSR.rr.record_route();
end
KSR.dbg("EP: ksr_route_withindlg loose route calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
end
if KSR.is_ACK() then
if KSR.tm.t_check_trans() > 0 then
-- no loose-route, but stateful ACK;
-- must be an ACK after a 487
-- or e.g. 404 from upstream server
KSR.dbg("EP: ksr_route_withindlg is ACK calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
else
-- ACK without matching transaction ... ignore and discard
KSR.dbg("EP: ksr_route_withindlg Unknown ACK exit\n");
KSR.x.exit();
end
end
KSR.sl.sl_send_reply(404, "Not here");
KSR.dbg("EP: ksr_route_withindlg exit after 404\n");
KSR.x.exit();
end
And logs for the ACK:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/385) [[ACK
sip:service@192.168.1.15:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP
192.168.1.12:5060;branch=z9hG4bK-1091869]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:679]: parse_msg(): method: <ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): uri:
<sip:service@192.168.1.15:5060>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type
1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> =
<z9hG4bK-1091869-1-5>; state=16
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [From] type
4
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [To] type 3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=4088926SIPpTag014
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:173]: get_hdr_field(): <To> [63];
uri=[sip:service@192.168.1.15:5060]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:176]: get_hdr_field(): to body (39)[service
<sip:service@192.168.1.15:5060>], to tag (17)[4088926SIPpTag014]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Call-ID]
type 6
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [CSeq] type
5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1> <ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core> [core/receive.c:387]:
receive_msg(): --- received sip message - request - call-id: [1-1091869(a)192.168.1.12
<mailto:1-1091869@192.168.1.12>] - cseq: [1 ACK]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:259]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:457]: receive_msg(): preparing to run routing scripts...
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sl [sl_funcs.c:443]:
sl_filter_ACK(): too late to be a local ACK!
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:489]: sr_lua_reload_script(): No need to reload
[/etc/kamailio/kamailio.lua] is version 0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:673]: app_lua_run_ex(): executing Lua function: [[ksr_request_route]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:675]: app_lua_run_ex(): lua top index is: 21
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Contact]
type 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name
[Max-Forwards] type 8
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Subject]
type 27
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name
[Content-Length] type 12
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: process_maxfwd is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd [mf_funcs.c:74]:
is_maxfwd_present(): value = 70
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: is_maxfwd_lt is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd [maxfwd.c:187]:
ki_is_maxfwd_lt(): value = 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for: sanity_check is int: 1511
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[1] for: sanity_check is int: 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:247]:
check_ruri_sip_version(): check_ruri_sip_version entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:270]:
check_ruri_sip_version(): check_ruri_sip_version passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:277]:
check_ruri_scheme(): check_ruri_scheme entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:297]:
check_ruri_scheme(): check_ruri_scheme passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:318]:
check_required_headers(): check_required_headers entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:340]:
check_required_headers(): check_required_headers passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:506]:
check_cseq_method(): check_cseq_method entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:539]:
check_cseq_method(): check_cseq_method passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:548]:
check_cseq_value(): check_cseq_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:576]:
check_cseq_value(): check_cseq_value passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:585]:
check_cl(): check_cl entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:610]:
check_cl(): check_cl passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:622]:
check_expires_value(): check_expires_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:659]:
check_expires_value(): no expires header found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:759]:
check_parse_uris(): check_parse_uris entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:763]:
check_parse_uris(): parsing ruri
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:777]:
check_parse_uris(): looking up From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:791]:
check_parse_uris(): parsing From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=1091869SIPpTag001
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:817]:
check_parse_uris(): parsing From URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:835]:
check_parse_uris(): looking up To header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:857]:
check_parse_uris(): check_parse_uris(): parsing To URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity [sanity.c:902]:
check_parse_uris(): check_parse_uris passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: siputils
[checks.c:123]: has_totag(): totag found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg has to-tag, it is within a dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg has to-tag, it is within a
dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr [loose.c:108]:
find_first_route(): No Route headers found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr [loose.c:1006]:
loose_route_mode(): There is no Route HF
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1034]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=1/2414 T start=0xffffffffffffffff
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:497]:
t_lookup_request(): start searching: hash=12314, isACK=1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:455]:
matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-1091869-1-5]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:675]:
t_lookup_request(): no transaction found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1103]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=2/2414 T end=(ni
l)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1 with no name
returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket: (106/100/577) [[SIP/2.0
200 OK 0D 0A Via: SIP/2.0/UDP
192.168.1.15;branch=z9hG4bKa103.32dd17e8a1a3458280dbbe34442737e7.0,]]
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 2 (reply(status))
flags 1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:687]: parse_msg(): SIP Reply (status):
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:689]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:691]: parse_msg(): status: <200>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:693]: parse_msg(): reason: <OK>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type
1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> =
<z9hG4bKa103.3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm [t_lookup.c:1103]:
t_check_msg(): msg (0x7fef983a2608) id=2/2414 global id=2/2414 T end=(nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str: EP:
ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1 with no name
returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
The ACK is this:
ACK sip:service@192.168.1.15:5060 SIP/2.0\r\n
Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK-1091869-1-5\r\n
From: sipp <sip:sipp@192.168.1.12:5060>;tag=1091869SIPpTag001\r\n
To: service <sip:service@192.168.1.15:5060>;tag=4088926SIPpTag014\r\n
Call-ID: 1-1091869(a)192.168.1.12 <mailto:1-1091869@192.168.1.12>\r\n
CSeq: 1 ACK\r\n
Contact: sip:sipp@192.168.1.12:5060\r\n
Max-Forwards: 70\r\n
Subject: Performance Test\r\n
Content-Length: 0\r\n
\r\n
I’ve been trying to figure this out for days and don’t know what’s wrong here.
Thanks
<PastedGraphic-2.png>
8:34 a.m.
In my opinion, the carrier that you send a call, send ACK to RURI different
than Contact header value in your "200 OK".
On Fri, Nov 12, 2021 at 8:17 AM M S <shaheryarkh(a)gmail.com> wrote:
No, i didn't mean to add RR to SIPp, which is an
endpoint. The problem is
with your kamailio, which is a sip proxy here. Just look at default
kamailio.cfg file that is shipped with RPM package. You will get the idea.
It has lots of comments which explains most of the stuff in there.
As for SIPp, the default call scenario is fine. However, you may want to
add RTP stuff there for proper call setup (i.e. with audio).
--
Muhammad Shahzad Shafi
Tel: +49 176 99 83 10 85
Sent from my Huawei P40 5G phone
-------- Original message --------
From: Emilio Panighetti <emiliop(a)operalogic.com>
Date: Fri, 12 Nov 2021, 05:49
To: M S <shaheryarkh(a)gmail.com>
Cc: "Kamailio (SER) - Users Mailing List" <sr-users(a)lists.kamailio.org>
Subject: Re: [SR-Users] Kamailio dropping ACKs
You’re right that SIPp is not adding record route.
I tried adding the ‘rrs’ flag as shown on the default scenarios but did
not work.
Working SIPp scenarios would be appreciated.
Thanks
On Nov 11, 2021, at 2:42 PM, M S <shaheryarkh(a)gmail.com> wrote:
Seems you forgot to add record route to invite, as a result there is no
Route header in ACK, so loose route fails.
Additionally there is no contact alias, so routing via alias also fails.
Also it seems you are not creating SIP transactions and dialogs in script,
you just blindly receiving sip request from one end and throwing it out to
the other end!
So only possible way to route ACK is to set destination URI, same way you
do for INVITE. You will have to do that for EVERY sip request, unless you
make your script intelligent enough to create and recognize sip
transactions & dialogs properly.
Hope this helps.
--
Muhammad Shahzad Shafi
Tel: +49 176 99 83 10 85
Sent from my Huawei P40 5G phone
-------- Original message --------
From: Emilio Panighetti <emiliop(a)operalogic.com>
Date: Thu, 11 Nov 2021, 18:44
To: "Kamailio (SER) - Users Mailing List" <sr-users(a)lists.kamailio.org>
Subject: [SR-Users] Kamailio dropping ACKs
Working on a proof of concept with Kamailio 5.5.2 (Installed
via kamailio-5.5.2-0.el8.centos.x86_64 RPM from rpm.kamailio.org).
Also note that this is using the LUA interface
Running a simple SIPp scenario without registration. Routing is set with
in Lua:
KSR.dbg("EP: ksr_route_relay Check for Base Route\n");
if KSR.is_INVITE() and KSR.siputils.has_totag() < 0 then
KSR.dbg("EP: ksr_route_relay Base Route\n");
--KSR.sl.send_reply("503", "OLGX Debug");
KSR.setdsturi("sip:192.168.1.14:5060");
--KSR.pv.sets("$du", "sip:192.168.1.12:5062");
end
The problem is that Kamailio is dropping the ACK to the 200 OK from the
UAS. Wireshark shows that the UAS is retransmitting the 200 OK and the ACK
is not being forwarded from the UAC to the UAS.
<PastedGraphic-2.png>
Within the Lua config script:
-- Handle requests within SIP dialogs
function ksr_route_withindlg()
if KSR.siputils.has_totag() < 0 then return 1; end
KSR.dbg("EP: ksr_route_withindlg has to-tag, it is within a dialog\n");
-- sequential request within a dialog should
-- take the path determined by record-routing
if KSR.rr.loose_route() > 0 then
ksr_route_dlguri();
if KSR.is_BYE() then
KSR.setflag(FLT_ACC); -- do accounting ...
KSR.setflag(FLT_ACCFAILED); -- ... even if the transaction
fails
elseif KSR.is_ACK() then
-- ACK is forwarded statelessly
KSR.dbg("EP: ksr_route_withindlg Forwarding ACK\n");
ksr_route_natmanage();
elseif KSR.is_NOTIFY() then
-- Add Record-Route for in-dialog NOTIFY as per RFC 6665.
KSR.rr.record_route();
end
KSR.dbg("EP: ksr_route_withindlg loose route calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
end
if KSR.is_ACK() then
if KSR.tm.t_check_trans() > 0 then
-- no loose-route, but stateful ACK;
-- must be an ACK after a 487
-- or e.g. 404 from upstream server
KSR.dbg("EP: ksr_route_withindlg is ACK calling
ksr_route_relay\n");
ksr_route_relay();
KSR.dbg("EP: ksr_route_withindlg exit\n");
KSR.x.exit();
else
-- ACK without matching transaction ... ignore and discard
KSR.dbg("EP: ksr_route_withindlg Unknown ACK exit\n");
KSR.x.exit();
end
end
KSR.sl.sl_send_reply(404, "Not here");
KSR.dbg("EP: ksr_route_withindlg exit after 404\n");
KSR.x.exit();
end
And logs for the ACK:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket:
(106/100/385) [[ACK sip:service@192.168.1.15:5060 SIP/2.0 0D 0A Via:
SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK-1091869]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 1
(request) flags 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:679]: parse_msg(): method: <ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): uri: <
sip:service@192.168.1.15:5060>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:683]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Via] type 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bK-1091869-1-5>; state=16
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:557]: parse_headers(): this is the first via
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [From] type 4
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [To] type 3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param:
tag=4088926SIPpTag014
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header
reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:173]: get_hdr_field(): <To> [63]; uri=[
sip:service@192.168.1.15:5060]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:176]: get_hdr_field(): to body (39)[service <
sip:service@192.168.1.15:5060>], to tag (17)[4088926SIPpTag014]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Call-ID] type 6
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [CSeq] type 5
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1>
<ACK>
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: <core>
[core/receive.c:387]: receive_msg(): --- received sip message - request -
call-id: [1-1091869(a)192.168.1.12] - cseq: [1 ACK]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:259]: ksr_evrt_pre_routing(): event route core:pre-routing
not defined
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:457]: receive_msg(): preparing to run routing scripts...
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sl
[sl_funcs.c:443]: sl_filter_ACK(): too late to be a local ACK!
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:489]: sr_lua_reload_script(): No need to reload
[/etc/kamailio/kamailio.lua] is version 0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:673]: app_lua_run_ex(): executing Lua function:
[[ksr_request_route]]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:675]: app_lua_run_ex(): lua top index is: 21
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Contact] type 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Max-Forwards] type 8
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Subject] type 27
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Content-Length] type 12
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for:
process_maxfwd is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd
[mf_funcs.c:74]: is_maxfwd_present(): value = 70
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for:
is_maxfwd_lt is int: 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: maxfwd
[maxfwd.c:187]: ki_is_maxfwd_lt(): value = 69
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[0] for:
sanity_check is int: 1511
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1007]: sr_kemi_lua_exec_func_ex(): param[1] for:
sanity_check is int: 7
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:247]: check_ruri_sip_version(): check_ruri_sip_version entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:270]: check_ruri_sip_version(): check_ruri_sip_version passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:277]: check_ruri_scheme(): check_ruri_scheme entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:297]: check_ruri_scheme(): check_ruri_scheme passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:318]: check_required_headers(): check_required_headers entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:340]: check_required_headers(): check_required_headers passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:506]: check_cseq_method(): check_cseq_method entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:539]: check_cseq_method(): check_cseq_method passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:548]: check_cseq_value(): check_cseq_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:576]: check_cseq_value(): check_cseq_value passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:585]: check_cl(): check_cl entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:610]: check_cl(): check_cl passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:622]: check_expires_value(): check_expires_value entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:659]: check_expires_value(): no expires header found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:759]: check_parse_uris(): check_parse_uris entered
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:763]: check_parse_uris(): parsing ruri
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:777]: check_parse_uris(): looking up From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:791]: check_parse_uris(): parsing From header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:185]: parse_to_param(): add param:
tag=1091869SIPpTag001
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header
reached, state=29
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:817]: check_parse_uris(): parsing From URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:835]: check_parse_uris(): looking up To header
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:857]: check_parse_uris(): check_parse_uris(): parsing To URI
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: sanity
[sanity.c:902]: check_parse_uris(): check_parse_uris passed
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}:
siputils [checks.c:123]: has_totag(): totag found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str:
EP: ksr_route_withindlg has to-tag, it is within a dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg has to-tag,
it is within a dialog
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr
[loose.c:108]: find_first_route(): No Route headers found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: rr
[loose.c:1006]: loose_route_mode(): There is no Route HF
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:1034]: t_check_msg(): msg (0x7fef983a2608) id=2/2414 global
id=1/2414 T start=0xffffffffffffffff
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:497]: t_lookup_request(): start searching: hash=12314, isACK=1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:455]: matching_3261(): RFC3261 transaction matching failed -
via branch [z9hG4bK-1091869-1-5]
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:675]: t_lookup_request(): no transaction found
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:1103]: t_check_msg(): msg (0x7fef983a2608) id=2/2414 global
id=2/2414 T end=(ni
l)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str:
EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK
exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1
with no name returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/udp_server.c:493]: udp_rcv_loop(): received on udp socket:
(106/100/577) [[SIP/2.0 200 OK 0D 0A Via: SIP/2.0/UDP
192.168.1.15;branch=z9hG4bKa103.32dd17e8a1a3458280dbbe34442737e7.0,]]
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): first line type 2
(reply(status)) flags 1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:687]: parse_msg(): SIP Reply (status):
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:689]: parse_msg(): version: <SIP/2.0>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:691]: parse_msg(): status: <200>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/msg_parser.c:693]: parse_msg(): reason: <OK>
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header
name [Via] type 1
Nov 11 12:24:37 ol-vm1 /usr/sbin/kamailio[2413]: DEBUG: <core>
[core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232,
<branch> = <z9hG4bKa103.3
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: tm
[t_lookup.c:1103]: t_check_msg(): msg (0x7fef983a2608) id=2/2414 global
id=2/2414 T end=(nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1003]: sr_kemi_lua_exec_func_ex(): param[0] for: dbg is str:
EP: ksr_route_withindlg Unknown ACK exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/kemi.c:85]: sr_kemi_core_dbg(): EP: ksr_route_withindlg Unknown ACK
exit
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:1837]: sr_kemi_lua_exit(): script exit call
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_api.c:729]: app_lua_run_ex(): ksr error call from Lua: ~~ksr~exit~~
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: app_lua
[app_lua_mod.c:167]: sr_kemi_config_engine_lua(): execution of route type 1
with no name returned 1
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: INFO: LUA {ACK}: <core>
[core/receive.c:515]: receive_msg(): request-route executed in: 364 usec
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
Nov 11 12:24:36 ol-vm1 /usr/sbin/kamailio[2414]: DEBUG: LUA {ACK}: <core>
[core/receive.c:606]: receive_msg(): cleaning up
The ACK is this:
ACK sip:service@192.168.1.15:5060 SIP/2.0\r\n
Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK-1091869-1-5\r\n
From: sipp <sip:sipp@192.168.1.12:5060>;tag=1091869SIPpTag001\r\n
To: service <sip:service@192.168.1.15:5060>;tag=4088926SIPpTag014\r\n
Call-ID: 1-1091869(a)192.168.1.12\r\n
CSeq: 1 ACK\r\n
Contact: sip:sipp@192.168.1.12:5060\r\n
Max-Forwards: 70\r\n
Subject: Performance Test\r\n
Content-Length: 0\r\n
\r\n
I’ve been trying to figure this out for days and don’t know what’s wrong
here.
Thanks
<PastedGraphic-2.png>
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions
* sr-users(a)lists.kamailio.org
Important: keep the mailing list in the recipients, do not reply only to
the sender!
Edit mailing list options or unsubscribe:
* https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
1106
days inactive
1107
days old
4 comments
3 participants
participants (3)
-
Emilio Panighetti -
Sergey Safarov -
M S