Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552 FS#296 : tm:branch-failure event_route is not executed on all branch failures

sip-router

Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

SIP Router Project

Tasklist

FS#296 - tm:branch-failure event_route is not executed on all branch failures

Attached to Project: sip-router
Opened by Juha Heinanen (jh) - Wednesday, 15 May 2013, 17:13 GMT
Last edited by Juha Heinanen (jh) - Saturday, 25 May 2013, 11:16 GMT
Task Type Bug Report
Category Module → tm
Status New   Reopened
Assigned To No-one
Operating System All
Severity Medium
Priority Normal
Reported Version Development
Due in Version Undecided
Due Date Undecided
Percent Complete 0%
Votes 0
Private No

Details

when t_relay() fails due to unreachable tcp destination, [t_fwd.c:1520] generates error message

LOG(L_ERR, “ERROR: t_send_branch: sending request on branch %d "

			"failed\n", branch);

and immediately sends back SIP/2.0 477 Unfortunately error on sending to next hop occurred (477/TM) response.

tm:branch-failure event_route is not executed although it has been activated for the branch. instead, this makes is difficult to act on the failing branch in the config script, for example, by unregistering the unresponsive contact.

currently tm:branch-failure event_route is executed only from t_reply.c when reply is processed. one possibility to fix this might be generating a fake reply from t_fwd.c so that t_reply.c could do its job. another one might be calling the activated tm:branch-failure event_route directly from t_fwd.c.

i would appreciate if someone who is familiar with internals of tm module could fix this bug.

This task depends upon

Comment by Daniel-Constantin Mierla (miconda) - Thursday, 16 May 2013, 20:57 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

Just checked a bit and variants can be:
1) execute branch failure route immediately it is discovered a tcp connection is not available, but this means kind of blocking to execute the actions from the branch failure route and then the next branch will be generated
2) add the branch in a dummy timer mode that will trigger a timeout event - there will be no attempt to send it, the branch will be put in a “suspended” state, the rest of the branches will be generated and the timer will end up firing at some point

The 2nd is more like what would happen if the request is sent over udp, from the point of view of timings. This option might be easier to do and should also end up in failure_route execution if all branches fail.

Again, just few thought on quick check, it may need more than that, though.

Comment by Juha Heinanen (jh) - Friday, 17 May 2013, 04:21 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

the second alternative sounds better to me, because it unifies the behavior of tcp and udp failures and also triggers failure route if all branches fail. the timer should trigger as soon as the implementation allows it to happen in order to avoid the long re-transmission wait that we currently have in case of udp failures.

Comment by Daniel-Constantin Mierla (miconda) - Friday, 17 May 2013, 08:54 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

Maybe this timeout value should be set via mod param. Otherwise, it should be the fr_timer value.

Comment by Juha Heinanen (jh) - Friday, 17 May 2013, 10:23 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

currently t_fwd generates “477 sending to next hop failed” immediately, i.e., fr_timer does not apply dead tcp connections. for example, fr_tcp_timer module param would be fine with me. i could then set it to smaller value than fr_timer.

Comment by Juha Heinanen (jh) - Friday, 17 May 2013, 10:43 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

currently i have set fr_timer to 5000 ms. for dead udp destinations it means a few SIP request re-sends before the timer fires. if tcp connection is broken, tm realizes it right away. so it would not make sense in that case to wait 5000 ms. i don’t know if it is possible in the fake reply case to separate dead tcp connection from non-responsive tcp destination. if not, the fr_timer could apply also in case of dead tcp connections.

Comment by Daniel-Constantin Mierla (miconda) - Sunday, 19 May 2013, 13:10 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

With the last commit, tm will consider the branches that failed to be sent for failure routing blocks. At this moment such branch will fail after fr_timer (improvements to be added in the future), reply status code is 408.

However, branch failure route does not seem to be executed for the branches that don’t get the negative reply from the network (e.g., case of local timeout, even for UDP), no branch failure route execution). Didn’t have time to analyze properly, i’ll have to see where Hugh added its execution.

For the moment, the failure_route[] blocks seems to be executed ok.

Note that t_relay() will return true in such case.

To enable this feature, you have to set module parameter failure_exec_mode to 1.

Comment by Daniel-Constantin Mierla (miconda) - Sunday, 19 May 2013, 21:30 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

Commenting here because it’s easier to follow the discussion. You said:

i have xlog info statement in the beginning of both and neither was executed:

The failure route is executed by timer process after fr_timer. Here is what I get:

1(70905) DEBUG: tm [t_fwd.c:1573]: t_send_branch(): t_send_branch: send to 127.0.0.1:10 (2) failed
1(70905) ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
1(70905) ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
...
3(70907) ERROR: <script>: ==== failure route block
3(70907) DEBUG: tm [t_reply.c:1806]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=908

The log error realated to ‘putting branch 0 on hold’ is for debugging purposes, should be made info or dbg – I added to see that the branch is put on timer.

Comment by Juha Heinanen (jh) - Monday, 20 May 2013, 05:18 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

i re-build kamailio from latest master and still in my test branch and normal failure route is not executed by t_relay() to dead tcp destination. i get

May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: INFO: activating contact_failure failure route
May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: INFO: activating contact branch_failure route
May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: INFO: Routing INVITE <sip:jh@192.98.102.10:5044;transport=tcp> to contact via <sip:192.98.102.10:43368;transport=TCP>
May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 20 08:05:21 siika /usr/sbin/sip-proxy[14415]: ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold

the branch is put on hold, but never released from there. using the same config and same destination that registered over udp and then died, both branch and normal failure routes do get executed after fr_timer fires. in tcp case, calling party gets 408 immediately, i.e., kamailio does not wait for fr_timer to fire.

i don’t know what the difference could be. i call t_on_failure(), t_on_branch() and “if (t_relay()) exit;” in route block and t_on_branch_failure() in branch route block.

Comment by Juha Heinanen (jh) - Monday, 20 May 2013, 06:11 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

i added xlog info after t_relay() and got:

May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: INFO: activating contact_failure failure route
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: INFO: activating contact branch_failure route
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: INFO: Routing INVITE <sip:jh@192.98.102.10:5044;transport=tcp> to contact via <sip:192.98.102.10:43560;transport=TCP>
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
May 20 09:08:02 siika /usr/sbin/sip-proxy[15173]: INFO: t_relay() failed

that explains why 408 comes immediately, because i send it from script if t_relay() fails and there are no more contacts left.

what i understood from this commit. t_relay() should not anymore fail if failure and branch failure routes are set when tcp destination is dead, but it does.

Comment by Daniel-Constantin Mierla (miconda) - Monday, 20 May 2013, 15:27 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

I tested again - t_relay() returns 1. I have two invalid branches – here is my config:

request_route {
  xlog("===== main route block\n");
  t_on_failure("x");
  t_on_branch_failure("x");
  set_forward_no_connect();
  # t_relay_to("tcp:127.0.0.1:9");
  $du = "sip:127.0.0.1:9;transport=tcp";
  append_branch();
  $du = "sip:127.0.0.1:10;transport=tcp";
  t_relay();
  $var(rc) = $rc;
  xlog("===== t relay return code: $rc\n");
  exit;
}

failure_route[x] {
	xlog("==== failure route block\n");
	exit;
}

event_route[tm:branch-failure:x] {
	xlog("==== branch failure route block\n");
}

And the logs I get:

1(72046) ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
1(72046) DEBUG: tm [t_fwd.c:1573]: t_send_branch(): t_send_branch: send to 127.0.0.1:10 (2) failed
1(72046) ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
1(72046) ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
1(72046) ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
1(72046) DEBUG: tm [t_fwd.c:1573]: t_send_branch(): t_send_branch: send to 127.0.0.1:9 (2) failed
1(72046) ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 1 failed
1(72046) ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 1 on hold
1(72046) DEBUG: tm [t_funcs.c:384]: t_relay_to(): SER: new transaction fwd’ed
1(72046) ERROR: <script>: ===== t relay return code: 1
1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list 0×0 1(72046) DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list 0×0 1(72046) DEBUG: <core> [receive.c:293]: receive_msg(): receive_msg: cleaning up
...
3(72048) DEBUG: tm [t_reply.c:1289]: t_should_relay_response(): →»»»» T_code=100, new_code=408
3(72048) DEBUG: tm [t_reply.c:1806]: relay_reply(): DEBUG: relay_reply: branch=0, save=1, relay=-1 icode=908
3(72048) DEBUG: tm [t_reply.c:1289]: t_should_relay_response(): →»»»» T_code=100, new_code=408
3(72048) ERROR: <script>: ==== failure route block
3(72048) DEBUG: tm [t_reply.c:1806]: relay_reply(): DEBUG: relay_reply: branch=1, save=0, relay=0 icode=908
3(72048) DEBUG: <core> [msg_translator.c:204]: check_via_address(): check_via_address(127.0.0.1, 192.168.178.8, 0)

Comment by Juha Heinanen (jh) - Monday, 20 May 2013, 16:26 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

i don’t use append_branch and i don’t have corex module in my config and thus cannot test with it. i tested a simpler case, where only $ru and $du are set similar to this:

request_route {
xlog(”===== main route block\n”);
$ru = “sip:foo@bar.com”;
$du = “sip:127.0.0.1:9;transport=tcp”;
t_on_failure(”x”);
t_on_branch_failure(”x”);
set_forward_no_connect();
t_relay();
$var(rc) = $rc;
xlog(”===== t relay return code: $rc\n”);
exit;
}

and got:

May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: INFO: activating failure and branch failure routes
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: ERROR: <core> [tcp_main.c:2781]: tcpconn_1st_send(): connect 127.0.0.1:9 failed (RST) Connection refused
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: ERROR: <core> [tcp_main.c:2791]: tcpconn_1st_send(): 127.0.0.1:9: connect & send for 0x7ff2f7b63030 failed: Connection refused (111)
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
May 20 19:21:56 siika /usr/sbin/sip-proxy[20734]: INFO: t_relay() failed

can you test with the above simpler config and see what you get?

Comment by Juha Heinanen (jh) - Wednesday, 22 May 2013, 16:32 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

it turned out that i had forgotten to include

modparam(”tm”, “failure_exec_mode”, 1)

in my test config. once i included it, both branch failure route and transaction failure route were executed after fr_timer fired.

i’ll therefore close this issue.

it would be nice if it would be possible to get branch failure route executed faster than what fr_timer specifies when tcp connection to the destination is broken.

Comment by Juha Heinanen (jh) - Saturday, 25 May 2013, 11:29 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

unfortunately i need to reopen this task. i started to do more tests and and branch failure route execution is not deterministic. closer examination of daniel’s test output showed that branch failure router was not executed in that test either. attached is complete test config. i use sipsak to send request to it like this:

sipsak -s sip:foo@127.0.0.1:5060

first time i got:

May 25 14:21:23 siika sip-proxy[6697]: ERROR: <script>: ===== main route block
May 25 14:21:23 siika sip-proxy[6697]: ERROR: <script>: ===== after t_newtrans()
May 25 14:21:23 siika sip-proxy[6697]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 25 14:21:23 siika sip-proxy[6697]: ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 25 14:21:23 siika sip-proxy[6697]: ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
May 25 14:21:23 siika sip-proxy[6697]: ERROR: <script>: ===== t relay return code: 1
May 25 14:21:23 siika sip-proxy[6696]: ERROR: <script>: ===== main route block
May 25 14:21:24 siika sip-proxy[6698]: ERROR: <script>: ===== main route block
May 25 14:21:26 siika sip-proxy[6695]: ERROR: <script>: ===== main route block
May 25 14:21:28 siika sip-proxy[6708]: ERROR: <script>: ==== failure route block

that is, branch failure block was not executed.

second time 20 sec later i got:

May 25 14:21:44 siika sip-proxy[6694]: ERROR: <script>: ===== main route block
May 25 14:21:44 siika sip-proxy[6694]: ERROR: <script>: ===== after t_newtrans()
May 25 14:21:44 siika sip-proxy[6694]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 25 14:21:44 siika sip-proxy[6694]: ERROR: tm [t_fwd.c:1592]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 25 14:21:44 siika sip-proxy[6694]: ERROR: tm [t_fwd.c:1595]: t_send_branch(): putting branch 0 on hold
May 25 14:21:44 siika sip-proxy[6694]: ERROR: <script>: ===== t relay return code: 1
May 25 14:21:45 siika sip-proxy[6693]: ERROR: <script>: ===== main route block
May 25 14:21:46 siika sip-proxy[6692]: ERROR: <script>: ===== main route block
May 25 14:21:48 siika sip-proxy[6691]: ERROR: <script>: ===== main route block
May 25 14:21:49 siika sip-proxy[6708]: ERROR: <script>: ==== branch failure route block
May 25 14:21:49 siika sip-proxy[6708]: ERROR: <script>: ==== failure route block

that is, branch failure route block was executed.

– juha

complete config used in test:

loadmodule “pv” loadmodule “xlog”

modparam(”tm”, “fr_timer”, 5000)
modparam(”tm”, “local_ack_mode”, 2)
modparam(”tm”, “failure_reply_mode”, 3)
modparam(”tm”, “failure_exec_mode”, 1)

route {
xlog(”===== main route block\n”);
t_newtran();
xlog(”===== after t_newtrans()\n”);
$ru = “sip:foo@127.0.0.1:9;transport=tcp”;
t_on_failure(”x”);
t_on_branch_failure(”x”);
set_forward_no_connect();
t_relay();
$var(rc) = $rc;
xlog(”===== t relay return code: $rc\n”);
exit;
}

failure_route[x] {
xlog(”==== failure route block\n”);
exit;
}

event_route[tm:branch-failure:x] {
xlog(”==== branch failure route block\n”);
}

Comment by Juha Heinanen (jh) - Saturday, 25 May 2013, 16:00 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

it turns out that branch failure route with the above example config is not executed when first request is processed after restart of kamailio. after that it seems to be always executed.

Comment by Juha Heinanen (jh) - Saturday, 25 May 2013, 16:12 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

another (important) thing that i noticed is that if i add to the above example config core dns parameter

use_dns_failover=on

then t_relay() always returns -1 and consequently branch failure route and transaction failure route are never executed:

May 25 19:09:32 siika sip-proxy[31820]: ERROR: <script>: ===== main route block
May 25 19:09:32 siika sip-proxy[31820]: ERROR: <script>: ===== after t_newtrans()
May 25 19:09:32 siika sip-proxy[31820]: ERROR: <script>: ==== branch route block
May 25 19:09:32 siika sip-proxy[31820]: ERROR: tm [../../forward.h:216]: msg_send(): msg_send: ERROR: tcp_send failed
May 25 19:09:32 siika sip-proxy[31820]: ERROR: tm [t_fwd.c:1596]: t_send_branch(): ERROR: t_send_branch: sending request on branch 0 failed
May 25 19:09:32 siika sip-proxy[31820]: ERROR: tm [t_fwd.c:1599]: t_send_branch(): putting branch 0 on hold
May 25 19:09:32 siika sip-proxy[31820]: ERROR: <script>: ===== t relay return code: -1

this is more serious issue than the failure to execute branch failure route for the first request after kamailio restart.

Comment by Daniel-Constantin Mierla (miconda) - Saturday, 25 May 2013, 19:33 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

I pushed a patch that hopefully fixes the dns failover case.

Branch failure route was added by Hugh and I haven’t had the time to review where is executed. In my tests I haven’t seen it executed.

Is failure branch route executed after restart for a local 408 on udp? IIRC, this was not seen in my tests as well.

Comment by Juha Heinanen (jh) - Sunday, 26 May 2013, 05:59 GMT
Strict Standards: call_user_func() expects parameter 1 to be a valid callback, non-static method dokuwiki_TextFormatter::render() should not be called statically in /var/www/sip-router.kamailio.org/flyspray/includes/class.tpl.php on line 552

thanks, now t_relay() returns 1 and failure routes are executed also when use_dns_failover=on.

using the test config in above, both failure routes are executed if tcp destination is not reachable. i just tested and they are also executed when i remove ;transport=tcp from the $ru value.

now only the minor problem remains, i.e., branch failure route is not executed in the very first test after kamailio restart.

also, it would be nice if in case of dead tcp connection, failure route execution would not need to wait until fr_timer expires.

Loading...