[SR-Users] CRASH on qm_free for simultaneous calls (V3.1.0)
Jijo
realjijo at gmail.com
Mon Dec 20 16:37:12 CET 2010
Hi Daniel,
Some more detail to this issue..
if we call t_release after failure route with append branch, a double free
causes the crash because the transaction will be free again after the
t_relay of ACK message. This happens because we compile the code with
DBG_QM_MALLOC.
wt_timer keeps the transaction active for 5 seconds. And I think if the
DBG_QM_MALLOC is not used, the crash happens in the timer proccess during
the wt time (when the 1st call is diconnected before this time).
Thanks
Jijo
On Fri, Dec 17, 2010 at 5:09 PM, Daniel-Constantin Mierla <miconda at gmail.com
> wrote:
> Hello,
>
>
> On 12/17/10 12:58 AM, Jijo wrote:
>
> Hi Daniel..
>
> This was due to an error in our config file.
>
> We were doing t_release and then t_relay. So we removed the t_release from
> config, which basically fixed the issue.
>
> thanks for further troubleshooting and reporting, I will check it and try
> to prevent the crash -- even it is a misusage should be nicer dealt with
> printing an error message.
>
> Cheers,
> Daniel
>
>
>
> On Thu, Dec 16, 2010 at 2:16 PM, Jijo <realjijo at gmail.com> wrote:
>
>> Hi Daniel,
>>
>> Thanks..Please find the logs
>>
>> 2010-12-17T10:29:04+00:00 [crit] sipserver: : <core> [mem/q_malloc.c:446]:
>> BUG: qm_free: freeing already freed pointer, first free: tm: h_table.c:
>> free_cell(141) - aborting
>> 2010-12-17T10:29:04+00:00 [crit] sipserver: : <core> [pass_fd.c:293]:
>> ERROR: receive_fd: EOF on 11
>> 2010-12-17T10:29:04+00:00 [alert] sipserver: ALERT: <core> [main.c:741]:
>> child process 14398 exited by a signal 6
>> 2010-12-17T10:29:04+00:00 [alert] sipserver: ALERT: <core> [main.c:744]:
>> core was generated
>> 2010-12-17T10:29:04+00:00 [crit] sipserver: : <core> [mem/q_malloc.c:446]:
>> BUG: qm_free: freeing already freed pointer, first free: tm: h_table.c:
>> free_cell(141) - aborting
>>
>>
>> Jijo
>>
>>
>> On Thu, Dec 16, 2010 at 1:27 AM, Daniel-Constantin Mierla <
>> miconda at gmail.com> wrote:
>>
>>> Hello,
>>>
>>> look into syslog file (/var/log/syslog or /var/log/messages if you didn't
>>> set a custom one) and search for a message like "BUG: qm_free: freeing
>>> already freed pointer ...".. Send it here, seems to be a double free of same
>>> pointer.
>>>
>>> Thanks,
>>> Daniel
>>>
>>>
>>> On 12/16/10 12:34 AM, Jijo wrote:
>>>
>>> I'm observing a crash on qm_free, when we made two outgoing calls to
>>> the same number. One SIP phone receives ring back tone and the other busy
>>> tone. The back trace is shown below which shows that it is crashed in
>>> abort(). How can the condition if (f->u.is_free){ could be true?
>>> Please let me know if anybody observed this issue and let me know how to
>>> debug this isssue.
>>>
>>> f=(struct qm_frag*) ((char*)p-sizeof(struct qm_frag));
>>> #ifdef DBG_QM_MALLOC
>>> qm_debug_frag(qm, f);
>>> if (f->u.is_free){
>>> LOG(L_CRIT, "BUG: qm_free: freeing already freed pointer,"
>>> " first free: %s: %s(%ld) - aborting\n",
>>> f->file, f->func, f->line);*
>>> abort();*
>>> }
>>> MDBG("qm_free: freeing frag. %p alloc'ed from %s: %s(%ld)\n",
>>> f, f->file, f->func, f->line);
>>> #endif
>>>
>>>
>>> BACKTRACE
>>> -------------------
>>>
>>>
>>> Program received signal SIGABRT, Aborted.
>>> 0xb76fd7a5 in raise () from /lib/libc.so.6
>>> (gdb) bt full
>>> #0 0xb76fd7a5 in raise () from /lib/libc.so.6
>>> No symbol table info available.
>>> #1 0xb76ff070 in abort () from /lib/libc.so.6
>>> No symbol table info available.
>>> #2 0x081824d5 in qm_free (qm=0xaf7ee000, p=0xaf9ed758, file=0xb7659aed
>>> "tm: h_table.c", func=0xb7659c9c "free_cell", line=141) at
>>> mem/q_malloc.c:447
>>> f = <value optimized out>
>>> prev = <value optimized out>
>>> next = <value optimized out>
>>> size = <value optimized out>
>>> #3 0xb75ff6b9 in free_cell (dead_cell=0xaf9e7054) at h_table.c:141
>>> b = <value optimized out>
>>> i = <value optimized out>
>>> rpl = <value optimized out>
>>> tt = <value optimized out>
>>> foo = <value optimized out>
>>> cbs = <value optimized out>
>>> cbs_tmp = <value optimized out>
>>> __FUNCTION__ = "free_cell"
>>> #4 0xb7625eb0 in t_unref (p_msg=0x847bb10) at t_lookup.c:1553
>>> kr = <value optimized out>
>>> #5 0xb764b3ad in w_t_unref (foo=0x847bb10, flags=2147483649, bar=0x0) at
>>> tm.c:707
>>> No locals.
>>> #6 0x0811543a in exec_post_script_cb (msg=0x847bb10,
>>> type=REQUEST_CB_TYPE) at script_cb.c:195
>>> cb = 0x8867874
>>> flags = 2147483649
>>> #7 0x080e5a4e in receive_msg (
>>> buf=0x82a89e0 "ACK sip:0845 at 10.80.13.54:5060;transport=udpSIP/2.0\r\nVia: SIP/2.0/UDP 10.200.3.39:5060;branch=z9hG4bK0a992e8d3052e85e5\r\nRoute:
>>> <sip:0845 at 10.200.0.31:5060;lr;transport=udp>\r\nMax-Forwards:
>>> 69\r\nFrom: 554"..., len=<value optimized out>, rcv_info=0xbf95b7fc) at
>>> receive.c:221
>>> msg = 0x847bb10
>>> ctx = {rec_lev = 137434160, run_flags = 0, last_retcode =
>>> -1080707352, jmp_env = {{__jmpbuf = {-1224488143, 137089696, 137434092, 0,
>>> -1080707248,
>>> -1080707304}, __mask_was_saved = 0, __saved_mask = {__val
>>> = {3079133424, 134556827, 3079002384, 0, 3214260024, 3070479287, 137089696,
>>> 137434160, 3070572886, 3070573396, 228, 137347864,
>>> 3214260056, 3077419768, 3079002384, 137089664, 4294967295, 3079131124,
>>> 134556827,
>>> 134535424, 1, 3079058382, 3079133864, 3079003192, 1, 1,
>>> 0, 134555968, 0, 136548964, 3077419768, 142823652}}}}}
>>> ret = <value optimized out>
>>> inb = {
>>> s = 0x82a89e0 "ACK sip:0845 at 10.80.13.54:5060;transport=udpSIP/2.0\r\nVia: SIP/2.0/UDP 10.200.3.39:5060;branch=z9hG4bK0a992e8d3052e85e5\r\nRoute:
>>> <sip:0845 at 10.200.0.31:5060;lr;transport=udp>\r\nMax-Forwards:
>>> 69\r\nFrom: 554"..., len = 457}
>>> __FUNCTION__ = "receive_msg"
>>> #8 0x08175cb6 in udp_rcv_loop () at udp_server.c:532
>>> len = <value optimized out>
>>> buf = "ACK sip:0845 at 10.80.13.54:5060;transport=udpSIP/2.0\r\nVia: SIP/2.0/UDP 10.200.3.39:5060;branch=z9hG4bK0a992e8d3052e85e5\r\nRoute:
>>> <sip:0845 at 10.200.0.31:5060;lr;transport=udp>\r\nMax-Forwards:
>>> 69\r\nFrom: 554"...
>>> from = 0x88350e4
>>> fromlen = 16
>>> ri = {src_ip = {af = 2, len = 4, u = {addrl = {654559242, 0,
>>> 3214260312, 3079002384}, addr32 = {654559242, 0, 3214260312, 3079002384},
>>> addr16 = {
>>> 51210, 9987, 0, 0, 47192, 49045, 55568, 46981}, addr =
>>> "\n\310\003'\000\000\000\000X\270\225\277\020Ù
>>> \267"}}, dst_ip = {af = 2, len = 4,
>>> u = {addrl = {520144906, 0, 0, 0}, addr32 = {520144906, 0, 0,
>>> 0}, addr16 = {51210, 7936, 0, 0, 0, 0, 0, 0},
>>> addr = "\n\310\000\037", '\000' <repeats 11 times>}},
>>> src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0,
>>> src_su = {
>>> s = {sa_family = 2, sa_data =
>>> "\023\304\n\310\003'\000\000\000\000\000\000\000"}, sin = {sin_family = 2,
>>> sin_port = 50195, sin_addr = {
>>> s_addr = 654559242}, sin_zero =
>>> "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195,
>>> sin6_flowinfo = 654559242,
>>> sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15
>>> times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0,
>>> 0}}},
>>> sin6_scope_id = 0}}, bind_address = 0x82f4140, proto = 1
>>> '\001'}
>>> __FUNCTION__ = "udp_rcv_loop"
>>> #9 0x080ac1d4 in main_loop () at main.c:1554
>>> i = <value optimized out>
>>> ---Type <return> to continue, or q <return> to quit---
>>> pid = <value optimized out>
>>> si = <value optimized out>
>>> si_desc = "udp receiver child=0 sock=10.200.0.31:5060\000\b
>>> A\206\b\002\000\000\000\004\000\000\000\n\310\000\037L
>>> \225\257H\271\225\277@
>>> \030\207\267\020i\203\b\006\000\000\000\000\340~\257\001\000\000\000\001\000\000\000\000\000\000\000\000\340~\257\004\000\000\000?)\037\b\001\000\000\000\a\000\000\000\000\000\000\000H\271\225\277\350\353\017\b"
>>> #10 0x080af2ec in main (argc=9, argv=0xbf95ba84) at main.c:2398
>>> cfg_stream = 0x8cbe008
>>> c = <value optimized out>
>>> r = <value optimized out>
>>> tmp = 0xbf95cdc0 ""
>>> tmp_len = -1217394389
>>> port = <value optimized out>
>>> proto = <value optimized out>
>>> options = 0x81ef340
>>> ":f:cm:dVhEb:l:L:n:vrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:"
>>> ret = -1
>>> seed = 3337198521
>>> rfd = <value optimized out>
>>> debug_save = <value optimized out>
>>> debug_flag = <value optimized out>
>>> dont_fork_cnt = 0
>>> p = <value optimized out>
>>>
>>> Thanks
>>> Jijo
>>>
>>>
>>> _______________________________________________
>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing listsr-users at lists.sip-router.orghttp://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>>
>>>
>>> --
>>> Daniel-Constantin Mierla
>>> Kamailio (OpenSER) Advanced Training
>>> Jan 24-26, 2011, Irvine, CA, USAhttp://www.asipto.com
>>>
>>>
>>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing listsr-users at lists.sip-router.orghttp://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>
>
> --
> Daniel-Constantin Mierla
> Kamailio (OpenSER) Advanced Training
> Jan 24-26, 2011, Irvine, CA, USAhttp://www.asipto.com
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20101220/842aada4/attachment-0001.htm>
More information about the sr-users
mailing list