Hi Daniel, So after a lot of digging, this is my finding so far:
Chronology: current Kamailio v5.5.2 - everything works update to Kamailio v5.6.1 - issue begins downgrade to Kamailio v5.5.4 - issue continues That got me triggered, so I added a lot of debug logs to see where I was getting stuck. the last point in the script I get to is something similar to: if(route(ABC)) { ... do stuff ... } Having: route[ABC] { if(condition) { return(1); } else { return(0); } } Right after doing the route(ABC) the call ends. I've done a diff from 5.5.2 to 5.5.4 and I think this commit could be related: https://github.com/kamailio/kamailio/commit/b149906e3c0558fd9cb866d39b36f180efaef656 @Daniel-Constantin Mierla <mico...@gmail.com> any tips? Do I need to rework my config and stop using the logic were a child route can return(1) or return(0) to parent route? I think that when I return(0) effectively the call is ending. I don't see kamailio v5.5.2 in the repo any more are they available? I could downgrade to 5.5.2 to confirm this 100%, but I think I'm finally getting to the root cause. root@csbc01:~# apt-cache policy kamailio kamailio: Installed: 5.5.4+bpo10 Candidate: 5.5.4+bpo10 Version table: *** 5.5.4+bpo10 500 500 http://deb.kamailio.org/kamailio55 buster/main amd64 Packages 100 /var/lib/dpkg/status 5.2.1-1 500 500 http://ftp.us.debian.org/debian buster/main amd64 Packages root@csbc01:~# Let me know what you think. Thanks, Joel. On Thu, Sep 15, 2022 at 9:50 AM Joel Serrano <j...@textplus.com> wrote: > 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 <mico...@gmail.com> > 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 <j...@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 < >>> mico...@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 <j...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} <script>: No >>>>> matching rewrite rules for '67339924' found >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: exec: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48 >>>>> [343:8614] with clid ' >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa' and tags >>>>> 'as5d31c96b' '' >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [ >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa], update_flag >>>>> is 1024 >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48 >>>>> [343:8614] with clid ' >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa' and tags >>>>> 'as5d31c96b' '' >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [ >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa], update_flag >>>>> is 1024 >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa} dialog >>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was >>>>> 5111a7c71ec485e443099844491ef...@sip02.vozelia.com.pa >>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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 >>>>> 5111a7c71ec485e443099844491ef...@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@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 >> >>
__________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions * sr-users@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