From miklos@iptel.org Thu Mar 29 11:01:35 2012
From: Miklos Tirpak <miklos@iptel.org>
To: sr-dev@lists.kamailio.org
Subject: Re: [sr-dev] Using t_suspend()/t_continue() multiple times on the
 same transaction
Date: Thu, 29 Mar 2012 11:01:27 +0200
Message-ID: <4F7424E7.1080006@iptel.org>
In-Reply-To: <1332946347.21388.17.camel@pd-laptop-linux>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============1764857869=="

--===============1764857869==
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable

Hi,

I think the problem was in the check made by t_continue() which verifies=20
whether or not a new branch was added, the check ignored the pending=20
"blind UAC", i.e. the new branch added by the subsequent t_suspend().
This explains why the first t_continue() killed the transaction and why=20
after the second t_suspend(). Thanks a lot for the logs!

I have committed a fix into master=20
(9ae149ba25ee6467da1d95dd435995b9a59166a3), could you please try it?

Miklos

On 03/28/2012 04:52 PM, Peter Dunkley wrote:
> Hello again,
>
> I took a quick look at the code in dset.c:append_branch(). This appears
> to update the global variable nr_branches, but the check in
> t_suspend.c:t_continue() is against t->nr_of_outgoings. There are no
> calls into the tm module in the PRESENCE_DISTRIBUTE and PRESENCE_ENQUEUE
> routes except for t_suspend(), so I suspect that the call to
> append_branch() didn't work because the updated nr_branches value was
> not used to update t->nr_of_outgoings. Should this be what happens?
>
> Does this make sense? Is there a simple work-around for this?
>
> Thanks,
>
> Peter
>
> On Wed, 2012-03-28 at 15:30 +0100, Peter Dunkley wrote:
>> Hi,
>>
>> The append_branch() hasn't helped.
>>
>> Having looked a bit more closely, I think what I said at the end of my
>> last email was not quite right.
>>
>> The t_continue() that kills the transaction is actually the first one.
>> However, it only kills the transaction (causing a 500 to be sent)
>> after it has been successfully suspended. What this means is that the
>> second t_continue() seems to manage to resume the transaction (despite
>> it having previously been killed), but at this point the presence APIs
>> go wrong because the transaction cannot be statefully replied to. Here
>> is some log content:
>>
>>     1: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: INFO:
>>     <script>: presence: Found queued transaction [57508:831770136]
>>     2: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: INFO:
>>     <script>: PUBLISH: route[PRESENCE_DISTRIBUTE]
>>     3: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: INFO:
>>     <script>: Adding to queue: presenceWorker4
>>     4: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: WARNING:
>>     <script>: PUBLISH: route[PRESENCE_ENQUEUE]
>>     5: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: INFO:
>>     <script>: Suspended transaction for PUBLISH [57508:831770136]
>>     6: Mar 28 12:02:28 pd-laptop-linux kamailio[16424]: ERROR: tm
>>     [t_suspend.c:223]: branch =3D=3D t->nr_of_outgoings
>>     7: Mar 28 12:02:28 pd-laptop-linux kamailio[16470]: ERROR: pua
>>     [pua_db.c:905]: no rows deleted
>>     8: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: WARNING:
>>     <script>: presenceWorker4: found queued transaction [57508:831770136]
>>     9: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: WARNING:
>>     <script>: PUBLISH: route[PRESENCE]: presenceWorker4
>>     10: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR: tm
>>     [t_reply.c:591]: ERROR: _reply_light: can't generate 200 reply
>>     when a final 500 was sent out
>>     11: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR: sl
>>     [sl.c:270]: failed to reply stateful (tm)
>>     12: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR:
>>     presence [presentity.c:154]: sending reply
>>     13: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR:
>>     presence [presentity.c:400]: sending 200OK
>>     14: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR:
>>     presence [publish.c:487]: when updating presentity
>>     15: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR: tm
>>     [t_reply.c:591]: ERROR: _reply_light: can't generate 500 reply
>>     when a final 500 was sent out
>>     16: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR: sl
>>     [sl.c:270]: failed to reply stateful (tm)
>>     17: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR:
>>     presence [utils_func.c:146]: sending 500 Server Internal Error reply
>>     18: Mar 28 12:02:28 pd-laptop-linux kamailio[16412]: ERROR:
>>     presence [publish.c:517]: failed to send error reply
>>
>> The scenario here is that pua_usrloc sends a PUBLISH to the local
>> Kamailio instance. Line 7 is the pua module handling the 500 response
>> sent by t_continue(). Lines 10 through 18 are presence getting the
>> PUBLISH, handling it properly (updating the DB and so on), but then
>> failing to respond, because a 500 has already been sent for the
>> transaction.
>>
>> Thanks,
>>
>> Peter
>>
>> On Wed, 2012-03-28 at 14:44 +0100, Peter Dunkley wrote:
>>> Hi,
>>>
>>> I am not relaying or replying to messages directly here - except in
>>> the error case. I am using the t_suspend()/t_continue() along with
>>> the presence and RLS APIs. So what I have is the following:
>>>
>>>     #!substdef"!PRESENCE_PROCESS_SLEEP!100000!g"
>>>     modparam("mqueue","mqueue","name=3Dpresence")
>>>     modparam("rtimer","timer","name=3DpresenceMaster;interval=3DPRESENCE_=
PROCESS_SLEEPu;mode=3D1;")
>>>     modparam("rtimer","exec","timer=3DpresenceMaster;route=3DPRESENCE_MAS=
TER_PROCESS")
>>>     modparam("mqueue","mqueue","name=3DpresenceWorker0")
>>>     modparam("rtimer","timer","name=3DpresenceWorker0;interval=3D1u;mode=
=3D1;")
>>>     modparam("rtimer","exec","timer=3DpresenceWorker0;route=3DPRESENCE_WO=
RKER_PROCESS")
>>>     modparam("mqueue","mqueue","name=3DpresenceWorker1")
>>>     modparam("rtimer","timer","name=3DpresenceWorker1;interval=3D1u;mode=
=3D1;")
>>>     modparam("rtimer","exec","timer=3DpresenceWorker1;route=3DPRESENCE_WO=
RKER_PROCESS")
>>>     ...
>>>     modparam("mqueue","mqueue","name=3DpresenceWorkern")
>>>     modparam("rtimer","timer","name=3DpresenceWorkern;interval=3D1u;mode=
=3D1;")
>>>     modparam("rtimer","exec","timer=3DpresenceWorkern;route=3DPRESENCE_WO=
RKER_PROCESS")
>>>     ...
>>>     route {
>>>     	...
>>>     	# Some logic to determine this is a presence request (within or with=
out dialog)
>>>     	$var(queue) =3D"presence";
>>>     	route(PRESENCE_ENQUEUE);
>>>     	...
>>>     }
>>>     ...
>>>     route[PRESENCE_ENQUEUE] {
>>>                     xlog("L_WARN","$rm: route[PRESENCE_ENQUEUE]\n");
>>>
>>>                     if (!t_suspend()) {
>>>                                     t_reply("500","Server Internal Error"=
);
>>>                                     xlog("L_ERR","Failed to suspend trans=
action for $rm\n");
>>>                                     exit;
>>>                     }
>>>
>>>                     xlog("L_INFO","Suspended transaction for $rm [$T(id_i=
ndex):$T(id_label)]\n");
>>>
>>>                     if (!mq_add("$var(queue)","$T(id_index)","$T(id_label=
)")) {
>>>                                     t_reply("500","Server Internal Error"=
);
>>>                                     xlog("L_ERR","Failed to queue transac=
tion for $rm [$T(id_index):$T(id_label)] on $var(queue)\n");
>>>                                     exit;
>>>                     }
>>>
>>>                     exit;
>>>     }
>>>
>>>     route[PRESENCE_MASTER_PROCESS] {
>>>                     xlog("L_INFO","Running PRESENCE_MASTER_PROCESS\n");
>>>
>>>                     while (mq_fetch("presence")) {
>>>                                     $var(id_index) =3D (int) $mqk(presenc=
e);
>>>                                     $var(id_label) =3D (int) $mqv(presenc=
e);
>>>                                     xlog("L_INFO","presence: Found queued=
 transaction [$var(id_index):$var(id_label)]\n");
>>>                                     t_continue("$var(id_index)","$var(id_=
label)","PRESENCE_DISTRIBUTE");
>>>                     }
>>>     }
>>>
>>>     route[PRESENCE_DISTRIBUTE] {
>>>                     xlog("L_WARN","$rm: route[PRESENCE_DISTRIBUTE]\n");
>>>
>>>                     # Some algorithm to distribute traffic across queues.=
..
>>>     	# Perhaps on request type (so we have a NOTIFIER that
>>>     	# sends NOTIFY requests in order), perhaps on some form
>>>     	# of hash...    I am experimenting with this...
>>>                     $var(queue) =3D"presenceWorker"  + $var(queue_number);
>>>                     xlog("L_INFO","Adding to queue: $var(queue)\n");
>>>                     route(PRESENCE_ENQUEUE);
>>>     }
>>>
>>>     route[PRESENCE_WORKER_PROCESS] {
>>>                     lock("pres");
>>>                     $var(pres) =3D $shv(pres);
>>>                     $shv(pres) =3D $shv(pres) + 1;
>>>                     unlock("pres");
>>>
>>>                     $var(queue) =3D"presenceWorker"  + $var(pres);
>>>                     xlog("L_WARN","Starting process: $var(queue) (pid: $p=
p)\n");
>>>
>>>                     while (1) {
>>>                                     while (mq_fetch($var(queue))) {
>>>                                                     $var(id_index) =3D (i=
nt) $mqk($var(queue));
>>>                                                     $var(id_label) =3D (i=
nt) $mqv($var(queue));
>>>                                                     xlog("L_WARN","$var(q=
ueue): found queued transaction [$var(id_index):$var(id_label)]\n");
>>>                                                     t_continue("$var(id_i=
ndex)","$var(id_label)","PRESENCE");
>>>                                     }
>>>                                     usleep(PRESENCE_PROCESS_SLEEP);
>>>                     }
>>>     }
>>>
>>>     route[PRESENCE] {
>>>                     xlog("L_WARN","$rm: route[PRESENCE]: $var(queue)\n");
>>>
>>>                     if (is_method("NOTIFY")) {
>>>                                     xlog("L_INFO","Sending NOTIFY to RLS\=
n");
>>>                                     rls_handle_notify();
>>>                     } else if (is_method("PUBLISH")) {
>>>                                     xlog("L_INFO","Sending PUBLISH to Pre=
sence\n");
>>>                                     handle_publish();
>>>                     } else if (is_method("SUBSCRIBE")) {
>>>                                     xlog("L_INFO","Sending SUBSCRIBE to R=
LS\n");
>>>                                     $var(ret_code) =3D rls_handle_subscri=
be();
>>>                                     if ($var(ret_code) =3D=3D 10) {
>>>                                                     xlog("L_INFO","    SU=
BSCRIBE not for RLS - sending to Presence\n");
>>>                                                     handle_subscribe();
>>>                                     }
>>>                     } else {
>>>                                     xlog("L_ERR","Received non-(NOTIFY|PU=
BLISH|SUBSCRIBE) request from presence queue\n");
>>>                                     t_reply("500","Server Internal Error"=
);
>>>                     }
>>>     	exit;
>>>     }
>>>     ...
>>>
>>>
>>> Previously, I had just a single queue "presence" which all of the
>>> presence worker process took requests from. This meant that
>>> t_suspend()/t_continue() was used just once and this worked (the
>>> presence/RLS APIs respond to the requests statefully). The reason for
>>> doing this in the first place is that I was getting problems with
>>> back-end RLS traffic all using a single TCP connection, which meant
>>> all the back-end presence requests were being handled by the same
>>> Kamailio process, which caused a bottleneck (using UDP causes a
>>> different set of problems under load and isn't really an option).
>>> Although the queue is a FIFO the fact that different processes could
>>> take different amounts of time means that things were happening out
>>> of order (Klaus and Anca have had a discussion about just this kind
>>> of issue with presence on the mailing list recently) and this is
>>> causing me problems.
>>>
>>> What I have now (above) is presence requests being pulled from the
>>> TCP buffer and suspended as quickly as possible. A presenceMaster
>>> process then dequeues the request (continues it), performs some
>>> analysis to determine which worker should deal with it, and then
>>> suspends it again queuing it for the right worker. All of this works
>>> up until the t_continue() for the worker (in the
>>> PRESENCE_WORKER_PROCESS) is called. At this point the transaction is
>>> killed.
>>>
>>> What I can't understand is why the first t_suspend()/t_continue()
>>> works here, but the second fails. My previous version of this (with
>>> the single queue and single t_suspend()/t_continue() call) worked
>>> fine, but it seems that the sequence of t_suspend(), t_continue(),
>>> t_suspend(), t_continue() - with no changes to or handling of the
>>> request in-between - fails.
>>>
>>> Thanks,
>>>
>>> Peter
>>>
>>>
>>> On Wed, 2012-03-28 at 15:13 +0200, Miklos Tirpak wrote:
>>>> Peter,
>>>>
>>>> t_suspend() and t_continue() should work multiple times as long as they
>>>> are executed sequentially after each other, i.e. there cannot be two
>>>> branches suspended at the same time.
>>>>
>>>> The error you get means to me that t_continue() executed the specified
>>>> route block, but in that route, the request was neither replied nor a
>>>> new branch was added. Hence, the transaction is hanging in memory and
>>>> the module sees no pending branch that could return a reply later.
>>>>
>>>> Make sure that in the route block executed by t_continue() there is
>>>> either a t_reply() or you append a new branch and forward it with
>>>> t_relay() (or append a new branch and call t_suspend() again). I think
>>>> you also need to handle the failure of t_relay() and explicitly call
>>>> t_reply() when t_relay() fails in this route.
>>>>
>>>> Regards,
>>>> Miklos
>>>>
>>>> On 03/28/2012 02:21 PM, Daniel-Constantin Mierla wrote:
>>>> >  Hello,
>>>> >
>>>> >  I have been using it only once and didn't looked much deeper into the=
 code.
>>>> >
>>>> >  Maybe Miklos (cc-ed) can give faster more details, afaik he is the
>>>> >  developer of that piece.
>>>> >
>>>> >  Cheers,
>>>> >  Daniel
>>>> >
>>>> >  On 3/28/12 1:13 PM, Peter Dunkley wrote:
>>>> >>  Hi,
>>>> >>
>>>> >>  I am trying to use t_suspend()/t_continue() multiple times on the sa=
me
>>>> >>  transaction. Calling t_suspend() more than once works, but the second
>>>> >>  time I call t_continue() the transaction is killed and a 500 response
>>>> >>  is sent. It is the"if (branch =3D=3D t->nr_of_outgoings)"  check fro=
m the
>>>> >>  code fragment below (from t_suspend.c:t_continue()) that results in
>>>> >>  the transaction being killed - you can see the debug/error line I
>>>> >>  added to determine this in the fragment.
>>>> >>
>>>> >>  Is using t_suspend()/t_continue() multiple times something that shou=
ld
>>>> >>  work?
>>>> >>
>>>> >>  Thanks,
>>>> >>
>>>> >>  Peter
>>>> >>
>>>> >>  if (t->uas.status<  200) {
>>>> >>  /* No final reply has been sent yet.
>>>> >>  * Check whether or not there is any pending branch.
>>>> >>  */
>>>> >>  for ( branch =3D 0;
>>>> >>  branch<  t->nr_of_outgoings;
>>>> >>  branch++
>>>> >>  ) {
>>>> >>  if ((t->uac[branch].request.buffer !=3D NULL)
>>>> >>  &&  (t->uac[branch].last_received<  200)
>>>> >>  )
>>>> >>  break;
>>>> >>  }
>>>> >>
>>>> >>  if (branch =3D=3D t->nr_of_outgoings) {
>>>> >>  /* There is not any open branch so there is
>>>> >>  * no chance that a final response will be received. */
>>>> >>  ret =3D 0;
>>>> >>  LM_ERR("branch =3D=3D t->nr_of_outgoings\n");
>>>> >>  goto kill_trans;
>>>> >>  }
>>>> >>  }
>>>> >>
>>>> >>  --
>>>> >>  Peter Dunkley
>>>> >>  Technical Director
>>>> >>  Crocodile RCS Ltd
>>>> >>
>>>> >>
>>>> >>
>>>> >>  _______________________________________________
>>>> >>  sr-dev mailing list
>>>> >>  sr-dev(a)lists.sip-router.org  <mailto:sr-dev(a)lists.sip-router.org>
>>>> >>  http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>>>> >
>>>> >  --
>>>> >  Daniel-Constantin Mierla
>>>> >  Kamailio Advanced Training, April 23-26, 2012, Berlin, Germany
>>>> >  http://www.asipto.com/index.php/kamailio-advanced-training/
>>>> >
>>>
>>> _______________________________________________
>>> sr-dev mailing list
>>> sr-dev(a)lists.sip-router.org  <mailto:sr-dev(a)lists.sip-router.org>
>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>>>
>> _______________________________________________
>> sr-dev mailing list
>> sr-dev(a)lists.sip-router.org  <mailto:sr-dev(a)lists.sip-router.org>
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>>
> --
> Peter Dunkley
> Technical Director
> Crocodile RCS Ltd
>


--===============1764857869==--