Improved logging

Added logging information for:
- client
- server
- hostgroup_id
- digest
- duration
connleak
René Cannaò 10 years ago
parent fc36d5487f
commit 8e81495bee

@ -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;

@ -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();
};

@ -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() {

@ -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) {

@ -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);

@ -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();

@ -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);

Loading…
Cancel
Save