[sr-dev] Crash bug freeing To headers

Fri Sep 6 10:52:37 CEST 2013

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 at 68.68.120.41>;tag=gK0c275042\r\nTo: 
<sip:12066513489 at 55.177.31.199>;tag=ed7d54e69a\r\nCall-ID: 
185377618_113020350 at 68.68.120.41\r\nCSeq: 15495 INVITE\r\nContact: 
<sip:5282797646 at 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/