Hello,
if the traffic is over UDP, the Kamailio workers were blocked in
recvfrom(), meaning that nothing is passed from the network layer to them.
If you see UDP packets coming to Kamailio via ngrep/sngrep/..., then is the
OS that drops them via firewall or some other app that controls the network
traffic.
Cheers,
Daniel
On 15.09.22 07:37, Joel Serrano wrote:
Hi Daniel,
I've tried with apparmor disabled unfortunately the same issue happens.
I've sent you privately the output of the kamctl trap. I personally don't
think it's Kamailio's fault per se, this is on a standard debian 11. I'm
just lost and don't really understand what the hell is going on.
Thanks, I appreciate your help with this.
Joel.
On Wed, Sep 14, 2022 at 9:50 AM Joel Serrano <joel(a)textplus.com> wrote:
Hi Daniel,
I've followed your suggestions and compared this "bad" server with the
two "good" ones.
- Pike:
In all cases we have:
if (src_ip!=myself && !ds_is_from_list()) {
if($sht(ipban=>$si)!=$null) {
xlog("L_ALERT","ALERT: blocked by pike R=$ru from $fu
(IP:$si:$sp)\n");
exit;
}
if (!pike_check_req()) {
xlog("L_ALERT","ALERT: pike blocking R=$ru from $fu
(IP:$si:$sp)\n");
$sht(ipban=>$si) = 1;
exit;
}
}
And we are not seeing any logs, therefore I'm discarding pike.
- Firewall:
I checked all 3 servers, and none of them have -local- firewall policies.
- conntrack:
All 3 servers have nf_conntrack loaded in kernel.
- selinux/etc:
The two good servers have "AppArmor" disabled.
The bad server has "AppArmor" enabled. !!!!!!!!!!!!!! <---------- I'm
hoping this could be the cause and I'm going to test tonight without it.
Thanks for checking this, I was so lost I actually went ahead and did
"kamctl trap" last night too just in case. When I run it, it didn't stop
by
itself (I stopped it with CTRL+C after some time) but it did generate a
file with a lot of output. Can I send you it privately? I'm not sure how to
interpret it.
Before anything I'm going to test tonight:
1- disabling apparmor
2- unloading nf_conntrack
I'll report back with the resutls.
On Wed, Sep 14, 2022 at 5:27 AM Daniel-Constantin Mierla <
miconda(a)gmail.com> wrote:
> Hello,
>
> be sure you do not hit some limits set by Kamailio (e.g., pike) or the
> system/firewall (e.g., selinux, conntrack).
>
> You should install gdb and run "kamctl trap" when it stops processing
> and inspect the written file to see where each kamailio process is in the
> execution stack.
>
> Cheers,
> Daniel
> On 14.09.22 10:20, Joel Serrano wrote:
>
> Bumping this! Any comments? Or suggestions on what to check? I'm feeling
> it has to be something stupid but I can't see it :(
>
>
> On Sun, Sep 11, 2022 at 12:56 AM Joel Serrano <joel(a)textplus.com> wrote:
>
>> Hello,
>>
>> I have a cluster of 2 kamailios v5.5 on debian 9 working flawlessly.
>>
>> We have added a third node, also on v5.5 but debian 11. Kamailio
>> doesn't work correctly for some reason that I'm not seeing.
>>
>> The symptoms are:
>>
>> 1- Kamailio receives INVITEs and starts to process them per routing
>> script.
>> 2- There is a specific place where something happens and the calls are
>> dropped (Kamailio is not even replying to the source). Note that the config
>> is exactly the same on all 3 servers, only one of the three is having the
>> issue.
>>
>> I enabled debug logs and I could see:
>>
>> [...]
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.example.com} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[GET_OUTBOUND_API_DATA]
>> c=[/etc/kamailio/sbc/api.cfg] l=61 a=5 n=route
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.example.com} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=211 a=26 n=xlog
>> Sep 10 12:30:48 sbc03 sbc[956340]: INFO: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <script>:
>> Applying local to toll-free rewrite rules on callee number using dpid
'20'
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=212 a=63 n=assign
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=219 a=16 n=if
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=213 a=26 n=dp_translate
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dialplan.c:237]: dp_get_ivalue(): searching 15
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dialplan.c:245]: dp_get_ivalue(): dpid is 20 from pv argument
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dialplan.c:254]: dp_get_svalue(): searching 15
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dialplan.c:350]: dp_translate_f(): input is 67339924
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:605]: dp_translate_helper(): regex operator testing over
>> [67339924]
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dp_repl.c:676]: dp_translate_helper(): no matching rule
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialplan
>> [dialplan.c:354]: dp_translate_f(): could not translate 67339924 with dpid
>> 20
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=217 a=26 n=xlog
>> Sep 10 12:30:48 sbc03 sbc[956340]: INFO: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <script>: No
>> matching rewrite rules for '67339924' found
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=218 a=2 n=return
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/receive.c:514]: receive_msg(): request-route executed in: 12245 usec
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:785]: dlg_lookup_mode(): ref dlg 0x7ff1b4884b48 with 1 -> 2
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:789]: dlg_lookup_mode(): dialog id=8614 found on entry 343
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_var.c:63]: dlg_cfg_cb(): new dialog with no transaction after config
>> execution
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1091]: dlg_unref_helper(): unref op on 0x7ff1b4884b48 with 1
>> from dlg_hash.c:1109
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): unref dlg 0x7ff1b4884b48 with 1 -> 1
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1091]: dlg_unref_helper(): unref op on 0x7ff1b4884b48 with 1
>> from dlg_hash.c:1109
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): unref dlg 0x7ff1b4884b48 with 1 -> 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): ref <=0 for dialog 0x7ff1b4884b48
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:345]: destroy_dlg(): destroying dialog 0x7ff1b4884b48 (ref 0)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48
>> [343:8614] with clid '
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa' and tags
>> 'as5d31c96b' ''
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa], update_flag is
>> 1024
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [db_query.c:72]: db_do_submit_query(): submitted query: delete from
>> `dialog` where `hash_entry`=343 AND `hash_id`=8614, result 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [db_query.c:72]: db_do_submit_query(): submitted query: delete from
>> `dialog_vars` where `hash_entry`=343 AND `hash_id`=8614, result 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list 0x7ff1b4880370
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/receive.c:606]: receive_msg(): cleaning up
>>
>> If I go to line 61 from route GET_OUTBOUND_API_DATA, I have this:
>>
>> if(route(APPLY_REWRITE_RULE)) {
>> $rU = $var(dp_user);
>> $avp(icx_real_number) = $var(dp_user);
>> }
>>
>> The very next thing is:
>>
>> # Query API
>> $avp(apiUrl) = "{{ call_api_url }}/outbound/" +
>> $avp(icx_src_number) + "/" + $avp(icx_real_number);
>> http_client_query("$avp(apiUrl)",
"$avp(apiResponseBody)");
>> $avp(apiResponseCode) = $rc;
>>
>> I see the GET_OUTBOUND_API_DATA route calling APPLY_REWRITE_RULE, and
>> APPLY_REWRITE_RULE returning correctly then finished:
>>
>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} ***
>> cfgtrace:dbg_cfg_trace(): request_route=[APPLY_REWRITE_RULE]
>> c=[/etc/kamailio/sbc/extras.cfg] l=218 a=2 n=return
>>
>> But then Kamailio is apparently just tearing down the call and ending
>> it.
>>
>> Can someone help me understand what this part of the logs means or what
>> can be causing them?
>>
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/receive.c:514]: receive_msg(): request-route executed in: 12245 usec
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:785]: dlg_lookup_mode(): ref dlg 0x7ff1b4884b48 with 1 -> 2
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:789]: dlg_lookup_mode(): dialog id=8614 found on entry 343
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_var.c:63]: dlg_cfg_cb(): new dialog with no transaction after config
>> execution
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1091]: dlg_unref_helper(): unref op on 0x7ff1b4884b48 with 1
>> from dlg_hash.c:1109
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): unref dlg 0x7ff1b4884b48 with 1 -> 1
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1091]: dlg_unref_helper(): unref op on 0x7ff1b4884b48 with 1
>> from dlg_hash.c:1109
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): unref dlg 0x7ff1b4884b48 with 1 -> 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:1095]: dlg_unref_helper(): ref <=0 for dialog 0x7ff1b4884b48
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:345]: destroy_dlg(): destroying dialog 0x7ff1b4884b48 (ref 0)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48
>> [343:8614] with clid '
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa' and tags
>> 'as5d31c96b' ''
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa], update_flag is
>> 1024
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [db_query.c:72]: db_do_submit_query(): submitted query: delete from
>> `dialog` where `hash_entry`=343 AND `hash_id`=8614, result 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [db_query.c:72]: db_do_submit_query(): submitted query: delete from
>> `dialog_vars` where `hash_entry`=343 AND `hash_id`=8614, result 0
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} dialog
>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list 0x7ff1b4880370
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>> 5111a7c71ec485e443099844491ef7d8(a)sip02.vozelia.com.pa} <core>
>> [core/receive.c:606]: receive_msg(): cleaning up
>>
>> I can see it's related to the dialogs, but is this a cause or a
>> consequence? I have checked the API access logs, and Kamailio doesn't get
>> to send the request, I've also noticed that normally Kamailio replies with
>> a 100-Trying almost instantly, in the case of this server I don't see a
>> single 100-Trying from Kamailio.
>>
>> I'm pretty lost here so any tips are more than welcome.
>>
>> NOTE: I tried with debian11 + Kamailio 5.6 and the same issue happens
>> too.
>>
>>
>> Thanks,
>> Joel.
>>
>>
>>
>>
> __________________________________________________________
> 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
>
> --
> Daniel-Constantin Mierla --
www.asipto.comwww.twitter.com/miconda --
www.linkedin.com/in/miconda
>
> --