diff --git a/include/MySQL_Logger.hpp b/include/MySQL_Logger.hpp index 355b5b851..91a017c00 100644 --- a/include/MySQL_Logger.hpp +++ b/include/MySQL_Logger.hpp @@ -25,7 +25,7 @@ class MySQL_Event { unsigned char buf[10]; enum log_event_type et; uint64_t hid; - char *err; + char *extra_info; public: MySQL_Event(log_event_type _et, uint32_t _thread_id, char * _username, char * _schemaname , uint64_t _start_time , uint64_t _end_time , uint64_t _query_digest, char *_client, size_t _client_len); uint64_t write(std::fstream *f, MySQL_Session *sess); @@ -33,7 +33,7 @@ class MySQL_Event { void write_auth(std::fstream *f, MySQL_Session *sess); void set_query(const char *ptr, int len); void set_server(int _hid, const char *ptr, int len); - void set_error(char *); + void set_extra_info(char *); }; class MySQL_Logger { diff --git a/lib/MySQL_Logger.cpp b/lib/MySQL_Logger.cpp index 4dee72246..6cc7bf8fb 100644 --- a/lib/MySQL_Logger.cpp +++ b/lib/MySQL_Logger.cpp @@ -38,11 +38,11 @@ MySQL_Event::MySQL_Event (log_event_type _et, uint32_t _thread_id, char * _usern et=_et; hid=UINT64_MAX; server=NULL; - err = NULL; + extra_info = NULL; } -void MySQL_Event::set_error(char *_err) { - err = _err; +void MySQL_Event::set_extra_info(char *_err) { + extra_info = _err; } void MySQL_Event::set_query(const char *ptr, int len) { @@ -66,6 +66,7 @@ uint64_t MySQL_Event::write(std::fstream *f, MySQL_Session *sess) { case PROXYSQL_MYSQL_AUTH_ERR: case PROXYSQL_MYSQL_AUTH_CLOSE: case PROXYSQL_MYSQL_AUTH_QUIT: + case PROXYSQL_MYSQL_INITDB: case PROXYSQL_ADMIN_AUTH_OK: case PROXYSQL_ADMIN_AUTH_ERR: case PROXYSQL_ADMIN_AUTH_CLOSE: @@ -83,16 +84,18 @@ uint64_t MySQL_Event::write(std::fstream *f, MySQL_Session *sess) { } void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { - json j; + json j; j["timestamp"] = start_time/1000; - time_t timer=start_time/1000/1000; - struct tm* tm_info; - tm_info = localtime(&timer); - char buffer1[64]; - char buffer2[64]; - strftime(buffer1, 32, "%Y-%m-%d %H:%M:%S", tm_info); - sprintf(buffer2,"%s.%03u", buffer1, (unsigned)(start_time%1000000)/1000); - j["time"] = buffer2; + { + time_t timer=start_time/1000/1000; + struct tm* tm_info; + tm_info = localtime(&timer); + char buffer1[64]; + char buffer2[64]; + strftime(buffer1, 32, "%Y-%m-%d %H:%M:%S", tm_info); + sprintf(buffer2,"%s.%03u", buffer1, (unsigned)(start_time%1000000)/1000); + j["time"] = buffer2; + } j["thread_id"] = thread_id; if (username) { j["username"] = username; @@ -112,8 +115,8 @@ void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { if (server) { j["server_addr"] = server; } - if (err) { - j["error"] = err; + if (extra_info) { + j["extra_info"] = extra_info; } switch (et) { case PROXYSQL_MYSQL_AUTH_OK: @@ -128,6 +131,9 @@ void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { case PROXYSQL_MYSQL_AUTH_QUIT: j["event"]="MySQL_Client_Quit"; break; + case PROXYSQL_MYSQL_INITDB: + j["event"]="MySQL_Client_Init_DB"; + break; case PROXYSQL_ADMIN_AUTH_OK: j["event"]="Admin_Connect_OK"; break; @@ -155,6 +161,34 @@ void MySQL_Event::write_auth(std::fstream *f, MySQL_Session *sess) { default: break; } + switch (et) { + case PROXYSQL_MYSQL_AUTH_CLOSE: + case PROXYSQL_ADMIN_AUTH_CLOSE: + case PROXYSQL_SQLITE_AUTH_CLOSE: + { + uint64_t curtime_real=realtime_time(); + uint64_t curtime_mono=sess->thread->curtime; + uint64_t timediff = curtime_mono - sess->start_time; + uint64_t orig_time = curtime_real - timediff; + time_t timer= (orig_time)/1000/1000; + struct tm* tm_info; + tm_info = localtime(&timer); + char buffer1[64]; + char buffer2[64]; + strftime(buffer1, 32, "%Y-%m-%d %H:%M:%S", tm_info); + sprintf(buffer2,"%s.%03u", buffer1, (unsigned)(orig_time%1000000)/1000); + j["creation_time"] = buffer2; + //unsigned long long life = sess->thread->curtime - sess->start_time; + //life/=1000; + float f = timediff; + f /= 1000; + sprintf(buffer1, "%.3fms", f); + j["duration"] = buffer1; + } + break; + default: + break; + } if (sess->client_myds) { if (sess->client_myds->proxy_addr.addr) { std::string s = sess->client_myds->proxy_addr.addr; @@ -521,37 +555,74 @@ void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) { } } -void MySQL_Logger::log_audit_entry(log_event_type _et, MySQL_Session *sess, MySQL_Data_Stream *myds, char *err) { +void MySQL_Logger::log_audit_entry(log_event_type _et, MySQL_Session *sess, MySQL_Data_Stream *myds, char *xi) { if (audit.enabled==false) return; if (audit.logfile==NULL) return; - MySQL_Connection_userinfo *ui=sess->client_myds->myconn->userinfo; + if (sess == NULL) return; + if (sess->client_myds == NULL) return; + MySQL_Connection_userinfo *ui= NULL; if (sess) { - // to reduce complexing in the calling function, we do some changes here - if (_et == PROXYSQL_MYSQL_AUTH_OK) { - switch (sess->session_type) { - case PROXYSQL_SESSION_ADMIN: - case PROXYSQL_SESSION_STATS: - _et = PROXYSQL_ADMIN_AUTH_OK; - break; - case PROXYSQL_SESSION_SQLITE: - _et = PROXYSQL_SQLITE_AUTH_OK; - default: - break; + if (sess->client_myds) { + if (sess->client_myds->myconn) { + ui = sess->client_myds->myconn->userinfo; } } - if (_et == PROXYSQL_MYSQL_AUTH_ERR) { - switch (sess->session_type) { - case PROXYSQL_SESSION_ADMIN: - case PROXYSQL_SESSION_STATS: - _et = PROXYSQL_ADMIN_AUTH_ERR; - break; - case PROXYSQL_SESSION_SQLITE: - _et = PROXYSQL_SQLITE_AUTH_ERR; - default: - break; - } + } + if (sess) { + // to reduce complexing in the calling function, we do some changes here + switch (_et) { + case PROXYSQL_MYSQL_AUTH_OK: + switch (sess->session_type) { + case PROXYSQL_SESSION_ADMIN: + case PROXYSQL_SESSION_STATS: + _et = PROXYSQL_ADMIN_AUTH_OK; + break; + case PROXYSQL_SESSION_SQLITE: + _et = PROXYSQL_SQLITE_AUTH_OK; + default: + break; + } + break; + case PROXYSQL_MYSQL_AUTH_ERR: + switch (sess->session_type) { + case PROXYSQL_SESSION_ADMIN: + case PROXYSQL_SESSION_STATS: + _et = PROXYSQL_ADMIN_AUTH_ERR; + break; + case PROXYSQL_SESSION_SQLITE: + _et = PROXYSQL_SQLITE_AUTH_ERR; + default: + break; + } + break; + case PROXYSQL_MYSQL_AUTH_QUIT: + switch (sess->session_type) { + case PROXYSQL_SESSION_ADMIN: + case PROXYSQL_SESSION_STATS: + _et = PROXYSQL_ADMIN_AUTH_QUIT; + break; + case PROXYSQL_SESSION_SQLITE: + _et = PROXYSQL_SQLITE_AUTH_QUIT; + default: + break; + } + break; + case PROXYSQL_MYSQL_AUTH_CLOSE: + switch (sess->session_type) { + case PROXYSQL_SESSION_ADMIN: + case PROXYSQL_SESSION_STATS: + _et = PROXYSQL_ADMIN_AUTH_CLOSE; + break; + case PROXYSQL_SESSION_SQLITE: + _et = PROXYSQL_SQLITE_AUTH_CLOSE; + default: + break; + } + break; + default: + break; } } @@ -611,6 +682,10 @@ void MySQL_Logger::log_audit_entry(log_event_type _et, MySQL_Session *sess, MySQ // me.set_server(hid,sa,sl); } + if (xi) { + me.set_extra_info(xi); + } + wrlock(); me.write(audit.logfile, sess); diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp index 629784c93..5dbdacebc 100644 --- a/lib/MySQL_Session.cpp +++ b/lib/MySQL_Session.cpp @@ -2881,6 +2881,7 @@ __get_pkts_from_client: // break; case _MYSQL_COM_QUIT: proxy_debug(PROXY_DEBUG_MYSQL_COM, 5, "Got COM_QUIT packet\n"); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_QUIT, this, NULL); l_free(pkt.size,pkt.ptr); handler_ret = -1; return handler_ret; @@ -2967,6 +2968,7 @@ __get_pkts_from_client: c=*((unsigned char *)pkt.ptr+sizeof(mysql_hdr)); if (c==_MYSQL_COM_QUIT) { proxy_error("Unexpected COM_QUIT from client %s . Session_status: %d , client_status: %d Disconnecting it\n", buf, status, client_myds->status); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_QUIT, this, NULL); proxy_debug(PROXY_DEBUG_MYSQL_COM, 5, "Got COM_QUIT packet\n"); l_free(pkt.size,pkt.ptr); if (thread) { @@ -4237,6 +4239,7 @@ void MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C uint16_t setStatus = (nTrx ? SERVER_STATUS_IN_TRANS : 0 ); if (autocommit) setStatus += SERVER_STATUS_AUTOCOMMIT; client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_INITDB, this, NULL); client_myds->DSS=STATE_SLEEP; } else { l_free(pkt->size,pkt->ptr); @@ -4278,6 +4281,7 @@ void MySQL_Session::handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_C uint16_t setStatus = (nTrx ? SERVER_STATUS_IN_TRANS : 0 ); if (autocommit) setStatus += SERVER_STATUS_AUTOCOMMIT; client_myds->myprot.generate_pkt_OK(true,NULL,NULL,1,0,0,setStatus,0,NULL); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_INITDB, this, NULL); client_myds->DSS=STATE_SLEEP; } else { l_free(pkt->size,pkt->ptr); diff --git a/lib/MySQL_Thread.cpp b/lib/MySQL_Thread.cpp index 8ab44dcef..2b011aa3c 100644 --- a/lib/MySQL_Thread.cpp +++ b/lib/MySQL_Thread.cpp @@ -2647,6 +2647,11 @@ MySQL_Thread::~MySQL_Thread() { if (mysql_sessions) { while(mysql_sessions->len) { MySQL_Session *sess=(MySQL_Session *)mysql_sessions->remove_index_fast(0); + if (sess->session_type == PROXYSQL_SESSION_ADMIN || sess->session_type == PROXYSQL_SESSION_STATS) { + char _buf[1024]; + sprintf(_buf,"%s:%d:%s()", __FILE__, __LINE__, __func__); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_CLOSE, sess, NULL, _buf); + } delete sess; } delete mysql_sessions; @@ -3712,6 +3717,9 @@ void MySQL_Thread::process_all_sessions() { sess->active_transactions = -1; } if (sess->healthy==0) { + char _buf[1024]; + sprintf(_buf,"%s:%d:%s()", __FILE__, __LINE__, __func__); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_CLOSE, sess, NULL, _buf); unregister_session(n); n--; delete sess; @@ -3721,6 +3729,9 @@ void MySQL_Thread::process_all_sessions() { rc=sess->handler(); //total_active_transactions_+=sess->active_transactions; if (rc==-1 || sess->killed==true) { + char _buf[1024]; + sprintf(_buf,"%s:%d:%s()", __FILE__, __LINE__, __func__); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_CLOSE, sess, NULL, _buf); unregister_session(n); n--; delete sess; @@ -3730,6 +3741,9 @@ void MySQL_Thread::process_all_sessions() { if (sess->killed==true) { // this is a special cause, if killed the session needs to be executed no matter if paused sess->handler(); + char _buf[1024]; + sprintf(_buf,"%s:%d:%s()", __FILE__, __LINE__, __func__); + GloMyLogger->log_audit_entry(PROXYSQL_MYSQL_AUTH_CLOSE, sess, NULL, _buf); unregister_session(n); n--; delete sess; diff --git a/lib/ProxySQL_Admin.cpp b/lib/ProxySQL_Admin.cpp index 32c9f6751..e3a3c1507 100644 --- a/lib/ProxySQL_Admin.cpp +++ b/lib/ProxySQL_Admin.cpp @@ -3423,6 +3423,8 @@ void *child_mysql(void *arg) { sess->handler_function=admin_session_handler; MySQL_Data_Stream *myds=sess->client_myds; + sess->start_time=mysql_thr->curtime; + sess->client_myds->client_addrlen=myarg->addr_size; sess->client_myds->client_addr=myarg->addr;