[SR-Users] tsilo - failure to add branches (-1)
Jurijs Ivolga
jurijs.ivolga at gmail.com
Thu Nov 5 11:54:13 CET 2020
Hi Federico,
In my Kamailio "append_branches" was set to 0 long time ago and this was a
legacy that I needed to deal with. After removing "modparam("registrar",
"append_branches", 0)" and fixing config everything worked. Thank you again!
Jurijs
On Thu, Nov 5, 2020 at 12:51 PM Federico Cabiddu <federico.cabiddu at gmail.com>
wrote:
> Good to know that you solved it :)
> Why did you have to set "append_branches" to 0? Which was the behaviour
> when enabling it?
>
> Cheers,
>
> Federico
>
> On Tue, Nov 3, 2020 at 6:51 PM Jurijs Ivolga <jurijs.ivolga at gmail.com>
> wrote:
>
>> Hi Federico,
>>
>> First of all, thank you a lot for helping me. This means a lot to me!!!!
>> This is true open source spirit!!!
>>
>> So indeed I had messed up config and I was saving transactions
>> incorrectly and that why you saw 2 call IDs.
>>
>> I updated my config and now I do save transactions correctly and it
>> works! I would like to add that I needed to update Registrar settings too:
>>
>> modparam("registrar", "append_branches", 0) -- this was messing with my
>> config too. I needed to disable it to make it work.
>>
>> Thank you again!!!!
>>
>> Jurijs
>>
>>
>> On Tue, Nov 3, 2020 at 12:55 PM Federico Cabiddu <
>> federico.cabiddu at gmail.com> wrote:
>>
>>> Hi Jurijs,
>>> I had a look at the logs but they are confusing: looks like there are
>>> two calls (transactions) stored by tsilo and the ts_append is called only
>>> for one.
>>> In the logs you sent:
>>> 1) row 19: an INVITE comes with callid
>>> 9741c821-93b2-1239-0599-024233fefdc7
>>> 2) row 60: since there is no contact the transaction is
>>> suspended (transaction hash:id=9467:1575872173)
>>> 3) row 132: a REGISTER is received from the user for which the
>>> transaction was suspended
>>> 4) row 193 onward: the transaction 9467:1575872173 is resumed, the
>>> INVITE is sent out and the transaction stored by tsilo
>>> 5) row 262: another REGISTER from the same instance (same sip.instance
>>> and received) is received
>>> 6) ts_append is called but the transaction hash:id is 16864:783220347
>>> and the callid is 3ed4a6c3051ea46b50487a0d1b5b25ec at 10.10.0.0: when has
>>> this transaction been stored? I couldn't find anywhere in the logs
>>> Which version of kamailio are you using?
>>> Are you setting the "use_domain" tsilo parameter?
>>> First I'd suggest trying to call ts_store specifying the r-uri, as you
>>> do for ts_append.
>>> Then could you please retry the scenario being sure that there is only
>>> one transaction stored?
>>> Thank you,
>>>
>>> Federico
>>>
>>>
>>>
>>>
>>> On Sat, Oct 31, 2020 at 5:16 PM Jurijs Ivolga <jurijs.ivolga at gmail.com>
>>> wrote:
>>>
>>>> Hi,
>>>>
>>>> Any ideas regarding "t_append_branches(): failure to add branches (-1)"?
>>>>
>>>> Is there a way somehow to dump what ts_append handover towards tm? I
>>>> think if I would be able to see this I will be able to understand what is
>>>> wrong. I tried tm:local-request and failure route and branch route, but
>>>> these routes are not executed when this error happens.
>>>>
>>>> Maybe the issue is that the TLS connection is established between
>>>> Kamailio and UAC what is in front my Register and this Register kamailio
>>>> just tries to connect directly towards UAC and it fails? At least this is
>>>> my idea why this might fail.
>>>>
>>>> Jurijs
>>>>
>>>>
>>>> On Thu, Oct 29, 2020 at 8:38 AM Jurijs Ivolga <jurijs.ivolga at gmail.com>
>>>> wrote:
>>>>
>>>>> Hi Federico,
>>>>>
>>>>> Indeed I had a messed up config at that point. I cleaned it up, but
>>>>> still had the same problem.
>>>>>
>>>>> Full log in attachment.
>>>>>
>>>>> Here is some part of it:
>>>>>
>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} tsilo [ts_append.c:72]:
>>>>>> ts_append(): transaction 16864:783220347 found for
>>>>>> sip:1443452187102-0af7c6035717-0001 at voipstaging.myappapp.net, going
>>>>>> to append branches
>>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} tm [t_lookup.c:1612]:
>>>>>> t_lookup_ident_filter(): transaction found
>>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} registrar [lookup.c:306]:
>>>>>> lookup_helper(): contact for [1443452187102-0af7c6035717-0001] found by
>>>>>> address
>>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} tm [t_append_branches.c:77]:
>>>>>> t_append_branches(): transaction 16864:783220347 in status 180
>>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} tm [t_append_branches.c:99]:
>>>>>> t_append_branches(): Call 3ed4a6c3051ea46b50487a0d1b5b25ec at 10.10.0.0:
>>>>>> 1 (0) outgoing branches
>>>>>> 45(51) DEBUG: {1 21 REGISTER 6z~FzexPro} tm
>>>>>> [t_append_branches.c:163]: t_append_branches(): Call
>>>>>> 3ed4a6c3051ea46b50487a0d1b5b25ec at 10.10.0.0: 1 (0) outgoing branches
>>>>>> after clear_branches()
>>>>>> 45(51) ERROR: {1 21 REGISTER 6z~FzexPro} tm
>>>>>> [t_append_branches.c:172]: *t_append_branches(): failure to add
>>>>>> branches (-1)*
>>>>>> 45(51) INFO: {1 21 REGISTER 6z~FzexPro} <script>: tsilo appending
>>>>>> branch sip:1443452187102-0af7c6035717-0001 at voipstaging.myappapp.net
>>>>>>
>>>>>
>>>>> Here Kamailio snippets of config:
>>>>> ...........................................................
>>>>> route[CONTINUE] {
>>>>> if (!is_method("REGISTER"))
>>>>> return;
>>>>> $var(pjoin) = 0;
>>>>> lock("$tU");
>>>>> $var(pjoin) = $sht(pmap=>join::$tU);
>>>>> $var(pstored) = $sht(pmap=>stored::$tU);
>>>>> xlog("L_INFO", "===== Stored 1 not stored 0 $var(pstored)
>>>>> [$sht(pmap=>stored::$tU)] \n");
>>>>> $sht(pmap=>join::$tU) = $null;
>>>>> unlock("$tU");
>>>>> if($var(pjoin)==0) {
>>>>> if ($var(pstored)) {
>>>>> if($expires(min)>0) {
>>>>> ts_append("location", "sip:$
>>>>> tU at voipstaging.onoffapp.net");
>>>>> xlog("L_INFO","tsilo appending branch
>>>>> $tu \n");
>>>>> }
>>>>> }
>>>>> return;
>>>>> }
>>>>> $var(id_index) = $(var(pjoin){s.select,0,:}{s.int});
>>>>> $var(id_label) = $(var(pjoin){s.select,1,:}{s.int});
>>>>> xlog("L_INFO", "===== resuming suspended trasaction
>>>>> [$var(id_index):$var(id_label)] $tU ($var(pjoin)) \n");
>>>>> t_continue("$var(id_index)", "$var(id_label)", "LOCATION");
>>>>> }
>>>>> ...........................................................
>>>>> if (is_method("INVITE")) {
>>>>> ts_store();
>>>>> $sht(pmap=>stored::$rU) = 1;
>>>>> xlog("L_ERR" ,"stored transaction
>>>>> [$T(id_index):$T(id_label)] $fU => $rU\n");
>>>>> }
>>>>> ...........................................................
>>>>>
>>>>> Jurijs
>>>>>
>>>>>
>>>>> On Wed, Oct 28, 2020 at 9:09 AM Federico Cabiddu <
>>>>> federico.cabiddu at gmail.com> wrote:
>>>>>
>>>>>> Hi Jurijs,
>>>>>> I had a look at the logs and there is something strange: I see the
>>>>>> ts_append logs before the registrar module ones (the save function).
>>>>>> Are you sure you are calling ts_append after calling save()?
>>>>>>
>>>>>> Cheers,
>>>>>>
>>>>>> Federico
>>>>>>
>>>>>> On Tue, Oct 27, 2020 at 10:26 AM Jurijs Ivolga <
>>>>>> jurijs.ivolga at gmail.com> wrote:
>>>>>>
>>>>>>> Hi Daniel-Constantin,
>>>>>>>
>>>>>>> Debug log is intachment. Do you see any hints?
>>>>>>>
>>>>>>> I think this is relative part:
>>>>>>>
>>>>>>> 2020-10-27T08:24:36.198Z,"79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tsilo [ts_append.c:72]: ts_append(): transaction 21280:984985415 found for
>>>>>>>> sip:1443452187102-0af7c6035717-0001 at voipstaging.myapp.net, going
>>>>>>>> to append branches"
>>>>>>>> 2020-10-27T08:24:36.198Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [lookup.c:306]: lookup_helper(): contact for
>>>>>>>> [1443452187102-0af7c6035717-0001] found by address
>>>>>>>> 2020-10-27T08:24:36.198Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_lookup.c:1612]: t_lookup_ident_filter(): transaction found
>>>>>>>> 2020-10-27T08:24:36.199Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:77]: t_append_branches(): transaction
>>>>>>>> 21280:984985415 in status 180
>>>>>>>> 2020-10-27T08:24:36.199Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:99]: t_append_branches(): Call
>>>>>>>> 88cc06a544ba41a8aee5035c437baabf at 0.0.0.0: 1 (0) outgoing branches
>>>>>>>> 2020-10-27T08:24:36.205Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:163]: t_append_branches(): Call
>>>>>>>> 88cc06a544ba41a8aee5035c437baabf at 0.0.0.0: 1 (0) outgoing branches
>>>>>>>> after clear_branches()
>>>>>>>> 2020-10-27T08:24:36.206Z,"79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tsilo [ts_append.c:72]: ts_append(): transaction 38832:1600293484 found for
>>>>>>>> sip:1443452187102-0af7c6035717-0001 at voipstaging.myapp.net, going
>>>>>>>> to append branches"
>>>>>>>> 2020-10-27T08:24:36.206Z,79(85) ERROR: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:172]:* t_append_branches(): failure to add
>>>>>>>> branches (-1)*
>>>>>>>> 2020-10-27T08:24:36.207Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [lookup.c:306]: lookup_helper(): contact for
>>>>>>>> [1443452187102-0af7c6035717-0001] found by address
>>>>>>>> 2020-10-27T08:24:36.207Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:77]: t_append_branches(): transaction
>>>>>>>> 38832:1600293484 in status 180
>>>>>>>> 2020-10-27T08:24:36.207Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_lookup.c:1612]: t_lookup_ident_filter(): transaction found
>>>>>>>> 2020-10-27T08:24:36.208Z,79(85) ERROR: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:172]: t_append_branches(): failure to add branches
>>>>>>>> (-1)
>>>>>>>> 2020-10-27T08:24:36.208Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:99]: t_append_branches(): Call
>>>>>>>> aac9c351-92d0-1239-0599-024233fefdc7: 2 (0) outgoing branches
>>>>>>>> 2020-10-27T08:24:36.208Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> tm [t_append_branches.c:163]: t_append_branches(): Call
>>>>>>>> aac9c351-92d0-1239-0599-024233fefdc7: 2 (0) outgoing branches after
>>>>>>>> clear_branches()
>>>>>>>> 2020-10-27T08:24:36.209Z,79(85) INFO: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> <script>: tsilo appending branch
>>>>>>>> sip:1443452187102-0af7c6035717-0001 at voipstaging.myapp.net
>>>>>>>> 2020-10-27T08:24:36.217Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> <core> [core/strutils.c:215]: unescape_user(): unescaped string is
>>>>>>>> <sip:192.168.173.107:55982;transport=tls>
>>>>>>>> 2020-10-27T08:24:36.218Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [path.c:116]: build_path_vector(): path is <<sip:
>>>>>>>> ingress1dev.myapp.net;lr;received=sip:192.168.173.107:55982
>>>>>>>> %3Btransport%3Dtls>>
>>>>>>>> 2020-10-27T08:24:36.218Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [path.c:108]: build_path_vector(): received is
>>>>>>>> <sip:192.168.173.107:55982;transport=tls>
>>>>>>>> 2020-10-27T08:24:36.218Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [save.c:314]: pack_ci(): set
>>>>>>>> instance[<urn:uuid:2a56856a-fae5-00f6-8f3b-2d9283f533be>]
>>>>>>>> 2020-10-27T08:24:36.219Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> <core> [sruid.c:182]: sruid_next(): new sruid is [uloc-5f97d8f4-55-1] (1 /
>>>>>>>> 18)
>>>>>>>> 2020-10-27T08:24:36.219Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [save.c:410]: pack_ci(): generated ruid is: uloc-5f97d8f4-55-1
>>>>>>>> 2020-10-27T08:24:36.220Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [save.c:410]: pack_ci(): generated ruid is: uloc-5f97d8f4-55-2
>>>>>>>> 2020-10-27T08:24:36.220Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> <core> [sruid.c:182]: sruid_next(): new sruid is [uloc-5f97d8f4-55-2] (2 /
>>>>>>>> 18)
>>>>>>>> 2020-10-27T08:24:36.220Z,"79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> registrar [reply.c:377]: build_contact(): created Contact HF: Contact:
>>>>>>>> <sip:1443452187102-0af7c6035717-0001 at 192.168.173.107:55982
>>>>>>>> ;transport=tls>;q=1;expires=120;received=""sip:192.168.173.107:55982
>>>>>>>> ;transport=tls"";+sip.instance=""<urn:uuid:2a56856a-fae5-00f6-8f3b-2d9283f533be>"""
>>>>>>>> 2020-10-27T08:24:36.227Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> cfgutils [cfgutils.c:724]: cfg_lock_helper(): cfg_lock mode 0 on 54
>>>>>>>> (1443452187102-0af7c6035717-0001)
>>>>>>>> 2020-10-27T08:24:36.228Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> htable [ht_var.c:89]: pv_set_ht_cell(): set value for
>>>>>>>> $sht(pmap=>join::1443452187102-0af7c6035717-0001)
>>>>>>>> 2020-10-27T08:24:36.228Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> cfgutils [cfgutils.c:724]: cfg_lock_helper(): cfg_lock mode 1 on 54
>>>>>>>> (1443452187102-0af7c6035717-0001)
>>>>>>>> 2020-10-27T08:24:36.228Z,79(85) DEBUG: {1 21 REGISTER G~qt15Oz7~}
>>>>>>>> <core> [core/receive.c:437]: receive_msg(): request-route executed in: 2293
>>>>>>>> usec
>>>>>>>>
>>>>>>>
>>>>>>> Jurijs
>>>>>>>
>>>>>>>
>>>>>>> On Tue, Oct 27, 2020 at 10:20 AM Daniel-Constantin Mierla <
>>>>>>> miconda at gmail.com> wrote:
>>>>>>>
>>>>>>>> Hello,
>>>>>>>>
>>>>>>>> if you get it always, then run with debug=3 and send all the debug
>>>>>>>> messages here, there should be more hints about why a branch is not added.
>>>>>>>>
>>>>>>>> Cheers,
>>>>>>>> Daniel
>>>>>>>> On 27.10.20 08:40, Jurijs Ivolga wrote:
>>>>>>>>
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> I have several Kamailio proxies - loadbalancer which is used as TLS
>>>>>>>> offload and Authorization server and behind registrar servers.
>>>>>>>>
>>>>>>>> In this case I can't make tsilo work on the registrar server.
>>>>>>>>
>>>>>>>> I'm always getting: "tm [t_append_branches.c:172]:
>>>>>>>> t_append_branches(): failure to add branches (-1)"
>>>>>>>>
>>>>>>>> If I use just one Kamailio which is used as Authorization and
>>>>>>>> Registrar server then tsilo works as expected.
>>>>>>>>
>>>>>>>> Looks like kamailio where I run ts_append tries to connect to UAC
>>>>>>>> directly and not through Loadbalancer.
>>>>>>>>
>>>>>>>> Any ideas? How can I troubleshoot this?
>>>>>>>>
>>>>>>>> Thank you!
>>>>>>>>
>>>>>>>> Jurijs
>>>>>>>>
>>>>>>>> _______________________________________________
>>>>>>>> Kamailio (SER) - Users Mailing Listsr-users at lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>>
>>>>>>>> --
>>>>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda
>>>>>>>> Funding: https://www.paypal.me/dcmierla
>>>>>>>>
>>>>>>>> _______________________________________________
>>>>>>> Kamailio (SER) - Users Mailing List
>>>>>>> sr-users at lists.kamailio.org
>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>
>>>>>> _______________________________________________
>>>>>> Kamailio (SER) - Users Mailing List
>>>>>> sr-users at lists.kamailio.org
>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>
>>>>> _______________________________________________
>>>> Kamailio (SER) - Users Mailing List
>>>> sr-users at lists.kamailio.org
>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>
>>> _______________________________________________
>>> Kamailio (SER) - Users Mailing List
>>> sr-users at lists.kamailio.org
>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>
>> _______________________________________________
>> Kamailio (SER) - Users Mailing List
>> sr-users at lists.kamailio.org
>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>
> _______________________________________________
> Kamailio (SER) - Users Mailing List
> sr-users at lists.kamailio.org
> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20201105/f3792d80/attachment.htm>
More information about the sr-users
mailing list