Re: [SR-Users] Kamailio stops processing requests mid script

In sngrep I do see the the INVITEs coming in, I’ll check more on the OS side and see what I can find. Again, thanks for checking! I’ll follow up with what I find. On Thu, Sep 15, 2022 at 09:16 Daniel-Constantin Mierla &lt;miconda(a)gmail.com&gt; wrote: > 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 &lt;joel(a)textplus.com&gt; 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&gt; 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 &lt;joel(a)textplus.com&gt; >>> 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&#39; 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&#39; 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 >>> >>> -- > Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda > >