[tracker] Task opened: Crash in asynchronous processing - sr-dev

24 Feb 2014


      THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.
A new Flyspray task has been opened.  Details are below.
User who did this - Carsten Bock (carstenbock)
Attached to Project - sip-router
Summary - Crash in asynchronous processing
Task Type - Bug Report
Category - Core
Status - New
Assigned To - 
Operating System - Linux
Severity - Low
Priority - Normal
Reported Version - Development
Due in Version - Undecided
Due Date - Undecided
Details - The crash is related to commit:
Commit: f3f2f09beda60e1f7f4e6dfc0359f788991aeef6
and applies to both 4.1 and master.
Config sniplet, to reproduce the crash:
<code>
[...]
# ----- mqueue params -----
modparam("mqueue", "mqueue", "name=presence")
# ----- rtimer params -----
modparam("rtimer", "timer", "name=presence0;interval=1;mode=1;")
modparam("rtimer", "exec", "timer=presence0;route=PRESENCE_PROCESS")
[...]
route {
        if (!t_suspend()) {
                t_reply("500", "Server Internal Error");
                xlog("L_ERR", "Failed to suspend transaction for $rm\n");
                exit;
        }
if (!mq_add("presence", "$T(id_index)", "$T(id_label)")) {
                t_reply("500", "Server Internal Error");
                xlog("L_ERR", "Failed to queue transaction for $rm [$T(id_index):$T(id_label)]\n");
                exit;
        }
        exit;
}
route[PRESENCE_PROCESS] {
    lock("pres");
    $var(pres) = $shv(pres);
    $shv(pres) = $shv(pres) + 1;
    unlock("pres");
    
    $var(q_size) = mq_size("presence");
    xlog("L_WARN", "Starting presence de-queue process $var(pres) (pid: $pp), size of queue is: $var(q_size)\n");
while (mq_fetch("presence")) {
    	$var(id_index) = (int) $mqk(presence);
    	$var(id_label) = (int) $mqv(presence);
    	xlog("L_INFO", "Found queued presence transaction [$var(id_index):$var(id_label)]\n");
    	t_continue("$var(id_index)", "$var(id_label)", "PRESENCE");
    }
}
route[PRESENCE] {
    xlog("L_INFO", "$rm: route[PRESENCE] process $var(pres)\n");
}
</code>
----
Logfile from the issue (different use-case, same crash; with TIMER_DEBUG enabled):
----
<code>
Feb 11 22:37:23 scscf ./kamailio[32230]: ERROR: <script>: 2 saa_return code (for scscf_save on register) is 1
Feb 11 22:37:23 scscf ./kamailio[32230]: ERROR: <script>: SAR success - 200 response sent from module
Feb 11 22:37:23 scscf ./kamailio[32230]: WARNING: <core> [timer.c:584]: timer_add_safe(): timer_add called on an active timer 0x7fcf1ba5eb68 (0x7fcf1b77e7d8, 0x7fcf1b77e7d8), flags 201
Feb 11 22:37:23 scscf ./kamailio[32230]: WARNING: <core> [timer.c:586]: timer_add_safe(): WARN: -timer_add-; called from put_on_wait(t_funcs.c):176
Feb 11 22:37:23 scscf ./kamailio[32230]: WARNING: <core> [timer.c:592]: timer_add_safe(): WARN: -timer_add-: added 1 times, last from: put_on_wait(t_funcs.c):176, deleted 0 times, last from: (null)((null)):0, init 1 times, expired 0
Feb 11 22:37:28 scscf ./kamailio[32220]: : <core> [timer.c:868]: timer_list_expire(): BUG: timer_list_expire: @1843226859 tl=0x7fcf1ba6a870 { (nil), 0x7fcf1b7998f8, 463910128, 32719, 0x7fcf1ba6bb68, 0x7fcf1ba6b8e0, bbf8, -}, h=0x7fcf1b7998f8 {0x7fcf1ba6a870, 0x7fcf1ba5eb68}
Feb 11 22:37:28 scscf ./kamailio[32220]: : <core> [timer.c:870]: timer_list_expire(): BUG: -timer_list_expire-: cycle 0, first 0x7fcf1ba6a870,running (nil)
Feb 11 22:37:28 scscf ./kamailio[32220]: : <core> [timer.c:878]: timer_list_expire(): BUG: -timer_list_expire-: added 32719 times, last from: #007(#004):463911912, deleted 0 times, last from: (null)(#011):0, init 463912904 times, expired 32720
</code>
----
Output of "bt full" of gdb:
----
<code>
(gdb) bt full
#0  0x0000000000554c34 in timer_list_expire (slow_mark=112,
slow_l=0x7fbbd37c0208, h=0x7fbbd37bf8f8, t=1936555861) at timer.c:883
        tl = 0x7fbbd3a81790
        ret = <optimized out>
#1  timer_handler () at timer.c:959
        saved_ticks = <optimized out>
        run_slow_timer = 0
        i = 112
#2  timer_main () at timer.c:998
No locals.
#3  0x0000000000480a05 in main_loop () at main.c:1688
        i = <optimized out>
        pid = <optimized out>
        si = 0x0
        si_desc = "udp receiver child=2 sock=141.0.21.99:5060", '\000'
<repeats 22 times>,
"\016\b\000\000\000\000\000\000\020\325`\000\000\000\000\000\003\000\000\000\000\000\000\000\000\001l\f\304\331\373\177\001\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000(\331\223\000\000\000\000\000
\331\223\000\000\000\000"
        nrprocs = <optimized out>
        __FUNCTION__ = "main_loop"
#4  0x0000000000420585 in main (argc=<optimized out>, argv=<optimized
out>) at main.c:2533
        cfg_stream = <optimized out>
        c = <optimized out>
        r = <optimized out>
        tmp = 0x7fff9cc4fa17 ""
        tmp_len = -1664821218
        port = 118
        proto = -1664820856
        options = 0x608470
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:"
        ret = -1
        seed = 4225034667
        rfd = 0
        debug_save = <optimized out>
        debug_flag = <optimized out>
        dont_fork_cnt = <optimized out>
        n_lst = 0x0
        p = <optimized out>
        __FUNCTION__ = "main"
</code>
----
As soon as i revert the above mentioned patch, everything's fine; so my crash is definitely related to that commit.
More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=400
You are receiving this message because you have requested it from the Flyspray bugtracking system.  If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.