Hello all!
I have stumbled in a weird behaviour which I cannot understand why it
happened now. Hope someone can explain why.
For some reason, calls are blocked with an error message saying that there
is no transactions available right at the beginning/start of the call.
I am using some event routes like the one below:
event_route[tm:local-response] {
xlog("L_INFO", "local-response - replied locally to $rm with
$T_reply_code \n");
if ( is_method("OPTIONS") )
{
xlog("L_INFO","tm:local-response - local response to $rm with
$T_reply_code $Ri:$Rp $RAi:$RAp \n");
}
}
it is very simple, only logs a line in case method is OPTIONS when replied
by Kamailio. And this **was** working fine for weeks having processed
thousands of test calls.
I also have a tm:local-request event route:
# TM Event Routes - Catches BYE sent from local
event_route[tm:local-request] {
xlog("L_INFO", "tm:local-request - sending $rm from $$ua=$ua\n");
if ($rm == "BYE" && $ua =~ "kamailio") {
$var(type) = "CALL_FINISH";
$var(_ev_type) = "CALL_FINISH";
$var(_ev_hint) = "local-bye";
$var(islocal) = 1;
xlog("L_INFO", "tm:local-request - setting islocal=1 - $rm from
$$ua=$ua\n");
route(TRACK_BYE); # sets $dlg_var(ts_bye_usec) and
$dlg_var(finished_by)
# Protect empty branch_stats before it reaches jansson later
if ($var(_branch_stats) == $null || $var(_branch_stats) == "")
$var(_branch_stats) = "[]";
# Lock only for the atomic write block - no module calls inside.
sht_lock("local_bye=>$ci");
$sht(local_bye=>$ci|tkg_eid) = $dlg_var(tkg_eid);
$sht(local_bye=>$ci|bye_time) = $dlg_var(ts_bye_usec);
$sht(local_bye=>$ci|ack_time) = $dlg_var(ts_ack_usec);
$sht(local_bye=>$ci|180_time) = $dlg_var(first_180_ts);
$sht(local_bye=>$ci|183_time) = $dlg_var(first_183_ts);
$sht(local_bye=>$ci|branch_stats) = $dlg_var(branch_stats);
$sht(local_bye=>$ci|finished_by) = $dlg_var(finished_by);
$sht(local_bye=>$ci|is_local) = 1;
sht_unlock("local_bye=>$ci");
xlog("L_INFO", "tm:local-request - cached all dlg_vars for ci=$ci
tkg_eid=$dlg_var(tkg_eid) bye_time=$dlg_var(ts_bye_usec)\n");
}
if ($rm == "OPTIONS" && $ua =~ "kamailio")
{
# Override fr_timer just for OPTIONS transactions
t_set_fr(7000, 0); # 7s instead of 10s, closer to dispatcher's 5s
ping interval; if not, the result is a timing drift 60s-70s-80s
$var(local_ip_port) = $shv(local_ip_port);
$var(statuskey) = $du;
xlog("L_DBG", "tm:local-request - DISPATCHER PROBE: Sending from
$var(local_ip_port) to $var(statuskey) ( $var(statuskey) has
$sht(sbcstatus=>$var(statuskey)) failures |
probe=$sht(gw_probe=>$var(statuskey))) \n");
if ( $sht(sbcstatus=>$var(statuskey)) >= SBC_FAILURE_THRESHOLD)
{
xlog("L_DBG","tm:local-request - counter for $du is
$sht(sbcstatus=>$var(statuskey)), probing... \n");
route(NOTIFY_ENDPOINT_DOWN);
}
$sht(sbcstatus=>$var(statuskey)) =
$(sht(sbcstatus=>$var(statuskey)){s.int}) + 1;
}
}
The main route looks like:
request_route {
$avp(START_TIME)=$utimef(%Y-%m-%d %H:%M:%S);
$var(send_sock) = $null;
$var(EVENT_TIME) = $TV(Sn);
// in case KXP is not connected, do not process any SIP messages
// (except OPTIONS or any method from an ongoing dialog) and reply with
503 to INVITEs
if ( $sht(evapistatus=>state) == 0 && is_method("INVITE") )
{
sl_reply("503", "Service Unavailable");
exit;
}
#!ifdef WITH_ACL
$var(GROUPID) = allow_address("100", "$si", "$sp"); // group ID 100
sets denied IPs and subnets
if ( !$var(GROUPID) ) // if client is in denied group (group ID
100)
{
xlog("L_WARN", "INIT - $si:$sp is not in the allowed ACL
Group ID !\n");
# uncoment below if you wish to return SIP 401 error to
non-allowed clients
#sl_reply("401", "Address not allowed");
exit;
}
#!endif
if (is_method("OPTIONS") && $sht(evapistatus=>state) > 0 )
{
// reply to OPTIONS only if Kamailio has an EVAPI connection active
// as we do not want Kamailio to receive SIP messages if no KXP
available
sl_send_reply("200","OK");
exit;
}
#!ifdef WITH_DMQ
route(HANDLE_DMQ);
#!endif
# handle retransmissions
route(HANDLE_RETRANS);
# per request initial checks
route(REQINIT);
# CANCEL processing
route(HANDLE_CANCEL);
# handle requests within SIP dialogs
route(WITHINDLG);
# record routing for dialog forming requests (in case they are routed)
# - remove preloaded route headers
remove_hf("Route");
if (is_method("INVITE"))
{
record_route();
route(RESET_VARS);
xlog("L_INFO","MAIN_ROUTE - initializing dlg_manage()\n");
dlg_manage();
route(HANDLE_INVITE);
exit;
}
route(RELAY);
exit;
}
route[HANDLE_INVITE] {
# Send INVITE details to Python script
# Convert headers to JSONc
route(TRACK_INVITE); // keeps track of timestamp when INVITE was
received
route(HEADERS_TO_JSON); // converts SIP headers to JSON struct
using jsdt_run
function
# Send to Python via EVAPI
$var(evmsg) = "INVITE:" + $T(id_index) + ":" + $T(id_label) + ":" +
$var(json_headers);
// no need to t_suspend() request as evapi_async_relay already suspends
the request
xlog("L_INFO", "HANDLE_INVITE - suspended transaction for INVITE /
CALL_ATTEMPT. Index: $T(id_index) - Label: $T(id_label) \n" );
evapi_async_relay("CALL_ATTEMPT:$T(id_index):$T(id_label):$var(json_headers)");
exit;
}
At some given point, the HANDLE_INVITE makes use of an EVAPI script
(Python) that requests routes from a routing engine, applies rules (like
header manipulation,etc...) and then RELAYs the calls.
This is all working fine and has been working for many months (still under
test environments).
For some reason, after restarting, Kamailio started producing the below
debug logs and stopped processing calls.
In fact, Calls where received and the only message that Kamailio would
reply was SIP 100 Trying until the ingress endpoint gives up with timeout.
I restarted Kamailio many time, increased shared and private memory to 2048
(just in case), but no luck.
I think the issue is identified in these lines (also highlighted in log
lines below):
{105415 2}: tm: add_blind_uac(): no transaction context
{105415 2}: tm: t_suspend(): failed to add the blind UAC
{105415 2}: evapi: w_evapi_async_relay(): failed to suspend request
processing
And then back in Context 1 we can find:
{105415 1}: HANDLE_INVITE - Index: <null> - Label: <null>
I thought that it could be some stale Dialogs in DB causing the issue, so I
connected to DB and checked dialog and dialog_vars tables, but they were
both empty.
After extensive testing and analysis, the solution was to **comment** the
full event_route[tm:local-response] route block. Once restarted, everything
worked as before!
No other lines of code were modified.
So the question remains: why this behaviour? Why Kamailio stopped creating
transactions, processing calls, until I commented the
event_route[tm:local-response] ?
This was tested using Kamailio 5.8.4 and Kamailio 6.1.1
{1775747310.015114 105415 1 [email protected] INVITE}
<script>: HANDLE_INVITE - suspended transaction for INVITE.
{1775747310.015146 105415 1 [email protected] INVITE} tm
[t_lookup.c:1868]: t_newtran(): msg (0x7f5720e45020) id=62/105415 global
id=62/105415 T start=(nil)
{1775747310.015146 105415 1 [email protected] INVITE} tm
[t_lookup.c:781]: t_lookup_request(): start searching: hash=46408, isACK=0
{1775747310.015146 105415 1 [email protected] INVITE} tm
[t_lookup.c:499]: matching_3261(): RFC3261 transaction matching failed -
via branch [z9hG4bK00B1b0918b41312488f]
{1775747310.015146 105415 1 [email protected] INVITE} tm
[t_lookup.c:981]: t_lookup_request(): no transaction found
{1775747310.015146 105415 1 [email protected] INVITE} tm
[h_table.c:532]: tm_xdata_swap(): copy X/AVPs from msg context to txdata
{1775747310.015146 105415 1 [email protected] INVITE} tm
[t_hooks.c:301]: run_reqin_callbacks_internal(): trans=0x7f56a2f20d50,
callback type 1, id 0 entered
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:780]: dlg_lookup_mode(): ref dlg 0x7f56a2f02110 with 1
-> 2
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:784]: dlg_lookup_mode(): dialog id=115027 found on entry
83302
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_handlers.c:819]: dlg_onreq(): dialog added to tm callbacks
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:1088]: dlg_unref_helper(): unref op on 0x7f56a2f02110
with 1 from dlg_hash.c:1106
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:1092]: dlg_unref_helper(): unref dlg 0x7f56a2f02110 with
1 -> 1
{1775747310.015146 105415 1 [email protected] INVITE} tm
[h_table.c:551]: tm_xdata_swap(): restore X/AVPs msg context from txdata
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated:
b00467ce86b2fae8ac84d50ec8899e2e
{1775747310.015146 105415 1 [email protected] INVITE} tm
[h_table.c:415]: build_cell(): created new cell 0x7f56a2f20d50
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/msg_translator.c:162]: check_via_address(): (10.246.252.2,
10.246.252.2, 0)
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_cseq.c:116]: dlg_cseq_prepare_new_msg(): prepare new msg for
cseq update operations
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type
2 (reply(status)) flags 1
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply (status):
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:732]: parse_msg(): version: <SIP/2.0>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:734]: parse_msg(): status: <100>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:736]: parse_msg(): reason: <trying --
your call is important to us>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Via] type 1
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:1309]: parse_via_param(): Found param type
232, <branch> = <z9hG4bK00B1b0918b41312488f>; state=6
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:1309]: parse_via_param(): Found param type
235, <rport> = <5168>; state=16
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached,
state=5
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first
via
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_cseq.c:59]: dlg_cseq_prepare_msg(): prepare msg for cseq update
operations
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [From] type 4
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [To] type 3
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of
header reached, state=10
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:172]: get_hdr_field(): <To> [54]; uri=[
sip:[email protected]:5060]
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body
(54)["+3225484211" <sip:[email protected]:5060>#015#012], to tag
(0)[]
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Call-ID] type 6
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [CSeq] type 5
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>:
<929293> <INVITE>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Server] type :
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Content-Length] type 12
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
{1775747310.015146 105415 1 [email protected] INVITE}
dialog [dlg_cseq.c:87]: dlg_cseq_prepare_msg(): no second via in this
message
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type
2 (reply(status)) flags 1
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply (status):
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:732]: parse_msg(): version: <SIP/2.0>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:734]: parse_msg(): status: <100>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:736]: parse_msg(): reason: <trying --
your call is important to us>
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Via] type 1
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:1309]: parse_via_param(): Found param type
232, <branch> = <z9hG4bK00B1b0918b41312488f>; state=6
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:1309]: parse_via_param(): Found param type
235, <rport> = <5168>; state=16
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached,
state=5
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
{1775747310.015146 105415 1 [email protected] INVITE}
<core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first
via
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [From] type 4
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [To] type 3
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of
header reached, state=10
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/msg_parser.c:172]: get_hdr_field(): <To> [54]; uri=[
sip:[email protected]:5060]
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body
(54)["+3225484211" <sip:[email protected]:5060>#015#012], to tag
(0)[]
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [Call-ID] type 6
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed
header name [CSeq] type 5
{1775747310.015490 105415 2 [email protected] INVITE}
<core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>:
<929293> <INVITE>
{1775747310.015490 105415 2 [email protected] INVITE} tm
[t_lookup.c:1565]: t_check_msg(): msg (0x7ffe7d59aec0) id=63/105415 global
id=62/105415 T start=0x7f56a2f20d50
{1775747310.015490 105415 2 [email protected] INVITE} tm
[t_lookup.c:1542]: t_reply_matching(): failure to match a transaction
{1775747310.015490 105415 2 [email protected] INVITE} tm
[t_lookup.c:1637]: t_check_msg(): msg (0x7ffe7d59aec0) id=63/105415 global
id=63/105415 T end=(nil)
{1775747310.015490 105415 2 [email protected] INVITE} tmx
[t_var.c:554]: pv_get_tm_reply_code(): reply code is <0>
*{1775747310.015490 105415 2 [email protected]
<[email protected]> INVITE} <script>: local-response -
replied locally to INVITE with 0*
*{1775747310.015542 105415 2 [email protected]
<[email protected]> INVITE} tm [t_reply.c:634]:
_reply_light(): reply sent out - buf=0x7f57209fd0d0: SIP/2.0 100 trying
-... shmem=0x7f56a2f02920: SIP/2.0 100 trying - {1775747310.015542 105415 2
[email protected] <[email protected]> INVITE}
tm [t_reply.c:650]: _reply_light(): finished {1775747310.015542 105415 2
[email protected] <[email protected]> INVITE}
tm [t_fwd.c:721]: add_blind_uac(): no transaction
context {1775747310.015542 105415 2 [email protected]
<[email protected]> INVITE} tm [t_suspend.c:101]:
t_suspend(): failed to add the blind UAC {1775747310.015542 105415 2
[email protected] <[email protected]> INVITE}
evapi [evapi_mod.c:364]: w_evapi_async_relay(): failed to suspend request
processing*
{*1775747310.015566 105415 1 [email protected]
<[email protected]> INVITE} <script>: HANDLE_INVITE -
suspended transaction for INVITE / CALL_ATTEMPT. Index: <null> - Label:
<null>*
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/receive.c:531]: receive_msg(): request-route executed in: 2404
usec
{1775747310.015570 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:780]: dlg_lookup_mode(): ref dlg 0x7f56a2f02110 with 1
-> 2
{1775747310.015570 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:784]: dlg_lookup_mode(): dialog id=115027 found on entry
83302
{1775747310.015570 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:1088]: dlg_unref_helper(): unref op on 0x7f56a2f02110
with 1 from dlg_hash.c:1106
{1775747310.015570 105415 1 [email protected] INVITE}
dialog [dlg_hash.c:1092]: dlg_unref_helper(): unref dlg 0x7f56a2f02110 with
1 -> 1
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
{1775747310.015570 105415 1 [email protected] INVITE}
<core> [core/receive.c:635]: receive_msg(): cleaning up
Atenciosamente / Kind Regards / Cordialement / Un saludo,
*Sérgio Charrua*
*www.kahea.ai <http://www.kahea.ai> / www.voip.pt <http://www.voip.pt>*
*OpenTelecom* - Consulting for Telecoms, Lda
Tel.: +351 <callto:+351+91+104+12+66>91 631 11 44
Email : *[email protected] <[email protected]>*
This message and any files or documents attached are strictly confidential
or otherwise legally protected.
It is intended only for the individual or entity named. If you are not the
named addressee or have received this email in error, please inform the
sender immediately, delete it from your system and do not copy or disclose
it or its contents or use it for any purpose. Please also note that
transmission cannot be guaranteed to be secure or error-free.
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions --
[email protected]
To unsubscribe send an email to [email protected]
Important: keep the mailing list in the recipients, do not reply only to the
sender!
