From 8e81495beed7454f95e8eed8930c18552eb4bb12 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=A9=20Canna=C3=B2?= Date: Sun, 15 May 2016 21:06:04 +0000 Subject: [PATCH] Improved logging Added logging information for: - client - server - hostgroup_id - digest - duration --- include/MySQL_Data_Stream.h | 5 ++ include/MySQL_Logger.hpp | 6 ++- lib/MySQL_Logger.cpp | 80 +++++++++++++++++++++++++++++-- lib/MySQL_Session.cpp | 2 +- lib/MySQL_Thread.cpp | 7 +++ lib/mysql_data_stream.cpp | 7 +++ tools/eventslog_reader_sample.cpp | 20 +++++++- 7 files changed, 118 insertions(+), 9 deletions(-) diff --git a/include/MySQL_Data_Stream.h b/include/MySQL_Data_Stream.h index 378b243d5..f27a2a7c6 100644 --- a/include/MySQL_Data_Stream.h +++ b/include/MySQL_Data_Stream.h @@ -105,6 +105,11 @@ class MySQL_Data_Stream SSL *ssl; struct sockaddr *client_addr; + struct { + char *addr; + uint16_t port; + } addr; + unsigned int connect_tries; int connect_retries_on_failure; enum mysql_data_stream_status DSS; diff --git a/include/MySQL_Logger.hpp b/include/MySQL_Logger.hpp index 678baff05..fcf4ef575 100644 --- a/include/MySQL_Logger.hpp +++ b/include/MySQL_Logger.hpp @@ -23,11 +23,13 @@ class MySQL_Event { uint64_t total_length; unsigned char buf[10]; enum log_event_type et; + uint64_t hid; public: - MySQL_Event(uint32_t _thread_id, char * _username, char * _schemaname , uint64_t _start_time , uint64_t _end_time , uint64_t _query_digest); + MySQL_Event(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); uint64_t write_query(std::fstream *f); void set_query(const char *ptr, int len); + void set_server(int _hid, const char *ptr, int len); }; class MySQL_Logger { @@ -51,7 +53,7 @@ class MySQL_Logger { unsigned int find_next_id(); void set_datadir(char *); void set_base_filename(); - void log_request(MySQL_Session *); + void log_request(MySQL_Session *, MySQL_Data_Stream *); void flush(); }; diff --git a/lib/MySQL_Logger.cpp b/lib/MySQL_Logger.cpp index 52c16f61f..327648d3d 100644 --- a/lib/MySQL_Logger.cpp +++ b/lib/MySQL_Logger.cpp @@ -23,14 +23,18 @@ static inline int write_encoded_length(unsigned char *p, uint64_t val, uint8_t l return len; } -MySQL_Event::MySQL_Event (uint32_t _thread_id, char * _username, char * _schemaname , uint64_t _start_time , uint64_t _end_time , uint64_t _query_digest) { +MySQL_Event::MySQL_Event (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) { thread_id=_thread_id; username=_username; schemaname=_schemaname; start_time=_start_time; end_time=_end_time; query_digest=_query_digest; + client=_client; + client_len=_client_len; et=PROXYSQL_QUERY; + hid=UINT64_MAX; + server=NULL; } void MySQL_Event::set_query(const char *ptr, int len) { @@ -38,6 +42,12 @@ void MySQL_Event::set_query(const char *ptr, int len) { query_len=len; } +void MySQL_Event::set_server(int _hid, const char *ptr, int len) { + server=(char *)ptr; + server_len=len; + hid=_hid; +} + uint64_t MySQL_Event::write(std::fstream *f) { uint64_t total_bytes=0; switch (et) { @@ -59,6 +69,13 @@ uint64_t MySQL_Event::write_query(std::fstream *f) { schemaname_len=strlen(schemaname); total_bytes+=mysql_encode_length(schemaname_len,NULL)+schemaname_len; + total_bytes+=mysql_encode_length(client_len,NULL)+client_len; + + total_bytes+=mysql_encode_length(hid, NULL); + if (hid!=UINT64_MAX) { + total_bytes+=mysql_encode_length(server_len,NULL)+server_len; + } + total_bytes+=mysql_encode_length(start_time,NULL); total_bytes+=mysql_encode_length(end_time,NULL); total_bytes+=mysql_encode_length(query_digest,NULL); @@ -86,6 +103,22 @@ uint64_t MySQL_Event::write_query(std::fstream *f) { f->write((char *)buf,len); f->write(schemaname,schemaname_len); + len=mysql_encode_length(client_len,buf); + write_encoded_length(buf,client_len,len,buf[0]); + f->write((char *)buf,len); + f->write(client,client_len); + + len=mysql_encode_length(hid,buf); + write_encoded_length(buf,hid,len,buf[0]); + f->write((char *)buf,len); + + if (hid!=UINT64_MAX) { + len=mysql_encode_length(server_len,buf); + write_encoded_length(buf,server_len,len,buf[0]); + f->write((char *)buf,len); + f->write(server,server_len); + } + len=mysql_encode_length(start_time,buf); write_encoded_length(buf,start_time,len,buf[0]); f->write((char *)buf,len); @@ -217,7 +250,7 @@ void MySQL_Logger::set_datadir(char *s) { flush_log(); }; -void MySQL_Logger::log_request(MySQL_Session *sess) { +void MySQL_Logger::log_request(MySQL_Session *sess, MySQL_Data_Stream *myds) { if (enabled==false) return; if (logfile==NULL) return; @@ -225,11 +258,24 @@ void MySQL_Logger::log_request(MySQL_Session *sess) { uint64_t curtime_real=realtime_time(); uint64_t curtime_mono=sess->thread->curtime; - std::cout << " " << curtime_real << " " << curtime_mono << " " << sess->CurrentQuery.end_time << std::endl; + //std::cout << " " << curtime_real << " " << curtime_mono << " " << sess->CurrentQuery.end_time << std::endl; + int cl=0; + char *ca=(char *)""; // default + if (sess->client_myds->addr.addr) { + ca=sess->client_myds->addr.addr; + } + cl+=strlen(ca); + if (cl && sess->client_myds->addr.port) { + ca=(char *)malloc(cl+8); + sprintf(ca,"%s:%d",sess->client_myds->addr.addr,sess->client_myds->addr.port); + } + cl=strlen(ca); MySQL_Event me(sess->thread_session_id,ui->username,ui->schemaname, sess->CurrentQuery.start_time + curtime_real - curtime_mono, sess->CurrentQuery.end_time + curtime_real - curtime_mono, - GloQPro->get_digest(&sess->CurrentQuery.QueryParserArgs)); + GloQPro->get_digest(&sess->CurrentQuery.QueryParserArgs), + ca, cl + ); char *c=(char *)sess->CurrentQuery.QueryPointer; if (c) { me.set_query(c,sess->CurrentQuery.QueryLength); @@ -237,6 +283,24 @@ void MySQL_Logger::log_request(MySQL_Session *sess) { me.set_query("",0); } + int sl=0; + char *sa=(char *)""; // default + if (myds) { + if (myds->myconn) { + sa=myds->myconn->parent->address; + } + } + sl+=strlen(sa); + if (sl && myds->myconn->parent->port) { + sa=(char *)malloc(sl+8); + sprintf(sa,"%s:%d", myds->myconn->parent->address, myds->myconn->parent->port); + } + sl=strlen(sa); + if (sl) { + int hid=-1; + hid=myds->myconn->parent->myhgc->hid; + me.set_server(hid,sa,sl); + } /* ev.set_server(""); ev.set_client(""); @@ -246,11 +310,19 @@ void MySQL_Logger::log_request(MySQL_Session *sess) { me.write(logfile); + unsigned long curpos=logfile->tellp(); if (curpos > max_log_file_size) { flush_log_unlocked(); } wrunlock(); + + if (cl && sess->client_myds->addr.port) { + free(ca); + } + if (sl && myds->myconn->parent->port) { + free(sa); + } } void MySQL_Logger::flush() { diff --git a/lib/MySQL_Session.cpp b/lib/MySQL_Session.cpp index f2ad0332a..2887761ff 100644 --- a/lib/MySQL_Session.cpp +++ b/lib/MySQL_Session.cpp @@ -2138,7 +2138,7 @@ void MySQL_Session::RequestEnd(MySQL_Data_Stream *myds) { // so we track the time here CurrentQuery.end_time=thread->curtime; - GloMyLogger->log_request(this); + GloMyLogger->log_request(this, myds); // clean qpo if (qpo) { diff --git a/lib/MySQL_Thread.cpp b/lib/MySQL_Thread.cpp index 6b969de98..498666f19 100644 --- a/lib/MySQL_Thread.cpp +++ b/lib/MySQL_Thread.cpp @@ -2047,6 +2047,13 @@ void MySQL_Thread::listener_handle_new_connection(MySQL_Data_Stream *myds, unsig } sess->client_myds->client_addrlen=addrlen; sess->client_myds->client_addr=addr; + if (sess->client_myds->client_addr->sa_family==AF_INET) { + struct sockaddr_in * ipv4addr=(struct sockaddr_in *)sess->client_myds->client_addr; + sess->client_myds->addr.addr=strdup(inet_ntoa(ipv4addr->sin_addr)); + sess->client_myds->addr.port=htons(ipv4addr->sin_port); + } else { + sess->client_myds->addr.addr=strdup("localhost"); + } sess->client_myds->myprot.generate_pkt_initial_handshake(true,NULL,NULL, &sess->thread_session_id); ioctl_FIONBIO(sess->client_myds->fd, 1); mypolls.add(POLLIN|POLLOUT, sess->client_myds->fd, sess->client_myds, curtime); diff --git a/lib/mysql_data_stream.cpp b/lib/mysql_data_stream.cpp index d79ad51a6..7b1f77bfe 100644 --- a/lib/mysql_data_stream.cpp +++ b/lib/mysql_data_stream.cpp @@ -97,6 +97,9 @@ MySQL_Data_Stream::MySQL_Data_Stream() { pkts_sent=0; client_addr=NULL; + addr.addr=NULL; + addr.port=0; + sess=NULL; mysql_real_query.pkt.ptr=NULL; mysql_real_query.pkt.size=0; @@ -148,6 +151,10 @@ MySQL_Data_Stream::~MySQL_Data_Stream() { free(client_addr); client_addr=NULL; } + if (addr.addr) { + free(addr.addr); + addr.addr=NULL; + } free_mysql_real_query(); diff --git a/tools/eventslog_reader_sample.cpp b/tools/eventslog_reader_sample.cpp index a61f3c5dc..463e167f2 100644 --- a/tools/eventslog_reader_sample.cpp +++ b/tools/eventslog_reader_sample.cpp @@ -85,6 +85,7 @@ class MySQL_Event { size_t server_len; size_t client_len; uint64_t total_length; + uint64_t hid; log_event_type et; public: MySQL_Event() { @@ -107,10 +108,24 @@ class MySQL_Event { username=read_string(f,username_len); read_encoded_length((uint64_t *)&schemaname_len,f); schemaname=read_string(f,schemaname_len); - cout << "ProxySQL LOG QUERY: thread_id=\"" << thread_id << "\" username=\"" << username << "\" schemaname=" << schemaname << "\""; + read_encoded_length((uint64_t *)&client_len,f); + client=read_string(f,client_len); + cout << "ProxySQL LOG QUERY: thread_id=\"" << thread_id << "\" username=\"" << username << "\" schemaname=" << schemaname << "\" client=\"" << client << "\""; + read_encoded_length((uint64_t *)&hid,f); + if (hid==UINT64_MAX) { + cout << " HID=NULL "; + } else { + read_encoded_length((uint64_t *)&server_len,f); + server=read_string(f,server_len); + cout << " HID=" << hid << " server=\"" << server << "\""; + } read_encoded_length((uint64_t *)&start_time,f); read_encoded_length((uint64_t *)&end_time,f); read_encoded_length((uint64_t *)&query_digest,f); + char digest_hex[20]; + uint32_t d32[2]; + memcpy(&d32,&query_digest,sizeof(digest_hex)); + sprintf(digest_hex,"0x%X%X", d32[0], d32[1]); read_encoded_length((uint64_t *)&query_len,f); query_ptr=read_string(f,query_len); char buffer[26]; @@ -127,7 +142,8 @@ class MySQL_Event { strftime(buffer, 26, "%Y-%m-%d %H:%M:%S", tm_info); sprintf(buffer2,"%6u", (unsigned)(end_time%1000000)); cout << " endtime=\"" << buffer << "." << buffer2 << "\""; - cout << " query=\"" << query_ptr << "\""<< endl; + cout << " duration=" << (end_time-start_time) << "us"; + cout << " digest=\"" << digest_hex << "\"" << endl << query_ptr << endl; } ~MySQL_Event() { free(username);