[SR-Users] Kamailio stops processing requests mid script

Joel Serrano joel at textplus.com
Fri Sep 16 16:48:06 CEST 2022


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 <miconda at 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 at 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 at csbc01:~#



Let me know what you think.

Thanks,
Joel.



On Thu, Sep 15, 2022 at 9:50 AM Joel Serrano <joel at 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 <miconda at 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 <joel at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48
>>>>> [343:8614] with clid '
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa' and tags
>>>>> 'as5d31c96b' ''
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa], update_flag
>>>>> is 1024
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at 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 at 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 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_hash.c:356]: destroy_dlg(): removed timer for dlg 0x7ff1b4884b48
>>>>> [343:8614] with clid '
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa' and tags
>>>>> 'as5d31c96b' ''
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_db_handler.c:708]: remove_dialog_from_db(): trying to remove dialog [
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa], update_flag
>>>>> is 1024
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at 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 at 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 at sip02.vozelia.com.pa} dialog
>>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was
>>>>> 5111a7c71ec485e443099844491ef7d8 at sip02.vozelia.com.pa
>>>>> Sep 10 12:30:48 sbc03 sbc[956340]: DEBUG: {1 102 INVITE
>>>>> 5111a7c71ec485e443099844491ef7d8 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20220916/f4632b4a/attachment.htm>


More information about the sr-users mailing list