Thanks, I'll analyze the logs as I get a chance very soon.

Cheers,
Daniel


On Fri, Sep 6, 2013 at 10:52 AM, Alex Balashov <abalashov@evaristesys.com> wrote:
Just for fun, I caused another crash, and this time got this backtrace:

#0  0x000000000054274d in qm_status (qm=0x7f7a3a24a010) at mem/q_malloc.c:775
#1  0x000000000053c10d in qm_debug_frag (qm=0x7f7a3a24a010, f=0x7f7a3a4fc918)
    at mem/q_malloc.c:141
#2  0x000000000053d32a in qm_malloc (qm=0x7f7a3a24a010, size=952,
    file=0x5e5434 "<core>: rvalue.c", func=0x5e9fb4 "rval_new_empty", line=236)
    at mem/q_malloc.c:384
#3  0x00000000004bddee in rval_new_empty (extra_size=102) at rvalue.c:236
#4  0x00000000004bde65 in rval_new_str (s=0x7fffcb1c9110, extra_size=80)
    at rvalue.c:260
#5  0x00000000004c057d in rval_convert (h=0x7fffcb1caf50, msg=0x7f7a39799920,
    type=RV_STR, v=0x7f7a3a3fd3d0, c=0x7fffcb1c92d0) at rvalue.c:1321
#6  0x00000000004c1a31 in rval_str_lop2 (h=0x7fffcb1caf50, msg=0x7f7a39799920,
    res=0x7fffcb1c9778, op=RVE_EQ_OP, l=0x7f7a3a3fd3d0, c1=0x7fffcb1c92d0,
    r=0x7f7a3a3fdbd0, c2=0x0) at rvalue.c:1752
#7  0x00000000004c2667 in rval_expr_eval_int (h=0x7fffcb1caf50,
    msg=0x7f7a39799920, res=0x7fffcb1c9778, rve=0x7f7a3a3fe2e8) at rvalue.c:2058
#8  0x0000000000418dca in do_action (h=0x7fffcb1caf50, a=0x7f7a3a4001e8,
    msg=0x7f7a39799920) at action.c:1050
#9  0x0000000000421ce7 in run_actions (h=0x7fffcb1caf50, a=0x7f7a3a3fd1a8,
    msg=0x7f7a39799920) at action.c:1573
#10 0x00000000004206af in do_action (h=0x7fffcb1caf50, a=0x7f7a3a4006c0,
    msg=0x7f7a39799920) at action.c:1374
#11 0x0000000000421ce7 in run_actions (h=0x7fffcb1caf50, a=0x7f7a3a3f3958,
    msg=0x7f7a39799920) at action.c:1573
#12 0x0000000000419012 in do_action (h=0x7fffcb1caf50, a=0x7f7a3a405f80,
    msg=0x7f7a39799920) at action.c:1065
#13 0x0000000000421ce7 in run_actions (h=0x7fffcb1caf50, a=0x7f7a3a405f80,
    msg=0x7f7a39799920) at action.c:1573
#14 0x000000000041906b in do_action (h=0x7fffcb1caf50, a=0x7f7a3a4060c0,
    msg=0x7f7a39799920) at action.c:1069
#15 0x0000000000421ce7 in run_actions (h=0x7fffcb1caf50, a=0x7f7a3a3da6a8,
    msg=0x7f7a39799920) at action.c:1573
#16 0x0000000000416f5a in do_action (h=0x7fffcb1caf50, a=0x7f7a3a4125d0,
    msg=0x7f7a39799920) at action.c:690
#17 0x0000000000421ce7 in run_actions (h=0x7fffcb1caf50, a=0x7f7a3a40b828,
    msg=0x7f7a39799920) at action.c:1573
#18 0x0000000000422471 in run_top_route (a=0x7f7a3a40b828, msg=0x7f7a39799920,
    c=0x0) at action.c:1658
#19 0x00007f7a3954ce90 in run_failure_handlers (t=0x7f7935779ad8,
    rpl=0x7f7a3a4fa4a8, code=404, extra_flags=64) at t_reply.c:1024
#20 0x00007f7a3954e00b in t_should_relay_response (Trans=0x7f7935779ad8,
    new_code=404, branch=0, should_store=0x7fffcb1cb230,
    should_relay=0x7fffcb1cb234, cancel_data=0x7fffcb1cb440, reply=0x7f7a3a4fa4a8)
    at t_reply.c:1300
#21 0x00007f7a3954fb98 in relay_reply (t=0x7f7935779ad8, p_msg=0x7f7a3a4fa4a8,
    branch=0, msg_status=404, cancel_data=0x7fffcb1cb440, do_put_on_wait=1)
    at t_reply.c:1703
#22 0x00007f7a39552cce in reply_received (p_msg=0x7f7a3a4fa4a8) at t_reply.c:2370
#23 0x00000000004591b1 in do_forward_reply (msg=0x7f7a3a4fa4a8, mode=0)
    at forward.c:799
