Fix write event log and audit log coredump(the events.logfile&audit.logfile null pointer)

Bug description:
When i make a benchmark test with a sysbench(version: 1.0.17) in proxysql 2.0.8   + mysql 5.7.26, i get the follow error info: 
Error: signal 11:
proxysql(_Z13crash_handleri+0x25)[0x5b607c]
/lib64/libc.so.6(+0x35270)[0x2b673de34270]
/lib64/libstdc++.so.6(_ZNSo6sentryC2ERSo+0xf)[0x2b673d67521f]
/lib64/libstdc++.so.6(_ZNSo5writeEPKcl+0x31)[0x2b673d675621]
proxysql(_ZN11MySQL_Event20write_query_format_1EPSt13basic_fstreamIcSt11char_traitsIcEE+0x27d)[0x6e2d81]
proxysql(_ZN11MySQL_Event5writeEPSt13basic_fstreamIcSt11char_traitsIcEEP13MySQL_Session+0x79)[0x6e19e9]
proxysql(_ZN12MySQL_Logger11log_requestEP13MySQL_SessionP17MySQL_Data_Stream+0x710)[0x6e5416]
proxysql(_ZN13MySQL_Session8LogQueryEP17MySQL_Data_Stream+0x6d)[0x654055]
proxysql(_ZN13MySQL_Session10RequestEndEP17MySQL_Data_Stream+0x35)[0x6540d7]
proxysql(_ZN13MySQL_Session7handlerEv+0x4397)[0x6459ed]
proxysql(_ZN12MySQL_Thread20process_all_sessionsEv+0x830)[0x623180]
proxysql(_ZN12MySQL_Thread3runEv+0x2cbe)[0x62208a]
proxysql(_Z24mysql_worker_thread_funcPv+0xbb)[0x5afb05]
/lib64/libpthread.so.0(+0x7e25)[0x2b673cda8e25]
/lib64/libc.so.6(clone+0x6d)[0x2b673def734d]
2019-12-02 09:52:26 main.cpp:1396:ProxySQL_daemonize_phase3(): [ERROR] ProxySQL crashed. Restarting!

I analyze the coredump with proxysql 2.0.8 debug version  very carefully, and  i found the variable of events.logfile  is null pointer in log_request  function when it call write function(me.write(events.logfile, sess)). The following is the coredump(write (this=0x2b67402fd1f0, f=0x0, sess=0x2b67414a8c00)):
(gdb) bt
#0  0x00002b673d67521f in std::ostream::sentry::sentry(std::ostream&) () from /lib64/libstdc++.so.6
#1  0x00002b673d675621 in std::ostream::write(char const*, long) () from /lib64/libstdc++.so.6
#2  0x00000000006e2d81 in MySQL_Event::write_query_format_1 (this=0x2b67402fd1f0, f=0x0) at MySQL_Logger.cpp:265
#3  0x00000000006e19e9 in MySQL_Event::write (this=0x2b67402fd1f0, f=0x0, sess=0x2b67414a8c00) at MySQL_Logger.cpp:89
#4  0x00000000006e5416 in MySQL_Logger::log_request (this=0x2b673e419680, sess=0x2b67414a8c00, myds=0x2b6741346480)
    at MySQL_Logger.cpp:717
#5  0x0000000000654055 in MySQL_Session::LogQuery (this=0x2b67414a8c00, myds=0x2b6741346480) at MySQL_Session.cpp:6691
#6  0x00000000006540d7 in MySQL_Session::RequestEnd (this=0x2b67414a8c00, myds=0x2b6741346480) at MySQL_Session.cpp:6711
#7  0x00000000006459ed in MySQL_Session::handler (this=0x2b67414a8c00) at MySQL_Session.cpp:4086
#8  0x0000000000623180 in MySQL_Thread::process_all_sessions (this=0x2b6741301000) at MySQL_Thread.cpp:4392
#9  0x000000000062208a in MySQL_Thread::run (this=0x2b6741301000) at MySQL_Thread.cpp:4125
#10 0x00000000005afb05 in mysql_worker_thread_func (arg=0x2b673e461f30) at main.cpp:648
#11 0x00002b673cda8e25 in start_thread () from /lib64/libpthread.so.0
#12 0x00002b673def734d in clone () from /lib64/libc.so.6

And then i add a line of code in log_request function of MySQL_Logger.cpp file to check up whether events.logfile is null pointer ,as follow:
void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) {
	if (events.enabled==false) return;
	if (events.logfile==NULL) return;

    proxy_info("log_request: First: events.logfile is null %d\n", (events.logfile == NULL) ? 1 : 0);
	MySQL_Connection_userinfo *ui=sess->client_myds->myconn->userinfo;

And i make a benchmark test  again with proxysql 2.0.8 debug version, the coredump of proxysql happen again, then i get the follow print info from proxysql.log
[root@XXXXX proxysql]# grep -n -w 'log_request: First: events.logfile is null 1' proxysql.log   
7358447:2019-12-02 09:52:26 MySQL_Logger.cpp:617:log_request(): [INFO] log_request: First: events.logfile is null 1
7358448:2019-12-02 09:52:26 MySQL_Logger.cpp:617:log_request(): [INFO] log_request: First: events.logfile is null 1

Bux fix:
Fix write event log and audit log  coredump, because  the proxysql get the null pointer variable of events.logfile(audit.logfile)in a multithreaded environment.
pull/2427/head
bskllzh 6 years ago committed by GitHub
parent a6fc967f25
commit d71d01cb63
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

@ -265,7 +265,8 @@ uint64_t MySQL_Event::write_query_format_1(std::fstream *f) {
// for performance reason, we are moving the write lock
// right before the write to disk
GloMyLogger->wrlock();
//GloMyLogger->wrlock();
//move wrlock() function to log_request() function, avoid to get a null pointer in a multithreaded environment
// write total length , fixed size
f->write((const char *)&total_bytes,sizeof(uint64_t));
@ -406,7 +407,8 @@ uint64_t MySQL_Event::write_query_format_2_json(std::fstream *f) {
// for performance reason, we are moving the write lock
// right before the write to disk
GloMyLogger->wrlock();
//GloMyLogger->wrlock();
//move wrlock() function to log_request() function, avoid to get a null pointer in a multithreaded environment
*f << j.dump(-1, ' ', false, json::error_handler_t::replace) << std::endl;
return total_bytes; // always 0
@ -713,6 +715,9 @@ void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) {
// for performance reason, we are moving the write lock
// right before the write to disk
//wrlock();
//add a mutex lock in a multithreaded environment, avoid to get a null pointer of events.logfile that leads to the program coredump
GloMyLogger->wrlock();
me.write(events.logfile, sess);
@ -866,6 +871,8 @@ void MySQL_Logger::log_audit_entry(log_event_type _et, MySQL_Session *sess, MySQ
// right before the write to disk
//wrlock();
//add a mutex lock in a multithreaded environment, avoid to get a null pointer of events.logfile that leads to the program coredump
GloMyLogger->wrlock();
me.write(audit.logfile, sess);

Loading…
Cancel
Save