Crash in master for inserting sip trace record in mysql

[danpascu]

Core was generated by `/usr/sbin/opensips -w /run/opensips -P opensips.pid -m 512'.
Program terminated with signal SIGABRT, Aborted.
#0 0xb76f2cf9 in __kernel_vsyscall ()
(gdb) bt
#0 0xb76f2cf9 in __kernel_vsyscall ()
#1 0xb752cdd0 in __libc_signal_restore_set (set=0xbfb550e0) at ../sysdeps/unix/sysv/linux/nptl-signals.h:79
#2 __GI_raise (sig=6) at ../sysdeps/unix/sysv/linux/raise.c:48
#3 0xb752e297 in __GI_abort () at abort.c:89
#4 0xb756838f in __libc_message (do_abort=, fmt=) at ../sysdeps/posix/libc_fatal.c:175
#5 0xb756efc7 in malloc_printerr (action=, str=0xb765ecc6 "corrupted size vs. prev_size", ptr=, ar_ptr=0xb76b4780 <main_arena>) at malloc.c:5049
#6 0xb75714d5 in _int_malloc (av=av@entry=0xb76b4780 <main_arena>, bytes=bytes@entry=8176) at malloc.c:3765
#7 0xb7572bf5 in __GI___libc_malloc (bytes=8176) at malloc.c:2928
#8 0x96de86f1 in my_malloc () from /usr/lib/i386-linux-gnu/libmariadbclient.so.18
#9 0x96de399c in alloc_root () from /usr/lib/i386-linux-gnu/libmariadbclient.so.18
#10 0x96dac668 in ?? () from /usr/lib/i386-linux-gnu/libmariadbclient.so.18
#11 0x96da8c92 in myodbc_remove_escape () from /usr/lib/i386-linux-gnu/libmariadbclient.so.18
#12 0x96dab457 in mysql_stmt_prepare () from /usr/lib/i386-linux-gnu/libmariadbclient.so.18
#13 0x9717f530 in wrapper_single_mysql_stmt_prepare (conn=0x1def140, ctx=0x1df5870) at dbase.c:121
#14 re_init_statement (conn=conn@entry=0x1def140, ctx=ctx@entry=0x1df5870, free_ctx=0, pq_ptr=) at dbase.c:407
#15 0x9718084c in get_new_stmt_ctx (conn=conn@entry=0x1def140, query=0x971a0240 <query_holder>) at dbase.c:488
#16 0x971819f9 in db_mysql_do_prepared_query (conn=conn@entry=0x1def140, v=v@entry=0x9659c980 <db_vals>, n=n@entry=14, uv=0x0, un=0, query=0x971a0240 <query_holder>) at dbase.c:603
#17 0x97185fcb in db_mysql_insert (_h=0x1def140, _k=0x9659c920 <db_keys>, _v=0x9659c980 <db_vals>, _n=14) at dbase.c:1283
#18 0x9658a9fc in insert_siptrace (keys=0x9659c920 <db_keys>, vals=0x9659c980 <db_vals>, trace_attrs=, st_db=0x1cdb450) at siptrace.c:905
#19 save_siptrace (info=info@entry=0x97d63400, msg=0x1defa08, vals=0x9659c980 <db_vals>, keys=0x9659c920 <db_keys>) at siptrace.c:967
#20 0x9658d646 in sip_trace (msg=msg@entry=0x1defa08, info=0x97d63400) at siptrace.c:1680
#21 0x9659207d in sip_trace_w (msg=0x1defa08, param1=0x1cb5430 "", param2=0x8 <error: Cannot access memory at address 0x8>, param3=0x1cb7550 "\001", param4=0x0) at siptrace.c:1590
#22 0x00515a67 in do_action (a=0x1ce5958, msg=0x1defa08) at action.c:1866
#23 0x0051c00a in run_action_list (a=0x1ce5958, msg=0x1defa08) at action.c:172
#24 0x0051954b in do_action (a=0x1d49628, msg=0x1defa08) at action.c:1124
#25 0x0051c00a in run_action_list (a=0x1cdbad0, msg=0x1defa08) at action.c:172
#26 0x0051c30a in run_actions (msg=0x1defa08, a=0x1cdbad0) at action.c:137
#27 run_top_route (a=0x1cdbad0, msg=0x1defa08) at action.c:214
#28 0x00522a33 in receive_msg (buf=, len=, rcv_info=, existing_context=, flags=) at receive.c:209
#29 0x0066b878 in tcp_handle_req (_max_msg_chunks=, con=0x97d5f170, req=0x7a4ea0 <tcp_current_req>) at net/proto_tcp/tcp_common.h:411
#30 tcp_read_req (con=0x97d5f170, bytes_read=0xbfb564e8) at net/proto_tcp/proto_tcp.c:1179
#31 0x0064ba8e in handle_io (fm=, idx=idx@entry=0, event_type=event_type@entry=1) at net/net_tcp_proc.c:241
#32 0x0064e0d5 in io_wait_loop_epoll (h=, t=, repeat=) at net/../io_wait_loop.h:280
#33 tcp_worker_proc_loop () at net/net_tcp_proc.c:386
#34 0x00659993 in tcp_start_processes (chd_rank=0x781980 <chd_rank>, startup_done=0x0) at net/net_tcp.c:1887
#35 0x004ff42c in main_loop () at main.c:761
#36 main (argc=, argv=) at main.c:1407

[bogdan-iancu]

Similar to #1472

[danpascu]

How is this a duplicate of #1472 ? This one happens in sip trace while inserting in mysql while #1472 happens in xlog? Just because both crash because of corrupt memory doesn't mean that fixing one will fix the other as the source of the corruption is very unlikely to be in the same place. The more likely case is that a certain pattern of programming is causing this, pattern that is not showing up when using pkg memory, but is immediately visible when using system memory.

Not long ago I fixed a crash myself that would not even allow opensips to start, crash which was hidden with pkg memory but happened 100% of the case with system memory. The cause of it was accessing already freed memory. After I fixed that now I ran into these. Nowadays I see #1472 more often only because that xlog line is the first one in the script. I'm pretty sure after we fix that, others will surface up, only because they do not have a chance to be hit now, simply because the proxy crashes before reaching them.