#24 0x0000000000459a40 in forward_reply (msg=0x7f7a3a4fa4a8) at forward.c:882
#25 0x000000000049f776 in receive_msg (
    buf=0x910e20 "SIP/2.0 404 Not Found\r\nVia: SIP/2.0/UDP 55.177.31.199;branch=z9hG4bK80fd.c731a837.0\r\nVia: SIP/2.0/UDP 68.68.120.41:5060;branch=z9hG4bK0cB61aa236182c0cf4d\r\nRecord-Route: <sip:55.177.31.199;lr=on;ftag=gK0c275042;vsf=", 'A' <repeats 38 times>, "--;dlgcor=a9.aca2>\r\nFrom: <sip:16784841111@68.68.120.41>;tag=gK0c275042\r\nTo: <sip:12066513489@55.177.31.199>;tag=ed7d54e69a\r\nCall-ID: 185377618_113020350@68.68.120.41\r\nCSeq: 15495 INVITE\r\nContact: <sip:5282797646@195.105.225.111:5060;transport=udp>\r\nSupported: 100rel, replaces, norefersub\r\nAllow-Events: refer\r\nAllow: INVITE, ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE\r\nAccept: application/sdp\r\nUser-Agent: snomONE/4.5.1.1107 Zeta Perseids\r\nContent-Length: 0\r\n\r\n", len=717, rcv_info=0x7fffcb1cb7c0) at receive.c:272
#26 0x0000000000532665 in udp_rcv_loop () at udp_server.c:557
#27 0x00000000004688a1 in main_loop () at main.c:1638
#28 0x000000000046b84a in main (argc=13, argv=0x7fffcb1cbaf8) at main.c:2566

This time, the overwritten fragment was:

Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19629]: : <core> [mem/q_malloc.c:140]: qm_debug_frag(): BUG: qm_*: fragm. 0x7f7a3a4fc918 (address 0x7f7a3a4fc948) beginning overwritten(3e653834323335)!

This time, the pedigree of the fragment address was much shorter:

Sep  6 04:47:50 gw1 /usr/local/sbin/kamailio[19631]: DEBUG: <core> [mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f7a3a24a010, 56) returns address 0x7f7a3a4fc918 frag. 0x7f7a3a4fc8e8 (size=96) on 1 -th hit
Sep  6 04:47:50 gw1 /usr/local/sbin/kamailio[19631]: DEBUG: <core> [mem/q_malloc.c:437]: qm_free(): qm_free(0x7f7a3a24a010, 0x7f7a3a4fc918), called from <core>: data_lump.c: free_duped_lump_list(626)
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f7a3a24a010, 48) returns address 0x7f7a3a4fc918 frag. 0x7f7a3a4fc8e8 (size=48) on 1 -th hit
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [db_res.c:184]: db_allocate_rows(): allocate 48 bytes for rows at 0x7f7a3a4fc918
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [db_res.c:62]: db_free_rows(): freeing rows at 0x7f7a3a4fc918
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [mem/q_malloc.c:437]: qm_free(): qm_free(0x7f7a3a24a010, 0x7f7a3a4fc918), called from <core>: db_res.c: db_free_rows(63)
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f7a3a24a010, 48) returns address 0x7f7a3a4fc918 frag. 0x7f7a3a4fc8e8 (size=48) on 1 -th hit
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [db_val.c:127]: db_str2val(): allocate 48 bytes memory for STRING at 0x7f7a3a4fc918
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [db_row.c:68]: db_free_row(): free VAL_STRING[14] '<urn:uuid:d3bcbc0b-7fde-4db5-9871-79efb9b07aab>' at 0x7f7a3a4fc918
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [mem/q_malloc.c:437]: qm_free(): qm_free(0x7f7a3a24a010, 0x7f7a3a4fc918), called from <core>: db_row.c: db_free_row(69)
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: <core> [mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f7a3a24a010, 48) returns address 0x7f7a3a4fc918 frag. 0x7f7a3a4fc8e8 (size=48) on 1 -th hit
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19629]: DEBUG: <core> [mem/q_malloc.c:413]: qm_malloc(): qm_malloc(0x7f7a3a24a010, 952) returns address 0x7f7a3a4fc948 frag. 0x7f7a3a4fc918 (size=952) on 1 -th hit
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19629]: DEBUG: <core> [mem/q_malloc.c:472]: qm_free(): qm_free: freeing frag. 0x7f7a3a4fc918 alloc'ed from <core>: rvalue.c: rval_new_empty(236)
Sep  6 04:47:54 gw1 /usr/local/sbin/kamailio[19629]: : <core> [mem/q_malloc.c:140]: qm_debug_frag(): BUG: qm_*: fragm. 0x7f7a3a4fc918 (address 0x7f7a3a4fc948) beginning overwritten(3e653834323335)!
Sep  6 04:48:06 gw1 /usr/local/sbin/kamailio[19627]: DEBUG: qm_status:   6792. N  address=0x7f7a3a4fc918 frag=0x7f7a3a4fc8e8 size=48 used=1

But the common factor is database involvement beforehand.

Am I right to suppose that this points to a buffer overflow in db_postgres or libsrdb1 somewhere?


-- Alex

--
Alex Balashov - Principal
Evariste Systems LLC
235 E Ponce de Leon Ave
Suite 106
Decatur, GA 30030
United States
Tel: +1-678-954-0670
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/

_______________________________________________
sr-dev mailing list
sr-dev@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev



--
Daniel-Constantin Mierla
  http://www.asipto.com