Hi Daniel!
Thanks for the suggestion.
I enabled latency statistics, and this is what I get:
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: INFO:
{1768400767.695436 1473608 1 102 INVITE
[email protected]:5060} <script>: HEADERS_TO_JSON
- Processing INVITE from 10.20.0.5:5060 to sip:[email protected]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: ERROR:
{1768400767.696483 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jsdt_run (25)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:445] took too long [1020 us]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: ERROR:
{1768400767.696516 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:454] took too long [1051 us]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: ERROR:
{1768400767.696629 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_set (28)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:454] took too long [107 us]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: ERROR:
{1768400767.696914 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (5)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:469] took too long [1481 us]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: INFO:
{1768400767.697365 1473608 2 102 INVITE
[email protected]:5060} <script>: local-response -
replied locally
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: ERROR:
{1768400767.697441 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [evapi_async_relay
(25)] cfg [/usr/local/etc/kamailio/kamailio_ire1_2.cfg:476] took too long
[448 us]
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: INFO: {
1768400767.697466 1473608 1 102 INVITE
[email protected]:5060} <script>: HANDLE_INVITE -
suspended transaction for INVITE / CALL_ATTEMPT. Index: 57894 - Label:
1377620424
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473608]: INFO:
{1768400767.697474 1473608 1 102 INVITE
[email protected]:5060} <core>
[core/receive.c:531]: receive_msg(): request-route executed in: 2978 usec
Jan 14 15:26:07 ire-lab-kamailio1 kamailio[1473635]: INFO: {
1768400767.999605 1473635 1 1 OPTIONS 123} <script>: evapi:message-received
- Received EVAPI message: RESPONSE:57894:1377620424:{"action": "ROUTE",
"call_id": "[email protected]:5060",
"max_number_of_crankbacks": 1, "method": "INVITE", "retry_on_failure":
"true", "routes": [{"crankback_profile": [{"next_tkg_eid": "20001",
"sip_errors": [402, 502]}, {"next_tkg_eid": "10003", "sip_errors": [403,
503]}], "dst_uri": "sip:10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10002", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [{"next_tkg_eid": "10003", "sip_errors": [404, 504]},
{"next_tkg_eid": "10003", "sip_errors": [403, 503]}], "dst_uri": "sip:
10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "20001", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [], "dst_uri": "sip:10.20.0.6:5060", "headers":
{"from": {"uri": "sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10003", "uri": "sip:[email protected]:5060"}],
"routing": "serial", "version": "1.0"}
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400767.999787 1473635 1 1 OPTIONS 123} <script>: Part 0: 'RESPONSE'
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400767.999808 1473635 1 1 OPTIONS 123} <script>: Part 1: '57894'
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400767.999816 1473635 1 1 OPTIONS 123} <script>: Part 2: '1377620424'
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400767.999982 1473635 1 1 OPTIONS 123} <script>: Part 3: '{"action":
"ROUTE", "call_id": "[email protected]:5060",
"max_number_of_crankbacks": 1, "method": "INVITE", "retry_on_failure":
"true", "routes": [{"crankback_profile": [{"next_tkg_eid": "20001",
"sip_errors": [402, 502]}, {"next_tkg_eid": "10003", "sip_errors": [403,
503]}], "dst_uri": "sip:10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10002", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [{"next_tkg_eid": "10003", "sip_errors": [404, 504]},
{"next_tkg_eid": "10003", "sip_errors": [403, 503]}], "dst_uri": "sip:
10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "20001", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [], "dst_uri": "sip:10.20.0.6:5060", "headers":
{"from": {"uri": "sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10003", "uri": "sip:[email protected]:5060"}],
"routing": "serial", "version": "1.0"}'
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.000196 1473635 1 1 OPTIONS 123} <core> [core/action.c:1629]:
run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:1439] took too long [202 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.000218 1473635 1 1 OPTIONS 123} <script>:
evapi:message-received - t_continue for 57894/1377620424
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.000450 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
TRANSACTION 57894|1377620424
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.000491 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
Resumed with RESPONSE {"action": "ROUTE", "call_id": "
[email protected]:5060",
"max_number_of_crankbacks": 1, "method": "INVITE", "retry_on_failure":
"true", "routes": [{"crankback_profile": [{"next_tkg_eid": "20001",
"sip_errors": [402, 502]}, {"next_tkg_eid": "10003", "sip_errors": [403,
503]}], "dst_uri": "sip:10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10002", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [{"next_tkg_eid": "10003", "sip_errors": [404, 504]},
{"next_tkg_eid": "10003", "sip_errors": [403, 503]}], "dst_uri": "sip:
10.20.0.6:5060", "headers": {"from": {"uri": "
sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "20001", "uri": "sip:[email protected]:5060"},
{"crankback_profile": [], "dst_uri": "sip:10.20.0.6:5060", "headers":
{"from": {"uri": "sip:[email protected]:5060"}, "to": {"uri": "
sip:[email protected]:5060"}}, "max_call_duration": 1000,
"tkg_eid": "10003", "uri": "sip:[email protected]:5060"}],
"routing": "serial", "version": "1.0"}
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.000676 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:669] took too long [126 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.000819 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
ROUTE action
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.000983 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (63)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:708] took too long [132 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.001009 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
has retry_on_failure
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.001066 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
retry_on_failure = 1
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001168 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:718] took too long [150 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001187 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:719] took too long [185 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001312 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:723] took too long [117 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001334 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:726] took too long [141 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001506 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:726] took too long [168 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.001722 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:729] took too long [144 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.001749 1473635 1 102 INVITE
[email protected]:5060} <script>: EVAPIRESPONSE -
retry_on_failure = 1 max_number_of_crankbacks = 1
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.001839 1473635 1 102 INVITE
[email protected]:5060} <script>: RTJSON_PROCESS -
Initializing RTJSON routes
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.001893 1473635 1 102 INVITE
[email protected]:5060} <script>: RTJSON_PROCESS -
{"version":"1.0","routing":"serial","routes":[{"crankback_profile":[{"next_tkg_eid":"20001","sip_errors":[402,502]},{"next_tkg_eid":"10003","sip_errors":[403,503]}],"dst_uri":"sip:
10.20.0.6:5060","headers":{"from":{"uri":"sip:[email protected]:5060
"},"to":{"uri":"sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"10002","uri":"
sip:[email protected]:5060
"},{"crankback_profile":[{"next_tkg_eid":"10003","sip_errors":[404,504]},{"next_tkg_eid":"10003","sip_errors":[403,503]}],"dst_uri":"sip:
10.20.0.6:5060","headers":{"from":{"uri":"sip:[email protected]:5060
"},"to":{"uri":"sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"20001","uri":"
sip:[email protected]:5060
"},{"crankback_profile":[],"dst_uri":"sip:10.20.0.6:5060
","headers":{"from":{"uri":"sip:[email protected]:5060"},"to":{"uri":"
sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"10003","uri":"
sip:[email protected]:5060"}]}
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002023 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [rtjson_init_routes
(25)] cfg [/usr/local/etc/kamailio/kamailio_ire1_2.cfg:755] took too long
[116 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002051 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:761] took too long [145 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.002082 1473635 1 102 INVITE
[email protected]:5060} <script>: RTJSON_PROCESS -
Processing new route
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.002143 1473635 1 102 INVITE
[email protected]:5060} <script>: RTJSON_PROCESS -
routes assigned as index = 1 JSON =
{"version":"1.0","routing":"serial","routes":[{"crankback_profile":[{"next_tkg_eid":"20001","sip_errors":[402,502]},{"next_tkg_eid":"10003","sip_errors":[403,503]}],"dst_uri":"sip:
10.20.0.6:5060","headers":{"from":{"uri":"sip:[email protected]:5060
"},"to":{"uri":"sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"10002","uri":"
sip:[email protected]:5060
"},{"crankback_profile":[{"next_tkg_eid":"10003","sip_errors":[404,504]},{"next_tkg_eid":"10003","sip_errors":[403,503]}],"dst_uri":"sip:
10.20.0.6:5060","headers":{"from":{"uri":"sip:[email protected]:5060
"},"to":{"uri":"sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"20001","uri":"
sip:[email protected]:5060
"},{"crankback_profile":[],"dst_uri":"sip:10.20.0.6:5060
","headers":{"from":{"uri":"sip:[email protected]:5060"},"to":{"uri":"
sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"10003","uri":"
sip:[email protected]:5060"}]}
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002342 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:838] took too long [120 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002509 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:839] took too long [135 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002666 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jansson_get (34)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:840] took too long [132 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.002691 1473635 1 102 INVITE
[email protected]:5060} <script>: RELAY -
Modifying SIP headers from INVITE - route 10002 index 0
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.002713 1473635 1 102 INVITE
[email protected]:5060} <script>: RELAY - route is
=
{"crankback_profile":[{"next_tkg_eid":"20001","sip_errors":[402,502]},{"next_tkg_eid":"10003","sip_errors":[403,503]}],"dst_uri":"sip:
10.20.0.6:5060","headers":{"from":{"uri":"sip:[email protected]:5060
"},"to":{"uri":"sip:[email protected]:5060
"}},"max_call_duration":1000,"tkg_eid":"10002","uri":"
sip:[email protected]:5060"} to sip:10.20.0.6:5060
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002870 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [jsdt_run (27)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:844] took too long [143 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002956 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:849] took too long [783 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.002990 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:851] took too long [830 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.003109 1473635 1 102 INVITE
[email protected]:5060} <script>: PIN_SOCKET -
stored dlg_sock=udp:10.20.0.4:5060
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.003195 1473635 1 102 INVITE
[email protected]:5060} <script>: PIN_SOCKET -
forcing <udp:10.20.0.4:5060> (recv udp:10.20.0.4:5060)
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.003245 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (16)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:822] took too long [225 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: ERROR:
{1768400768.003268 1473635 1 102 INVITE
[email protected]:5060} <core>
[core/action.c:1629]: run_actions(): alert - action [corefunc (5)] cfg
[/usr/local/etc/kamailio/kamailio_ire1_2.cfg:858] took too long [249 us]
Jan 14 15:26:08 ire-lab-kamailio1 kamailio[1473635]: INFO:
{1768400768.003329 1473635 1 102 INVITE
[email protected]:5060} <script>: MANAGE_BRANCH -
initializing new branch
Highlighted in yellow background, the times of the request to EVAPI client (
1768400767.697466) and the EVAPI response to Kamailio (1768400767.999605),
which is ~300ms.
However, on EVAPI client's logs, I can see that receiving the message from
Kamailio + request to REST service + the response back to Kamailio takes
less than 20ms!
It is like Kamailio got stuck during 280ms for no reason (IMHO).
Already check, this is not constant (sometimes whole process takes 50ms,
other times takes more than 1 second) and it was verified in multiple
servers.
Note that there was only 1 Call Attempt, nothing else.
Part of the code is below. I hope it helps.
FYI:
- route(HEADERS_TO_JSON); is a route block that calls a KEMI script via
jsdt_app, and converts SIP headers to JSON object, supporting repeated
headers (converts to Array of strings). The javascript uses var raw =
KSR.pv.get("$mb") || ""; to get the SIP Headers and then loops
through each header, converting it to JSON. If there is a better way, I'm
open for suggestions. This will generate a JSON structure, saved on
$var(json_headers) , that is then sent to EVAPI client
via evapi_async_relay in route[HANDLE_INVITE]
- the EVAPI client (python) will take the received JSON and POST it to REST
service. EVAPI script was created because it also monitors, distributes
load and does failover between multiple REST servers, between other
functionalities...It is really fast, processing in less than 30ms each
request.
route[HANDLE_INVITE] {
# Convert headers to JSON
route(HEADERS_TO_JSON);
# 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
evapi_async_relay("CALL_ATTEMPT:$T(id_index):$T(id_label):$var(json_headers)");
xlog("L_INFO", "HANDLE_INVITE - suspended transaction for INVITE /
CALL_ATTEMPT. Index: $T(id_index) - Label: $T(id_label) \n" );
exit;
}
route[HEADERS_TO_JSON]
{
xlog("L_INFO", "HEADERS_TO_JSON - Processing INVITE from $si:$sp to
$ru\n");
# Get the full SIP message
# Use JavaScript for complex header parsing
if (!jsdt_run("headers_to_json")) {
xlog("L_ERR", "HEADERS_TO_JSON - Failed to convert headers to
JSON\n");
$var(json_headers) = "{}";
sl_reply_error();
exit;
}
# Result is stored in $var(headers_json)
#$var(json_headers) = $var(headers_json);
jansson_set("object" , "sip_invite" , "$var(headers_json)" ,
"$var(json_headers)" );
jansson_set("string" , "remote_ip_port" , "$si:$sp" ,
"$var(json_headers)" );
jansson_set("string" , "local_ip_port" , "$RAi:$RAp" ,
"$var(json_headers)" );
jansson_set("string" , "protocol" , "$pr" ,
"$var(json_headers)" );
jansson_set("integer", "retry" , "$var(retry)" ,
"$var(json_headers)" );
jansson_set("string" , "timestamp" , "$TV(Sn)" ,
"$var(json_headers)" );
xlog("L_DBG","HEADERS_TO_JSON - json generated $var(json_headers) ...
\n");
}
# Tiny helper to reply correctly inside/outside TM
route[REPLY_SAFE] {
# validate code (default to 480 if bad/empty)
if (!($var(code) =~ "^[1-6][0-9][0-9]$"))
$var(code) = "480";
if ($var(text) == "")
$var(text) = "Temporarily Unavailable";
if (t_check_trans()) {
xlog("L_INFO", "REPLY_SAFE - replying with t_reply\n");
t_reply( "$var(code)" , "$var(text)");
} else {
xlog("L_INFO", "REPLY_SAFE - replying with send_reply\n");
sl_send_reply("$var(code)", "$var(text)");
}
xlog("L_INFO", "REPLY_SAFE - replied $var(code) - $var(text)\n");
exit;
}
route[EVAPIRESPONSE] {
xlog("L_INFO", "EVAPIRESPONSE - TRANSACTION $T(id_index)|$T(id_label)
\n" );
xlog("L_INFO", "EVAPIRESPONSE - Resumed with RESPONSE $var(response)
\n" );
if ($var(response) == $null || $var(response) == "") {
xlog("L_INFO", "EVAPIRESPONSE - missing cached EVAPI response;
replying 500\n");
$var(code) = 500;
$var(text) = "Internal Server Error - 1";
route(REPLY_SAFE);
exit;
}
# Test each condition individually
if ($var(response) == "FALSE" || $var(response) == "NO_ROUTES")
{
# Check if response is FALSE (drop the call)
xlog("L_INFO", "EVAPIRESPONSE - Python script returned FALSE or NO
ROUTES, dropping call\n");
$var(code) = 500;
$var(text) = "Internal Server Error";
route(REPLY_SAFE);
exit;
}
jansson_get("retry_on_failure", $var(response),
"$var(retry_on_failure)");
if (jansson_get("action", $var(response), "$var(action)"))
{
if ($var(action) == "DROP") {
jansson_get("error_code", $var(response), "$var(error_code)");
jansson_get("error_text", $var(response), "$var(error_text)");
xlog("L_INFO", "EVAPIRESPONSE - DROP $var(error_code) -
$var(error_text)\n");
$var(code)=$var(error_code);
$var(text)=$var(error_text);
route(REPLY_SAFE);
exit;
}
else if ($var(action) == "CALL_REJECT") {
# Prefer nested object: { "action":"CALL_REJECT", "reject": {
"error_code":480, "error_text":"..." } }
$var(error_code) = $null; $var(error_text) = $null;
if (jansson_get("reject.error_code", $var(response),
"$var(error_code)")) ;
if (jansson_get("reject.error_text", $var(response),
"$var(error_text)")) ;
if ($var(error_code) == $null)
jansson_get("error_code", $var(response),
"$var(error_code)");
if ($var(error_text) == $null)
jansson_get("error_text", $var(response),
"$var(error_text)");
if ($var(error_code) == $null || $var(error_text) == $null) {
xlog("L_INFO", "EVAPIRESPONSE - CALL_REJECT missing fields,
defaults to 480\n");
$var(code)=480;
$var(text)="Temporarily Unavailable";
} else {
xlog("L_INFO", "EVAPIRESPONSE - CALL_REJECT
$var(error_code) - $var(error_text)\n");
$var(code)=$var(error_code);
$var(text)=$var(error_text);
}
route(REPLY_SAFE);
exit;
}
# Process RTJSON routing, action = ROUTE
else if ($var(action) == "ROUTE") {
xlog("L_INFO", "EVAPIRESPONSE - ROUTE action\n");
$dlg_var(retry_on_failure) = "0";
if ($var(retry_on_failure) != "")
{
xlog("L_INFO", "EVAPIRESPONSE - has retry_on_failure \n");
if ( $var(retry_on_failure) =~ "^(1|[Tt]rue)$")
{
xlog("L_INFO", "EVAPIRESPONSE - retry_on_failure = 1
\n");
$dlg_var(retry_on_failure) = "1";
}
}else
xlog("L_INFO", "EVAPIRESPONSE - NO retry_on_failure FOUND
or retry_on_failure = 0 !\n");
if (!jansson_get("max_number_of_crankbacks" , $var(response),
"$xavp(max_number_of_crankbacks)") )
$xavp(max_number_of_crankbacks) = 3; // default value
jansson_get("routes", $var(response), "$dlg_var(routing)");
$xavp(crb=>doc) = $var(response);
jansson_get("routes", $xavp(crb=>doc), "$var(routes_arr)");
xlog("L_INFO", "EVAPIRESPONSE - retry_on_failure =
$dlg_var(retry_on_failure) max_number_of_crankbacks =
$xavp(max_number_of_crankbacks) \n");
$dlg_var(rtjson_str) = $var(response);
# Process routes from RTJSON
route(RTJSON_PROCESS);
}
} else {
xlog("L_ERR", "EVAPIRESPONSE - Invalid response format from
Python\n");
$var(code) = 500;
$var(text) = "Internal Server Error";
route(REPLY_SAFE);
exit;
}
}
# Handle responses from Python script
event_route[evapi:message-received] {
$var(msg) = $evapi(msg);
xlog("L_INFO", "evapi:message-received - Received EVAPI message:
$var(msg)\n");
# fast-path heartbeat (exact match)
if ($var(msg) == "HEARTBEAT" || $var(msg) == "heartbeat") {
#route(EVAPI_HEARTBEAT);
exit;
}
# parse only as much as needed
$var(type) = $(var(msg){s.select,0,:});
$var(tindex) = $(var(msg){s.select,1,:}{s.int});
$var(tlabel) = $(var(msg){s.select,2,:}{s.int});
# Calculate the offset where the JSON payload begins
# Offset = Length(Type) + Length(Index) + Length(Label) + 3 (the
colons)
$var(offset) = $(var(type){s.len}) + $(var(tindex){s.len}) +
$(var(tlabel){s.len}) + 3;
xlog("L_INFO", "Part 0: '$var(type)'\n");
xlog("L_INFO", "Part 1: '$var(tindex)'\n");
xlog("L_INFO", "Part 2: '$var(tlabel)'\n");
if ($var(type) == "RESPONSE" && $var(tindex) =~ "^[0-9]+$" &&
$var(tlabel) =~ "^[0-9]+$") {
# strip "<type>:<tindex>:<tlabel>:" prefix (payload may contain ':')
# Extract the remaining value (JSON) using substring
# 0 as the second parameter means "until the end of the string"
$var(response) = $(var(msg){s.substr,$var(offset),0});
xlog("L_INFO", "Part 3: '$var(response)'\n");
# Stash the JSON by transaction key so we can read it after resume
#$var(key) = "$var(tindex)|$var(tlabel)";
jansson_get("action", $var(response), "$var(action)");
xlog("L_INFO", "evapi:message-received - t_continue for
$var(tindex)/$var(tlabel)\n");
t_continue("$var(tindex)", "$var(tlabel)", "EVAPIRESPONSE");
exit;
}
xlog("L_ERR", "evapi:message-received - invalid EVAPI message, replying
500\n");
# No transaction context here; just drop.
# actually, as we're not in a SIP context yet, the t_reply should not
be called here
# FIX ME - to be further tested
# t_reply("500", "Internal Server Error");
exit;
}
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.
On Wed, Jan 14, 2026 at 9:12 AM Daniel-Constantin Mierla <[email protected]>
wrote:
> Hello,
>
> if you watched the network traffic and the communication with the external
> application is very fast, then you have to investigate what action is slow
> in Kamailio config. You can set the latency-related core parameter and see
> if anyone is reported to take long to execute.
>
> Cheers,
> Daniel
> On 13.01.26 17:36, Sergio Charrua via sr-users wrote:
>
> Hello all,
>
> using Kamilio 5.8.2 with EVAPI module, connecting to a Python client.
> Kamailio is using following modules:
>
> jsonrpcs.so
> db_mysql.so
> db_cluster.so
> kex.so
> corex.so
> tm.so
> tmx.so
> sl.so
> rr.so
> pv.so
> maxfwd.so
> textops.so
> textopsx.so
> siputils.so
> xlog.so
> sanity.so
> ctl.so
> cfg_rpc.so
> evapi.so
> jansson.so
> rtjson.so
> dispatcher.so
> permissions.s
> app_jsdt.so
> uac.so
> xhttp.so
> xhttp_rpc.so
> dmq.so
> dialog.so
> htable.so
>
> The (very reduced) logic is:
> 1 - INVITE received
> 2 - send request to EVAPI client with SIP headers transformed into JSON
> object
> 3 - receive response from EVAPI client
> 4 - depending on response type, relay the call with routes supplied in
> response using RTJSON
>
> On its side, EVAPI Client upon receiving request from Kamailio (step #2)
> 1 - sends request to HTTP REST service requesting routes
> 2 - receives full RTJSON object (may include custom headers to add or
> update or remove)
> 3 - return full RTJSON to Kamailio as a response
>
> All this is working fine. *Except* that we noticed that, under testing at
> 1 Call per minute (not performance testing yet), the delay betway EVAPI
> step #3 and Kamailio step #3 goes anything between 200ms up to 1.2 seconds!
> EVAPI client is running on the same node where Kamailio is running too,
> using 127.0.0.1:8448 for connection.
> Knowing that there is nothing else running on the server, and that the
> CAPS is like 1 call per minute, there is no load, no traffic, so why these
> delays?!
>
> Additional settings:
> # ----- evapi params -----
> modparam("evapi", "workers", 4)
> modparam("evapi", "bind_addr", "127.0.0.1:8448")
> modparam("evapi", "netstring_format", 1)
>
> Some logs:
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949838]: INFO:
> {1768314358.181270 1949838 2 1 INVITE
> [email protected]} <script>: local-response -
> replied locally
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949838]: INFO:
> {1768314358.181325 1949838 1 1 INVITE
> [email protected]} <script>: HANDLE_INVITE -
> suspended transaction 5701 - Label: 625621129
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.761888 1949871 1 1 OPTIONS 123} <script>: Part 0: 'RESPONSE'
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.761928 1949871 1 1 OPTIONS 123} <script>: Part 1: '5701'
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.761936 1949871 1 1 OPTIONS 123} <script>: Part 2: '625621129'
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.761943 1949871 1 1 OPTIONS 123} <script>: Part 3: '{"action":
> "ROUTE", "routes": ...
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.762018 1949871 1 1 OPTIONS 123} <script>:
> evapi:message-received - t_continue for 5701/625621129
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.762078 1949871 1 1 INVITE
> [email protected]} <script>: EVAPIRESPONSE -
> TRANSACTION 5701|6256
> Jan 13 14:25:58 bl1642 /usr/local/sbin/kamailio[1949871]: INFO:
> {1768314358.762089 1949871 1 1 INVITE
> [email protected]} <script>: EVAPIRESPONSE -
> Resumed with RESPONSE ...
>
> Above, we can see that Kamailio sends a request to EVAPI client
> at 1768314358.181325 and response is received by EVAPI client
> at 1768314358.761888, about 600ms later, which is too much!
> On the other hand, EVAPI client takes less than 20ms to receive the
> request, query REST service and reply back to Kamailio.
> If there were anything else between Kamailio and EVAPI client, I would
> probably assume there was some network delay somewhere, but both services
> are running on the same server, which is mostly idle, so no network delay
> can be found.
> I even captured packets with tcpdump , on port 8448, and indeed,
> communications between Kamailio and EVAPI client is like 20 to 30ms max!
> So, why Kamailio is taking between 500ms to 1sec to process the response
> received from EVAPI client? at least, this is what it seems doing....
>
> Any clue? Any advice?
>
> Greatly appreciated.
>
> 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!
>
> --
> Daniel-Constantin Mierla (@ asipto.com)twitter.com/miconda --
> linkedin.com/in/miconda
> Kamailio Consultancy, Training and Development Services -- asipto.com
> Kamailio World Conference, May 7-8, 2026 - Berlin, Germany --
> kamailioworld.com
>
>
__________________________________________________________
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!
