From: Rafal Somla Date: September 7 2012 1:05pm Subject: bzr push into mysql-trunk branch (rafal.somla:4084 to 4086) List-Archive: http://lists.mysql.com/commits/144734 Message-Id: <201209071305.q87D5kpJ005640@acsmt357.oracle.com> MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit 4086 Rafal Somla 2012-09-07 - protocol stage tracing with MYSQL_TRACE_STAGE() hooks in libmysql code, - move test trace plugin to separate file, move here code for tracing protocol stage changes and detecting invalid events, - different handling of trace event parameters. added: libmysql/test_trace_plugin.cc modified: include/mysql/plugin_trace.h libmysql/CMakeLists.txt libmysql/libmysql.c libmysql/mysql_trace.c libmysql/mysql_trace.h sql-common/client.c 4085 Rafal Somla 2012-08-28 - Build options for disabling/enabling the feature. - Add comments to files. modified: CMakeLists.txt include/mysql/plugin_trace.h libmysql/CMakeLists.txt libmysql/mysql_trace.c libmysql/mysql_trace.h sql-common/client.c sql-common/client_plugin.c 4084 Rafal Somla 2012-08-24 Test trace plugin inmprovements: - use per-connection data storage - do not report invalid events if error was detected modified: libmysql/mysql_trace.c === modified file 'CMakeLists.txt' --- a/CMakeLists.txt 2012-06-01 14:02:36 +0000 +++ b/CMakeLists.txt 2012-08-28 07:28:25 +0000 @@ -248,6 +248,15 @@ OPTION(OPTIMIZER_TRACE "Support tracing OPTION(INNODB_COMPILER_HINTS "Compile InnoDB with compiler hints" ON) MARK_AS_ADVANCED(INNODB_COMPILER_HINTS) +# +# Options related to client-side protocol tracing +# + +OPTION(WITH_CLIENT_PROTOCOL_TRACING + "Support for client-side protocol tracing plugins" ON) +OPTION(WITH_TEST_TRACE_PLUGIN + "Have a built-in test protocol trace plugin in libmysql (requires WITH_CLIENT_PROTOCOL_TRACING option)" OFF) + # Set DBUG_OFF and other optional release-only flags for non-debug project types FOREACH(BUILD_TYPE RELEASE RELWITHDEBINFO MINSIZEREL) FOREACH(LANG C CXX) === modified file 'include/mysql/plugin_trace.h' --- a/include/mysql/plugin_trace.h 2012-08-23 14:14:44 +0000 +++ b/include/mysql/plugin_trace.h 2012-09-07 12:42:49 +0000 @@ -6,12 +6,12 @@ #define PROTOCOL_STAGE_LIST(X) \ protocol_stage_ ## X(CONNECTING) \ - protocol_stage_ ## X(WAIT_FOR_CHALLENGE) \ + protocol_stage_ ## X(WAIT_FOR_INIT_PACKET) \ protocol_stage_ ## X(AUTHENTICATE) \ + protocol_stage_ ## X(SSL_NEGOTIATION) \ protocol_stage_ ## X(READY_FOR_COMMAND) \ - protocol_stage_ ## X(WAIT_FOR_SIMPLE_REPLY) \ protocol_stage_ ## X(WAIT_FOR_PACKET) \ - protocol_stage_ ## X(WAIT_FOR_RESULTSET) \ + protocol_stage_ ## X(WAIT_FOR_RESULT) \ protocol_stage_ ## X(WAIT_FOR_FIELD_DEF) \ protocol_stage_ ## X(WAIT_FOR_ROW) \ protocol_stage_ ## X(FILE_REQUEST) \ @@ -19,6 +19,44 @@ protocol_stage_ ## X(WAIT_FOR_PS_PARAMETER) \ protocol_stage_ ## X(DISCONNECTED) +/* + ---------------------- ----------------------------------------------------- + Connection events + ---------------------- ----------------------------------------------------- + CONNECTING Client is connecting to the server. + CONNECTED Physical connection has been established. + DISCONNECTED Connection with server was broken. + ---------------------- ----------------------------------------------------- + SSL events + ---------------------- ----------------------------------------------------- + SEND_SSL_REQUEST Client is sending SSL connection request. + SSL_CONNECT Client is initiating SSL handshake. + SSL_CONNECTED SSL connection has been established. + ---------------------- ----------------------------------------------------- + Authentication events + ---------------------- ----------------------------------------------------- + CHALLENGE_RECEIVED Client received authentication challenge. + AUTH_PLUGIN Client selects an authentication plugin to be used + in the following authentication exchange. + SEND_AUTH_RESPONSE Client sends response to the authentication + challenge. + SEND_AUTH_DATA Client sends extra authentication data packet. + AUTHENTICATED Server has accepted connection. + ---------------------- ----------------------------------------------------- + Command phase events + ---------------------- ----------------------------------------------------- + SEND_COMMAND Cleint is sending a command to the server. + SEND_FILE Client is sending local file contents to the server. + ---------------------- ----------------------------------------------------- + General events + ---------------------- ----------------------------------------------------- + READ_PACKET Client starts waiting for a packet from server. + PACKET_RECEIVED A packet from server has been received. + PACKET_SENT After successful sending of a packet to the server. + ERROR Client detected an error. + ---------------------- ----------------------------------------------------- +*/ + #define TRACE_EVENT_LIST(X) \ trace_event_ ## X(ERROR) \ trace_event_ ## X(CONNECTING) \ @@ -27,7 +65,7 @@ trace_event_ ## X(SEND_SSL_REQUEST) \ trace_event_ ## X(SSL_CONNECT) \ trace_event_ ## X(SSL_CONNECTED) \ - trace_event_ ## X(CHALLENGE_RECEIVED) \ + trace_event_ ## X(INIT_PACKET_RECEIVED) \ trace_event_ ## X(AUTH_PLUGIN) \ trace_event_ ## X(SEND_AUTH_RESPONSE) \ trace_event_ ## X(SEND_AUTH_DATA) \ @@ -56,6 +94,17 @@ enum trace_event { }; +struct st_trace_event_args +{ + const char *plugin_name; + int cmd; + const void *hdr; + size_t hdr_len; + const void *pkt; + size_t pkt_len; +}; + + struct st_mysql_client_plugin_TRACE; struct st_mysql; @@ -73,15 +122,7 @@ void (trace_event_handler)(struct st_mys struct st_mysql *connection_handle, enum protocol_stage stage, enum trace_event event, - va_list args); -typedef -enum protocol_stage - (invalid_event_handler)(struct st_mysql_client_plugin_TRACE *self, - void *data, - struct st_mysql *connection_handle, - enum protocol_stage stage, - enum trace_event event); - + struct st_trace_event_args args); struct st_mysql_client_plugin_TRACE @@ -90,7 +131,6 @@ struct st_mysql_client_plugin_TRACE tracing_start_callback *tracing_start; tracing_stop_callback *tracing_stop; trace_event_handler *trace_event; - invalid_event_handler *invalid_event; }; === modified file 'libmysql/CMakeLists.txt' --- a/libmysql/CMakeLists.txt 2012-07-20 16:36:35 +0000 +++ b/libmysql/CMakeLists.txt 2012-09-07 12:42:49 +0000 @@ -137,7 +137,6 @@ CACHE INTERNAL "Functions exported by cl ) SET(CLIENT_SOURCES - mysql_trace.c get_password.c libmysql.c errmsg.c @@ -151,8 +150,19 @@ SET(CLIENT_SOURCES ../sql/password.c ) +IF (WITH_CLIENT_PROTOCOL_TRACING) + +LIST(APPEND CLIENT_SOURCES mysql_trace.c) +ADD_DEFINITIONS(-D CLIENT_PROTOCOL_TRACING) + +IF (WITH_TEST_TRACE_PLUGIN) + LIST(APPEND CLIENT_SOURCES test_trace_plugin.cc) + ADD_DEFINITIONS(-D TEST_TRACE_PLUGIN) +ENDIF (WITH_TEST_TRACE_PLUGIN) + +ENDIF (WITH_CLIENT_PROTOCOL_TRACING) + -ADD_DEFINITIONS(-D TEST_TRACE_PLUGIN) # We do RESTRICT_SYMBOL_EXPORTS(yassl) elsewhere. # In order to get correct symbol visibility, md5.cc and sha1.cc === modified file 'libmysql/libmysql.c' --- a/libmysql/libmysql.c 2012-08-24 10:53:38 +0000 +++ b/libmysql/libmysql.c 2012-09-07 12:42:49 +0000 @@ -948,6 +948,11 @@ const char *cli_read_statistics(MYSQL *m set_mysql_error(mysql, CR_WRONG_HOST_INFO, unknown_sqlstate); return mysql->net.last_error; } + /* + After reading the single packet with reply to COM_STATISTICS + we are ready for new commands. + */ + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); return (char*) mysql->net.read_pos; } @@ -1422,6 +1427,8 @@ my_bool cli_read_prepare_result(MYSQL *m { MYSQL_DATA *param_data; + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_PS_PARAMETER); + /* skip parameters data: we don't support it yet */ if (!(param_data= (*mysql->methods->read_rows)(mysql, (MYSQL_FIELD*)0, 7))) DBUG_RETURN(1); @@ -1433,6 +1440,8 @@ my_bool cli_read_prepare_result(MYSQL *m if (!(mysql->server_status & SERVER_STATUS_AUTOCOMMIT)) mysql->server_status|= SERVER_STATUS_IN_TRANS; + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_FIELD_DEF); + if (!(fields_data= (*mysql->methods->read_rows)(mysql,(MYSQL_FIELD*)0,7))) DBUG_RETURN(1); if (!(stmt->fields= unpack_fields(mysql, fields_data,&stmt->mem_root, @@ -1440,6 +1449,9 @@ my_bool cli_read_prepare_result(MYSQL *m mysql->server_capabilities))) DBUG_RETURN(1); } + + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); + stmt->field_count= field_count; stmt->param_count= (ulong) param_count; DBUG_PRINT("exit",("field_count: %u param_count: %u warning_count: %u", @@ -4309,6 +4321,12 @@ int cli_read_binary_rows(MYSQL_STMT *stm mysql->server_status= uint2korr(cp+3); DBUG_PRINT("info",("status: %u warning_count: %u", mysql->server_status, mysql->warning_count)); +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif DBUG_RETURN(0); } } === modified file 'libmysql/mysql_trace.c' --- a/libmysql/mysql_trace.c 2012-08-24 14:58:05 +0000 +++ b/libmysql/mysql_trace.c 2012-09-07 12:42:49 +0000 @@ -1,15 +1,50 @@ +/** + @file + + Client-side protocol tracing infrastructure + =========================================== + + If a plugin of type MYSQL_CLIENT_TRACE_PLUGIN is loaded into + libmysql and its instance is pointed by the global trace_plugin + pointer, this plugin is notified of various protocol trace events + (see include/mysql/plugin_trace.h for the list). + + These trace events are generated with MYSQL_TRACE() macro put in + relevant places in libmysql code. The macro calls mysql_trace_trace() + function defined here. This function calls trace plugin's + trace_event() method, if it is defined. + + To correctly interpret each trace event, trace plugin is informed + of the current protocol stage (see include/mysql/plugin_trace.h for + list of stages). Function mysql_trace_trace() calls + protocol_stage_change() function which analyses trace events and + updates current protocol stage accordingly. + + If an event which is invalid for a given protocol stage is detected + and if trace plugin defines invalid_event() method, this method is + called and it determines if tracing should continue and what should + be the next protocol stage. If invalid_event() method is not defined, + tracing of the connection is interrupted upon detecting + invalid event. +*/ + #include #include "mysql.h" #include "mysql_trace.h" -/* +#include /* memcpy */ + +/** The global trace_plugin pointer. If it is not NULL, it points at a loaded trace plugin which should be used to trace all connections made to the server. */ struct st_mysql_client_plugin_TRACE *trace_plugin= NULL; - +/* + Macros for manipulating trace_info structure + defined in mysql_trace.h +*/ #define GET_DATA(TI) (TI)->trace_plugin_data #define SET_DATA(TI,D) GET_DATA(TI) = (D) #define GET_STAGE(TI) (TI)->stage @@ -18,983 +53,103 @@ struct st_mysql_client_plugin_TRACE *tra #define SET_PS_INFO(TI,P,C) do { (TI)->param_count= (P); (TI)->col_count= (C); } while(0) #define GET_PS_INFO(TI,P,C) do { (P)= (TI)->param_count; (C)= (TI)->col_count; } while(0) + #ifndef DBUG_OFF +/* + Functions for gettig names of trace events and protocol + stages for debugging purposes. +*/ -#define protocol_stage_name(X) case PROTOCOL_STAGE_ ## X: return #X; +#define protocol_stage_get_name(X) case PROTOCOL_STAGE_ ## X: return #X; const char* stage_name(enum protocol_stage stage) { switch(stage) { - PROTOCOL_STAGE_LIST(name) + PROTOCOL_STAGE_LIST(get_name) default: return ""; } } -#define trace_event_name(X) case TRACE_EVENT_ ## X: return #X; +#define trace_event_get_name(X) case TRACE_EVENT_ ## X: return #X; const char* event_name(enum trace_event ev) { switch(ev) { - TRACE_EVENT_LIST(name) + TRACE_EVENT_LIST(get_name) default: return ""; } } #endif -int protocol_stage_change(struct st_mysql_trace_info*, enum trace_event, va_list); -void mysql_trace_trace(struct st_mysql_client_plugin_TRACE *plugin, - enum trace_event ev, - struct st_mysql *m, ...) +void mysql_trace_start(struct st_mysql *m) { - va_list args, args_copy; \ - struct st_mysql_trace_info *trace_info= TRACE_DATA(m); - - if (ev == TRACE_EVENT_CONNECTING) - { - /* Initialize tracing in a new connection. */ - - trace_info= my_malloc(sizeof(struct st_mysql_trace_info), - MYF(MY_ZEROFILL)); - if (!trace_info) - return; - - TRACE_DATA(m)= trace_info; - SET_STAGE(trace_info, CONNECTING); - SET_DATA(trace_info, - plugin->tracing_start ? - plugin->tracing_start(plugin, m, PROTOCOL_STAGE_CONNECTING) : - NULL - ); - } - + struct st_mysql_trace_info *trace_info; + + trace_info= my_malloc(sizeof(struct st_mysql_trace_info), + MYF(MY_ZEROFILL)); if (!trace_info) - { - /* - There is no trace_info structure for this connection (out of memory?). - We are bailing out. - */ return; - } - - va_start(args,m); - /* - We pass event args to plugins trace_event method and later also to - protocol_stage_change() function. The same va_list value can not be - parsed twice so we need to make a copy for the second use. - - Note: __va_copy() is a non-standard extension of gcc. We assume - here that if va_list values can not be copied with assignemnt then - __va_copy() macro is defined. - */ - -#ifdef __va_copy - __va_copy(args_copy, args); -#else - args_copy= args; -#endif - - if (plugin->trace_event) - { - plugin->trace_event(plugin, GET_DATA(trace_info), m, - GET_STAGE(trace_info), ev, args); - } + trace_info->plugin= trace_plugin; + trace_info->stage= PROTOCOL_STAGE_CONNECTING; - /* Follow protocol stage changes */ - - if (protocol_stage_change(trace_info, ev, args_copy)) - { - /* - If plugin's invalid_event callback is defined, inform - the plugin about invalid event and let it determine which - protocol stage should be assumed now. Otherwise set protocol - stage to CLOSED which will end tracing in this connection. - */ - if(plugin->invalid_event) - GET_STAGE(trace_info)= - plugin->invalid_event(plugin, m, - GET_DATA(trace_info), - GET_STAGE(trace_info), - ev); - else - SET_STAGE(trace_info, DISCONNECTED); - } - - va_end(args); - - /* Stop tracing if end of connection. */ - - if (TEST_STAGE(trace_info, DISCONNECTED)) - { - plugin->tracing_stop(plugin, m, GET_DATA(trace_info)); - //my_free(GET_DATA(trace_info)); - SET_DATA(trace_info, NULL); - } + if (trace_info->plugin->tracing_start) + trace_info->trace_plugin_data= + trace_info->plugin->tracing_start( + trace_info->plugin, + m, PROTOCOL_STAGE_CONNECTING); + else + trace_info->trace_plugin_data= NULL; + TRACE_DATA(m)= trace_info; } -// =========================== -// Protocol stage tracing -// =========================== - -typedef unsigned char byte; - -/* - Macro to get packet pointer and length from a variable - argument list. -*/ -#define get_pkt(ARGS, BUF, LEN) \ - do { \ - LEN= va_arg(args, size_t); \ - BUF= va_arg(args, byte*); \ - } while (0) - +/** + Report a protocol trace event to trace plugin. -#define OK_PACKET(PKT) (*(PKT) == 0x00) -#define ERR_PACKET(PKT) (*(PKT) == 0xFF) -#define EOF_PACKET(PKT) (*(PKT) == 0xFE) -#define FILE_REQUEST(PKT) (*(PKT) == 0xFB) + Calls plugin's trace_event() method, if it is defined, passing to + it the event, the current protocol stage and event arguments (if any). + After reporting event to the plugin, the current protocol stage is + updated with protocol_stage_change() function. -void test_packet_dump(const char*, void*, size_t); - -/* - Returns zero if protocol stage was correctly updated, non-zero otherwise (invalid trace event). + @param plugin the trace plugin + @param ev trace event to be reported + @param m MYSQL connection handle + @param args trace event arguments */ -int protocol_stage_change(struct st_mysql_trace_info *ti, enum trace_event ev, va_list args) -{ - //printf("Tracing stage change at %s, event %s\n", stage_name(GET_STAGE(ti)), event_name(ev)); - - /* - ERROR trace event never changes the current protocol stage. - */ - if (ev == TRACE_EVENT_ERROR) - return 0; - - /* - Move to DISCONNECTED stage if connection was closed by client. - */ - if (ev == TRACE_EVENT_DISCONNECTED) - { - SET_STAGE(ti, DISCONNECTED); - return 0; - } - - - switch (GET_STAGE(ti)) - { - /* ----------------------------- */ - case PROTOCOL_STAGE_CONNECTING: - /* - This is the first stage of the protocol, when client is establishing - physical connection with the server. After connection is established - protocol moves to WAIT_FOR_CHALLENGE stage where the first - authentication challenge packet is expected from the server. - */ - switch (ev) - { - case TRACE_EVENT_CONNECTING: return 0; - case TRACE_EVENT_CONNECTED: SET_STAGE(ti, WAIT_FOR_CHALLENGE); return 0; - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_CHALLENGE: - /* - In this stage client waits for the first challenge packet from the - server. When it is received, protocol movest to AUTHENTICATE stage - where client authorizes itself against server. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: return 0; - case TRACE_EVENT_CHALLENGE_RECEIVED: SET_STAGE(ti, AUTHENTICATE); return 0; - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_AUTHENTICATE: - /* - In this stage client exchanges various packets with the server to: - - authenticate itself against the server, - - negotiante client/server capabilities and connection parameters, - - establish encrypted SSL connection. - At any moment during this exchange server can send an ERR packet - indicating that it rejects the connection. - */ - switch (ev) - { - case TRACE_EVENT_AUTHENTICATED: SET_STAGE(ti, READY_FOR_COMMAND); return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - - get_pkt(args, pkt, pkt_len); - - /* - Move to DISCONNECTED stage if ERR packet was received from the - server. - */ - if (ERR_PACKET(pkt)) - SET_STAGE(ti, DISCONNECTED); - - return 0; - } - case TRACE_EVENT_SEND_SSL_REQUEST: - case TRACE_EVENT_SSL_CONNECT: - case TRACE_EVENT_SSL_CONNECTED: - case TRACE_EVENT_AUTH_PLUGIN: - case TRACE_EVENT_SEND_AUTH_RESPONSE: - case TRACE_EVENT_SEND_AUTH_DATA: - case TRACE_EVENT_READ_PACKET: - case TRACE_EVENT_PACKET_SENT: - return 0; - - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_READY_FOR_COMMAND: - /* - This is the stage when client can send a command to the server. - After sending command packet to the server, PACKET_SENT trace - event happens. The next stage depends on whether a result set - is expected after the command, or just OK/ERR reply or it is - a command with no reply from server. - */ - switch (ev) - { - case TRACE_EVENT_SEND_COMMAND: - ti->last_command = va_arg(args, int); - /* Reset PS information stored in trace info record */ - SET_PS_INFO(ti, 0, 0); - return 0; - - case TRACE_EVENT_PACKET_SENT: - switch (ti->last_command) - { - case COM_QUIT: SET_STAGE(ti, DISCONNECTED); break; - case COM_STMT_PREPARE: SET_STAGE(ti, WAIT_FOR_PS_DESCRIPTION); break; - case COM_QUERY: - case COM_STMT_EXECUTE: SET_STAGE(ti, WAIT_FOR_RESULTSET); break; - - /* - No server reply is expected after these commands so we reamin ready - for the next command. - */ - case COM_REFRESH: - case COM_STMT_SEND_LONG_DATA: - case COM_STMT_CLOSE: - case COM_REGISTER_SLAVE: - return 0; - - /* - These replication commands are not supported and are reported as - invalid events (trace plugin can decide how to continue). - */ - case COM_BINLOG_DUMP: - case COM_BINLOG_DUMP_GTID: - case COM_TABLE_DUMP: - return 1; - - /* - After COM_PROCESS_INFO server sends a regular result set. - */ - case COM_PROCESS_INFO: - SET_STAGE(ti, WAIT_FOR_RESULTSET); - break; - - /* - Server replies to COM_STATISTICS with a single packet - containing a string with statistics information. - */ - case COM_STATISTICS: - SET_STAGE(ti, WAIT_FOR_PACKET); - break; - - case COM_CHANGE_USER: - SET_STAGE(ti, AUTHENTICATE); - break; - - default: - SET_STAGE(ti, WAIT_FOR_SIMPLE_REPLY); - break; - }; - return 0; - - case TRACE_EVENT_AUTH_PLUGIN: - /* - The AUTH_PLUGIN event can happen in READY_FOR_COMMAND stage - before COM_CHANGE_USER is executed. When the command is executed - the stage will be changed to AUTHENTICATE. - */ - return 0; - - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_SIMPLE_REPLY: - /* - This stage is reached after a command which produces no result set. - Server can reply with ERR or OK packet, indicating command execution - error or success, respectively. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - - get_pkt(args, pkt, pkt_len); - - /* - If the expected ERR, EOF or OK packet is received, we are ready for - a new command. Otherwise something is wrong and we report invalid - event. - */ - - if (ERR_PACKET(pkt) || OK_PACKET(pkt) || EOF_PACKET(pkt)) - { - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - } - - return 1; - } - - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_PACKET: - /* - After some commands (COM_STATISTICS) server sends just a - single packet and then it is ready for processing more - commands. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_RESULTSET: - /* - This stage is reached after a command which can produce a result set - (COM_QUERY or COM_STMT_EXECUTE). In this stage a single packet is - received from the server informing about the result of the query: - - ERR packet informs that error has happened when processing query, - - OK packet informs that query produced no result set, - - FILE_REQUEST packet asks client to send contents of a given file, - Otherwise information about the number of columns in the result set - is received. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - - get_pkt(args, pkt, pkt_len); - -// test_packet_dump("== resultset packet", pkt, pkt_len); - - /* - If server sends ERR, query processing is done - and next stage is READY_FOR_COMMAND. - */ - - if (ERR_PACKET(pkt)) - { - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - } - - /* - If server sends FILE_REQUEST packet, we move to FILE_REQUEST - stage of the protocol. - */ - if (FILE_REQUEST(pkt)) - { - SET_STAGE(ti, FILE_REQUEST); - return 0; - } - - /* - If query generates no data, server replies with OK packet. In - case of a multi-query, more result sets can follow, as - indicated by SERVER_MORE_RESULTS_EXISTS flag in the OK packet. - If the flag is set we move to WAIT_FOR_RESULTSET stage to - read the following result set(s). - */ - if (OK_PACKET(pkt)) - { - /* Extract flags from the OK packet */ - unsigned int flags; - pkt++; /* cmd header */ - (void)net_field_length(&pkt); /* affected_rows */ - (void)net_field_length(&pkt); /* last_insert_id */ - flags= uint2korr(pkt); - - if (SERVER_MORE_RESULTS_EXISTS & flags) - SET_STAGE(ti, WAIT_FOR_RESULTSET); - else - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - } - - /* - Otherwise a result set is expected from the server so we move - to WAIT_FOR_FIELD_DEF stage. - */ - - SET_STAGE(ti, WAIT_FOR_FIELD_DEF); - return 0; - } - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_FIELD_DEF: - /* - In this stage definitions of row fields are read from server. This - can happen when reading query result set, or after preparing - a statement which produces result set or upon explicit COM_FIELD_LIST - request. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - - get_pkt(args, pkt, pkt_len); - - /* - If the received packet is not an EOF packet, then it is description - of the next row field and we can continue, remaining in the same stage. - - To correctly recognize EOF packets we have to check its length, because - a field description packet can theoretically start with byte 0xFE - the - same as the first byte of the EOF packet. - - This can happen if the first length-encoded string in the packet starts - with 8-byte length-encoded integer whose first byte is 0xFE. In this - case the string and thus the whole packet is longer than 9 bytes and\ - EOF packet is always shorter than 9 bytes. - */ - - if (!(EOF_PACKET(pkt) && pkt_len < 9)) - return 0; - - /* - If this WAIT_FOR_FIELD_DEF stage was reached after COM_STMT_PREPARE or - COM_FIELD_LIST then the EOF packet ends proccesing of the command and - next stage is READY_FOR_COMMAND. - Otherwise we are reading a result set and the field definitions have - ended - next stage is WAIT_FOR_ROW. - */ - switch (ti->last_command) - { - case COM_STMT_PREPARE: - case COM_FIELD_LIST: - SET_STAGE(ti, READY_FOR_COMMAND); - break; - default: - SET_STAGE(ti, WAIT_FOR_ROW); - } - - return 0; - } - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_ROW: - /* - This stage is entered when reading a result set, after receiving - its metadata. In this stage server sends packets with rows unitl - EOF or ERR packet is sent. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - unsigned int flags; - - get_pkt(args, pkt, pkt_len); - - /* - If ERR packet is received, an error has happened and reading - the result set is done. Next stage is READY_FOR_COMMAND. - */ - - if (ERR_PACKET(pkt)) - { - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - } - - /* - Otherwise row packets are received until we get an EOF packet. - We need to check packet length again, because a text-protocol - row packet starts with a length-encoded string and thus its - first byte can be 0xFE. - */ - - if (!(EOF_PACKET(pkt) && pkt_len < 9)) - return 0; - - /* - In case of a multi-resutset a SERVER_MORE_RESULTS_EXISTS flag can - be set in the EOF packet. In that case next resultset will follow - and the next stage is WAIT_FOR_RESULTSET. If - SERVER_MORE_RESULTS_EXISTS flag is not set, next stage is - READY_FOR_COMMAND. - */ - - flags= uint2korr(pkt+3); - -// fprintf(stderr, "== EOF packet flags: 0x%x\n", flags); - - if (SERVER_MORE_RESULTS_EXISTS & flags) - SET_STAGE(ti, WAIT_FOR_RESULTSET); - else - SET_STAGE(ti, READY_FOR_COMMAND); - - return 0; - } - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_PS_DESCRIPTION: - /* - This stage is entered after executing COM_PREPARE_STMT command. - Server should send stmt OK packet with information about the - statement. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 1; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - unsigned col_count, param_count; - - get_pkt(args, pkt, pkt_len); - - /* - If we do not get OK packet here, something is wrong. - */ - if (!OK_PACKET(pkt)) - return 1; - - /* - Otherwise we read information about statement parameters - (param_count) and produced result set (col_count) and store - it in the ti structure. - */ - - col_count = uint2korr(pkt+5); - param_count = uint2korr(pkt+7); - - SET_PS_INFO(ti, param_count, col_count); - - /* - If statement has parameters then next stage is - WAIT_FOR_PS_PARAMETER, where server sends parameter - descriptions. - */ - - if (0 < param_count) - { - SET_STAGE(ti, WAIT_FOR_PS_PARAMETER); - return 0; - } - - /* - Otherwise, if statement has no parameters but produces - a result set, the next stage is WAIT_FOR_FIELD_DEF where - server sends descriptions of result set fields. - */ - - if (0 < col_count) - { - SET_STAGE(ti, WAIT_FOR_FIELD_DEF); - return 0; - } - - /* - Otherwise (no parameters and no result set), preparing - the statement is done and next stage is READY_FOR_COMMAND. - */ - - SET_STAGE(ti, READY_FOR_COMMAND); - return 0; - } - default: return 1; - } - - /* ----------------------------- */ - case PROTOCOL_STAGE_WAIT_FOR_PS_PARAMETER: - /* - This stage is reached after COM_PREPARE_STMT command and after - receiving the stmt OK packet from the server (if the statement - has parameters). Server sends descriptions of the parameters in - the same format in which result set fields are described. - */ - switch (ev) - { - case TRACE_EVENT_READ_PACKET: return 0; - case TRACE_EVENT_PACKET_RECEIVED: - { - byte *pkt; - size_t pkt_len; - unsigned param_count, col_count; - - get_pkt(args, pkt, pkt_len); - - /* - Sending parameter descriptions continues until an EOF - packet is received. To correctly recognize EOF packet - we must check the packet length the same as - in WAIT_FOR_FILED_DEF stage. - */ - - if (!(EOF_PACKET(pkt) && pkt_len < 9)) - { - return 0; - } - - /* - After receiving EOF packets next stage depends on whether - the statement produces any result set, in which case column - definitions will follow, or not. - - We decide this based on statement info stored in the ti - structure. - */ - - GET_PS_INFO(ti, param_count, col_count); - - if (0 < col_count) - SET_STAGE(ti, WAIT_FOR_FIELD_DEF); - else - SET_STAGE(ti, READY_FOR_COMMAND); - - return 0; - } - default: return 1; - } - - /* ----------------------------- */ - case PROTOCOL_STAGE_FILE_REQUEST: - /* - At this stage client should send a single packet - containing contnents of the file requested by the server. - */ - switch (ev) - { - case TRACE_EVENT_SEND_FILE: return 0; - case TRACE_EVENT_PACKET_SENT: - { - size_t len = va_arg(args, size_t); - // empty packet indicates end of file - then server can - // send a result set - if (0 == len) - SET_STAGE(ti, WAIT_FOR_RESULTSET); - return 0; - } - - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - case PROTOCOL_STAGE_DISCONNECTED: - /* - This is the final stage reached when connection with - server ends. - */ - switch (ev) - { - default: return 1; // invalid event - }; - break; - - /* ----------------------------- */ - default: return 1; // unknown protocol stage - - } // switch () - - return 1; -} - -// =========================== -// Test plugin -// =========================== - -#ifdef TEST_TRACE_PLUGIN - -tracing_start_callback test_trace_plugin_start; -tracing_stop_callback test_trace_plugin_stop; -trace_event_handler test_trace_plugin_trace; -invalid_event_handler test_trace_plugin_invalid_event; - -int test_trace_plugin_init(char *a, size_t b, int argc, va_list args); -int test_trace_plugin_deinit(); - - -struct st_mysql_client_plugin_TRACE test_trace_plugin= -{ - MYSQL_CLIENT_TRACE_PLUGIN, - MYSQL_CLIENT_TRACE_PLUGIN_INTERFACE_VERSION, - "test_trace_plugin", - "Rafal Somla", - "A plugin for testing protocl tracing infrastructure", - {0,1,0}, - "GPL", - NULL, - test_trace_plugin_init, - test_trace_plugin_deinit, - NULL, // option handling - test_trace_plugin_start, - test_trace_plugin_stop, - test_trace_plugin_trace, - test_trace_plugin_invalid_event -}; - - -#include // For isprint() - -void hexdump(void *ptr, int buflen) { - unsigned char *buf = (unsigned char*)ptr; - int i, j; - for (i=0; i 512 ? 512 : len); - printf("==================\n"); -} - - -static my_bool test_trace_log_enabled= 0; - -void test_trace_log(const char *fmt, ...) -{ - va_list args; - - if (!test_trace_log_enabled) - return; - - va_start(args, fmt); - vfprintf(stderr, fmt, args); - fprintf(stderr, "\n"); - va_end(args); -} - - -struct st_test_trace_plugin_data -{ - char error; - int saved_cmd; - char saved_cmd_hdr[128]; - size_t saved_cmd_hdr_len; - char saved_cmd_args[128]; - size_t saved_cmd_args_len; - char saved_pkt[128]; - size_t saved_pkt_len; -}; - - -void* -test_trace_plugin_start(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), - MYSQL *conn __attribute__((unused)), enum protocol_stage stage) -{ - struct st_test_trace_plugin_data *data; - test_trace_log("Starting tracing connection in stage %s", stage_name(stage)); - data= my_malloc(sizeof(struct st_test_trace_plugin_data), MYF(MY_ZEROFILL)); - return data; -} - -void -test_trace_plugin_stop(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), - MYSQL *conn __attribute__((unused)), - void *data) -{ - my_free(data); - test_trace_log("Connection tracing ended"); -} - -struct st_test_trace_plugin_data dummy_data; - -void -test_trace_plugin_trace(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), - void *data_ptr, MYSQL *conn, - enum protocol_stage stage, enum trace_event ev, - va_list args) +void mysql_trace_trace(struct st_mysql *m, + enum trace_event ev, + struct st_trace_event_args args) { - struct st_test_trace_plugin_data *data= data_ptr ? data_ptr : &dummy_data; - - test_trace_log("%02d = %s = Trace event: %s", - conn->thread_id, stage_name(stage), event_name(ev)); + struct st_mysql_trace_info *trace_info= TRACE_DATA(m); + struct st_mysql_client_plugin_TRACE *plugin= trace_info ? trace_info->plugin : NULL; -// saved_cmd= 0; -// saved_cmd_hdr= saved_cmd_args= saved_pkt= NULL; + DBUG_ASSERT(trace_info); - if (ev == TRACE_EVENT_ERROR) - { - struct st_mysql *m = (struct st_mysql*)conn; - int errnum= m->net.last_errno; - const char* error= m->net.last_error; - test_trace_log(" = Error %d: %s", errnum, error); - data->error= 1; - } + /* Call plugin's trace_event() method if defined */ - switch (ev) + if (plugin->trace_event) { - case TRACE_EVENT_SEND_COMMAND: - // command, hdrsize, argsize, hdr, args - data->saved_cmd= va_arg(args, int); - data->saved_cmd_hdr_len= va_arg(args, size_t); - data->saved_cmd_args_len= va_arg(args, size_t); - - if (data->saved_cmd_hdr_len > sizeof(data->saved_cmd_hdr)) - data->saved_cmd_hdr_len= sizeof(data->saved_cmd_hdr); - - if (data->saved_cmd_args_len > sizeof(data->saved_cmd_args)) - data->saved_cmd_args_len= sizeof(data->saved_cmd_args); - - memcpy(data->saved_cmd_hdr, va_arg(args, void*), data->saved_cmd_hdr_len); - memcpy(data->saved_cmd_args, va_arg(args, void*), data->saved_cmd_args_len); - - if (COM_QUERY == data->saved_cmd) - test_trace_log("== QUERY: %s", data->saved_cmd_args); - else - test_trace_log("== cmd: %d", data->saved_cmd); - break; - - case TRACE_EVENT_PACKET_RECEIVED: - // size, packet - data->saved_pkt_len= va_arg(args, size_t); - if (data->saved_pkt_len > sizeof(data->saved_pkt)) - data->saved_pkt_len= sizeof(data->saved_pkt); - memcpy(data->saved_pkt, va_arg(args, void*), data->saved_pkt_len); - break; - - default: - // do nothing - break; + plugin->trace_event(plugin, GET_DATA(trace_info), m, + GET_STAGE(trace_info), ev, args); } -} - - -enum protocol_stage -test_trace_plugin_invalid_event(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), - void *data_ptr, - MYSQL *conn __attribute__((unused)), - enum protocol_stage stage, - enum trace_event ev) -{ - struct st_test_trace_plugin_data *data= data_ptr ? data_ptr : &dummy_data; - - if (PROTOCOL_STAGE_DISCONNECTED == stage) - return stage; - - if (data->error) - return stage; - - if (PROTOCOL_STAGE_WAIT_FOR_RESULTSET == stage - && TRACE_EVENT_SEND_COMMAND == ev - && COM_QUIT == data->saved_cmd) - return PROTOCOL_STAGE_DISCONNECTED; - printf("= %s = Event %s is invalid in this stage\n", stage_name(stage), event_name(ev)); - if(data->saved_pkt) - test_packet_dump("Received packet", data->saved_pkt, data->saved_pkt_len); - - printf("= last command: %d\n", data->saved_cmd); + /* Stop tracing if end of connection. */ - if(data->saved_cmd_hdr || data->saved_cmd_args) + if (TEST_STAGE(trace_info, DISCONNECTED) + || TRACE_EVENT_DISCONNECTED == ev) { - test_packet_dump("CMD header", data->saved_cmd_hdr, data->saved_cmd_hdr_len); - test_packet_dump("CMD args", data->saved_cmd_args, data->saved_cmd_args_len); + plugin->tracing_stop(plugin, m, GET_DATA(trace_info)); + my_free(trace_info); + TRACE_DATA(m)= NULL; } - - fflush(stdout); - - //assert(0); - return PROTOCOL_STAGE_DISCONNECTED; -} - - -int test_trace_plugin_init(char *a __attribute__((unused)), - size_t b __attribute__((unused)), - int argc __attribute__((unused)), - va_list args __attribute__((unused))) -{ - const char *opt= getenv("MYSQL_TEST_TRACE_PLUGIN_LOGGING"); - - if (opt && '0' != *opt) - test_trace_log_enabled= 1; - test_trace_log("Test trace plugin initialized"); - return 0; } - -int test_trace_plugin_deinit() -{ - test_trace_log("Test trace plugin de-initialized"); - return 0; -} - -#endif === modified file 'libmysql/mysql_trace.h' --- a/libmysql/mysql_trace.h 2012-08-24 10:53:38 +0000 +++ b/libmysql/mysql_trace.h 2012-09-07 12:42:49 +0000 @@ -1,12 +1,20 @@ #ifndef MYSQL_TRACE_INCLUDED #define MYSQL_TRACE_INCLUDED +#if !defined(CLIENT_PROTOCOL_TRACING) || defined(MYSQL_SERVER) + +#define MYSQL_TRACE(E,M,ARGS) +#define MYSQL_TRACE_STAGE(M,S) + +#else + #include #include /* for MYSQL_EXTENSION() */ #include struct st_mysql_trace_info { + struct st_mysql_client_plugin_TRACE *plugin; void *trace_plugin_data; enum protocol_stage stage; enum enum_server_command last_command; // Last command sent to server @@ -14,50 +22,62 @@ struct st_mysql_trace_info unsigned col_count; }; + #define TRACE_DATA(M) (MYSQL_EXTENSION(M)->trace_data) -#ifndef MYSQL_SERVER +void mysql_trace_trace(struct st_mysql*, + enum trace_event, + struct st_trace_event_args); +void mysql_trace_start(struct st_mysql*); + +#define MYSQL_TRACE(E,M,ARGS) \ + do { \ + if (NULL == TRACE_DATA(M)) break; \ + { \ + struct st_trace_event_args event_args= \ + TRACE_ARGS_ ## E ARGS; \ + mysql_trace_trace(M, \ + TRACE_EVENT_ ## E, \ + event_args); \ + } \ + } while(0) -void mysql_trace_trace(struct st_mysql_client_plugin_TRACE*, - enum trace_event, struct st_mysql*, - ...); - -#define MYSQL_TRACE(E,M,ARGS) \ - do { \ - if (NULL == trace_plugin) break; \ - mysql_trace_trace(trace_plugin, \ - TRACE_EVENT_ ## E, \ - M TRACE_ARGS_ ## E ARGS); \ +#define MYSQL_TRACE_STAGE(M,S) \ + do { \ + if (TRACE_DATA(M)) \ + TRACE_DATA(M)->stage= PROTOCOL_STAGE_ ## S; \ + else if (PROTOCOL_STAGE_CONNECTING == PROTOCOL_STAGE_ ## S) \ + mysql_trace_start(M); \ } while(0) - -#define TRACE_ARGS_SEND_SSL_REQUEST(Size, Packet) , Size, Packet -#define TRACE_ARGS_SEND_AUTH_RESPONSE(Size, Packet) , Size, Packet -#define TRACE_ARGS_SEND_AUTH_DATA(Size, Packet) , Size, Packet -#define TRACE_ARGS_AUTH_PLUGIN(PluginName) , PluginName +/* + Macros to parse event arguments and initialize the st_trace_event_args structure + accordingly. +*/ + +#define TRACE_ARGS_SEND_SSL_REQUEST(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } +#define TRACE_ARGS_SEND_AUTH_RESPONSE(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } +#define TRACE_ARGS_SEND_AUTH_DATA(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } +#define TRACE_ARGS_AUTH_PLUGIN(PluginName) { PluginName, 0, NULL, 0, NULL, 0 } #define TRACE_ARGS_SEND_COMMAND(Command, HdrSize, ArgSize, Header, Args) \ - , Command, HdrSize, ArgSize, Header, Args -#define TRACE_ARGS_SEND_FILE(Size, Packet) , Size, Packet - -#define TRACE_ARGS_PACKET_SENT(Size) , Size -#define TRACE_ARGS_PACKET_RECEIVED(Size, Packet) , Size, Packet -#define TRACE_ARGS_CHALLENGE_RECEIVED(Size, Packet) , Size, Packet - -#define TRACE_ARGS_ERROR() -#define TRACE_ARGS_READ_PACKET() -#define TRACE_ARGS_CONNECT() -#define TRACE_ARGS_CONNECTED() -#define TRACE_ARGS_CONNECTING() -#define TRACE_ARGS_AUTHENTICATED() -#define TRACE_ARGS_SSL_CONNECT() -#define TRACE_ARGS_SSL_CONNECTED() - + { NULL, Command, Header, HdrSize, Args, ArgSize } +#define TRACE_ARGS_SEND_FILE(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } -#else +#define TRACE_ARGS_PACKET_SENT(Size) { NULL, 0, NULL, 0, NULL, Size } +#define TRACE_ARGS_PACKET_RECEIVED(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } +#define TRACE_ARGS_INIT_PACKET_RECEIVED(Size, Packet) { NULL, 0, NULL, 0, Packet, Size } + +#define TRACE_ARGS_ERROR() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_READ_PACKET() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_CONNECTING() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_CONNECTED() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_DISCONNECTED() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_AUTHENTICATED() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_SSL_CONNECT() { NULL, 0, NULL, 0, NULL, 0 } +#define TRACE_ARGS_SSL_CONNECTED() { NULL, 0, NULL, 0, NULL, 0 } -#define MYSQL_TRACE(E,M,ARGS) -#endif +#endif /* !defined(CLIENT_PROTOCOL_TRACING) || defined(MYSQL_SERVER) */ #endif === added file 'libmysql/test_trace_plugin.cc' --- a/libmysql/test_trace_plugin.cc 1970-01-01 00:00:00 +0000 +++ b/libmysql/test_trace_plugin.cc 2012-09-07 12:42:49 +0000 @@ -0,0 +1,935 @@ +/** + @file + + =========================== + Test trace plugin + =========================== + + If TEST_TRACE_PLUGIN guard is defined, this plugin is built into libmysql + (no plugin loading required). It prints some debug information about trace + events reported to it under debug keyword "test_trace". To see these debug + messages using the following DBUG flags: + + -------------- ----------------------------------------------- + d,test_trace output debug messages with "test_trace" keyword + i prefix each message with thread id + o, output to given file + -------------- ----------------------------------------------- + + For standard MySQL clients these flags can be set using --debug option, for + example: --debug="i:o,test_trace" + + If MYSQL_TEST_TRACE_CRASH environment variable is set to something else than 0 + then the plugin will crash if an invalid trace event was reported to it. + + NOTE: Debug information and crashing is supported only in debug builds of + libmysql. +*/ + +#include +#include "mysql.h" +#include "mysql_trace.h" + +extern "C" { + +tracing_start_callback test_trace_plugin_start; +tracing_stop_callback test_trace_plugin_stop; +trace_event_handler test_trace_plugin_trace; + +int test_trace_plugin_init(char *a, size_t b, int argc, va_list args); +int test_trace_plugin_deinit(); + + +struct st_mysql_client_plugin_TRACE test_trace_plugin= +{ + MYSQL_CLIENT_TRACE_PLUGIN, + MYSQL_CLIENT_TRACE_PLUGIN_INTERFACE_VERSION, + "test_trace_plugin", + "Rafal Somla", + "A plugin for testing protocl tracing infrastructure", + {0,1,0}, + "GPL", + NULL, + test_trace_plugin_init, + test_trace_plugin_deinit, + NULL, // option handling + test_trace_plugin_start, + test_trace_plugin_stop, + test_trace_plugin_trace +}; + +#ifndef DBUG_OFF + +// These are defined in mysql_trace.c +const char* stage_name(enum protocol_stage stage); +const char* event_name(enum trace_event ev); + +#endif + +} // extern "C" + +typedef unsigned char byte; + +struct st_test_trace_plugin_data +{ + bool tracing_disabled; + int last_cmd; + enum protocol_stage next_stage; + unsigned int col_count; +}; + +#define LOG(ARGS) DBUG_PRINT("test_trace", ARGS) +#define DUMP(KEY,DATA,LEN) \ + DBUG_DUMP("test_trace", (const byte*)(DATA), ((LEN) > 32 ? 32 : (LEN))) + +/** + Global flag telling if test trace plugin should crash if an + invalid event is reported to it. + + This can be used for detecting invalid protocol trace events in + MTR tests, for example. The flag is set from environment variable + MYSQL_TEST_TRACE_CRASH upon plugin initialization. By default it + is disabled. +*/ +static bool test_trace_crash_on_invalid_event= 0; + + +int +test_trace_plugin_init(char *a, size_t b ,int argc, va_list args) +{ + const char *opt= getenv("MYSQL_TEST_TRACE_CRASH"); + + if (opt && '0' != *opt) + test_trace_crash_on_invalid_event= 1; + + LOG(("Test trace plugin initialized")); + return 0; +} + + +int +test_trace_plugin_deinit() +{ + LOG(("Test trace plugin de-initialized")); + return 0; +} + + +void* +test_trace_plugin_start(struct st_mysql_client_plugin_TRACE *self, + MYSQL *conn, enum protocol_stage stage) +{ + LOG(("Starting tracing in stage %s", stage_name(stage))); + + struct st_test_trace_plugin_data *plugin_data= new st_test_trace_plugin_data; + memset(plugin_data, 0, sizeof(st_test_trace_plugin_data)); + + if (plugin_data) + plugin_data->next_stage= PROTOCOL_STAGE_CONNECTING; + else + { + LOG(("Could not allocate per-connection trace data" + " - checking protocol flow will be disabled")); + } + return plugin_data; +} + + +void +test_trace_plugin_stop(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), + MYSQL *conn, void *data) +{ + LOG(("Tracing connection has ended")); + if (data) + my_free(data); +} + +// Declare functions for checking protocol flow (defined below) + +#define protocol_stage_chk_ev_declare(S) \ + int check_event_ ## S(MYSQL *conn, \ + struct st_test_trace_plugin_data *data, \ + enum trace_event ev, \ + struct st_trace_event_args args, \ + enum protocol_stage *next_stage); + +PROTOCOL_STAGE_LIST(chk_ev_declare) + + +void +test_trace_plugin_trace(struct st_mysql_client_plugin_TRACE *self __attribute__((unused)), + void *data_ptr, MYSQL *conn, + enum protocol_stage stage, enum trace_event ev, + struct st_trace_event_args args) +{ + int check= 0; + struct st_test_trace_plugin_data *data= static_cast(data_ptr); + + if (data && data->tracing_disabled) + return; + + LOG(("stage: %s, event: %s", stage_name(stage), event_name(ev))); + + if (ev == TRACE_EVENT_ERROR) + { + int errnum= conn->net.last_errno; + const char* error= conn->net.last_error; + LOG(("error %d: %s", errnum, error)); + return; + } + + if (!data) + return; + + if (data && data->next_stage != stage) + { + LOG(("wrong stage, expected: %s", stage_name(data->next_stage))); + if (test_trace_crash_on_invalid_event) + DBUG_ASSERT(0); + } + + + // Show trace event details + + switch (ev) + { + case TRACE_EVENT_DISCONNECTED: + LOG(("Connection closed")); + return; + + case TRACE_EVENT_SEND_COMMAND: + switch(args.cmd) + { + case COM_BINLOG_DUMP: + case COM_BINLOG_DUMP_GTID: + case COM_TABLE_DUMP: + LOG(("Replication command (%d) - disabling furthert tracing", args.cmd)); + data->tracing_disabled= true; + break; + + case COM_QUERY: + LOG(("query: %s", args.pkt)); + break; + + case COM_QUIT: + LOG(("COM_QUIT")); + break; + + /* TODO: + case COM_STMT_PREPARE: NEXT_STAGE(WAIT_FOR_PS_DESCRIPTION); break; + case COM_STMT_EXECUTE: NEXT_STAGE(WAIT_FOR_RESULT); break; + */ + + default: + LOG(("cmd: %d", args.cmd)); + if (args.hdr_len > 0) + DUMP("cmd hdr", args.hdr, args.hdr_len); + if (args.pkt_len > 0) + DUMP("cmd args", args.pkt, args.pkt_len); + break; + }; + break; + + case TRACE_EVENT_AUTH_PLUGIN: + LOG(("Using authentication plugin: %s", args.plugin_name)); + break; + + case TRACE_EVENT_SEND_SSL_REQUEST: + case TRACE_EVENT_SEND_AUTH_RESPONSE: + // TODO: Parse response and show info. + case TRACE_EVENT_SEND_AUTH_DATA: + case TRACE_EVENT_SEND_FILE: + DUMP("packet sent", args.pkt, args.pkt_len); + break; + + case TRACE_EVENT_PACKET_RECEIVED: + case TRACE_EVENT_INIT_PACKET_RECEIVED: + // TODO: Parse init packet and show info. + DUMP("packet received", args.pkt, args.pkt_len); + break; + + default: break; + } + + + +#define protocol_stage_check(S) \ + case PROTOCOL_STAGE_ ## S: \ + check= check_event_ ## S(conn, data, ev, args, &(data->next_stage)); \ + break; + + switch (stage) + { + PROTOCOL_STAGE_LIST(check) + default: + LOG(("invlaid stage %d", stage)); + if (test_trace_crash_on_invalid_event) + DBUG_ASSERT(0); + } + + + if (check) + { + LOG(("invalid event detected")); + if (test_trace_crash_on_invalid_event) + DBUG_ASSERT(0); + } +} + + +/* + Macros to recognize various types of server replies. +*/ +#define OK_PACKET(PKT) (*((byte*)PKT) == 0x00) +#define ERR_PACKET(PKT) (*((byte*)PKT) == 0xFF) +#define EOF_PACKET(PKT) (*((byte*)PKT) == 0xFE) +#define FILE_REQUEST(PKT) (*((byte*)PKT) == 0xFB) + + +#define NEXT_STAGE(S) do{ if(next_stage) *next_stage= PROTOCOL_STAGE_ ## S; } while(0) + + +int check_event_CONNECTING(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This is the first stage of the protocol, when client is establishing + physical connection with the server. After connection is established + protocol moves to WAIT_FOR_CHALLENGE stage where the first + authentication challenge packet is expected from the server. + */ + switch (ev) + { + case TRACE_EVENT_CONNECTING: return 0; + case TRACE_EVENT_CONNECTED: + NEXT_STAGE(WAIT_FOR_INIT_PACKET); return 0; + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_INIT_PACKET(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + In this stage client waits for the first challenge packet from the + server. When it is received, protocol movest to AUTHENTICATE stage + where client authorizes itself against server. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: return 0; // TODO: Parse init packet and show info + case TRACE_EVENT_INIT_PACKET_RECEIVED: NEXT_STAGE(AUTHENTICATE); return 0; + default: return 1; /* invalid event */ + }; +} + + +int check_event_AUTHENTICATE(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + In this stage client exchanges various packets with the server to: + - authenticate itself against the server, + - negotiante client/server capabilities and connection parameters, + - establish encrypted SSL connection. + At any moment during this exchange server can send an ERR packet + indicating that it rejects the connection. + */ + switch (ev) + { + case TRACE_EVENT_AUTHENTICATED: NEXT_STAGE(READY_FOR_COMMAND); return 0; + case TRACE_EVENT_PACKET_RECEIVED: + { + /* + Move to DISCONNECTED stage if ERR packet was received from the + server. + */ + if (ERR_PACKET(args.pkt)) + { + LOG(("Server rejected connection (ERR packet)")); + NEXT_STAGE(DISCONNECTED); + } + + return 0; + } + + case TRACE_EVENT_AUTH_PLUGIN: + case TRACE_EVENT_SEND_SSL_REQUEST: + case TRACE_EVENT_SSL_CONNECT: + case TRACE_EVENT_SSL_CONNECTED: + case TRACE_EVENT_SEND_AUTH_RESPONSE: + case TRACE_EVENT_SEND_AUTH_DATA: + case TRACE_EVENT_READ_PACKET: + case TRACE_EVENT_PACKET_SENT: + return 0; + + default: return 1; /* invalid event */ + }; +} + +int check_event_SSL_NEGOTIATION(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + switch (ev) + { + case TRACE_EVENT_PACKET_SENT: + case TRACE_EVENT_PACKET_RECEIVED: + case TRACE_EVENT_SSL_CONNECT: + case TRACE_EVENT_SSL_CONNECTED: + return 0; + + default: return 1; /* invalid event */ + } +} + + +int check_event_READY_FOR_COMMAND(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This is the stage when client can send a command to the server. + After sending command packet to the server, PACKET_SENT trace + event happens. The next stage depends on whether a result set + is expected after the command, or just OK/ERR reply or it is + a command with no reply from server. + */ + switch (ev) + { + case TRACE_EVENT_SEND_COMMAND: + /* + Save the command code (to be examined in the following + PACKET_SENT event) and reset PS information stored in + trace info record + */ + if (data) + data->last_cmd = args.cmd; + + /* + Replication commands are not supported - report them as + invalid event so that trace plugin can decide how to proceed. + */ + switch (args.cmd) + { + case COM_BINLOG_DUMP: + case COM_BINLOG_DUMP_GTID: + case COM_TABLE_DUMP: + return 1; + + default: + return 0; + } + + case TRACE_EVENT_PACKET_SENT: + /* + Move to correct stage based on the command that was + reported in the preceeding SEND_COMMAND event. + */ + if (!data) + return 1; + switch (data->last_cmd) + { + case COM_STMT_PREPARE: NEXT_STAGE(WAIT_FOR_PS_DESCRIPTION); break; + case COM_QUERY: + case COM_STMT_EXECUTE: NEXT_STAGE(WAIT_FOR_RESULT); break; + + /* + No server reply is expected after these commands so we reamin ready + for the next command. + */ + case COM_QUIT: //NEXT_STAGE(DISCONNECTED); break; + case COM_REFRESH: + case COM_STMT_SEND_LONG_DATA: + case COM_STMT_CLOSE: + case COM_REGISTER_SLAVE: + return 0; + + /* + These replication commands are not supported (the SEND_COMMAND + event was already reported as invalid). + */ + case COM_BINLOG_DUMP: + case COM_BINLOG_DUMP_GTID: + case COM_TABLE_DUMP: + return 1; + + /* + After COM_PROCESS_INFO server sends a regular result set. + */ + case COM_PROCESS_INFO: + NEXT_STAGE(WAIT_FOR_RESULT); + break; + + /* + Server replies to COM_STATISTICS with a single packet + containing a string with statistics information. + */ + case COM_STATISTICS: + NEXT_STAGE(WAIT_FOR_PACKET); + break; + + /* + After COM_CHANGE_USER a regular authentication exchange + is performad. + */ + case COM_CHANGE_USER: + NEXT_STAGE(AUTHENTICATE); + break; + + /* + For all other commands a simple OK/ERR reply from server + is expected. + */ + default: + NEXT_STAGE(WAIT_FOR_RESULT); + break; + }; + return 0; + + case TRACE_EVENT_AUTH_PLUGIN: + /* + The AUTH_PLUGIN event can happen in READY_FOR_COMMAND stage + before COM_CHANGE_USER is executed. When the command is executed + the stage will be changed to AUTHENTICATE. + */ + return 0; + + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_PACKET(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + After some commands (COM_STATISTICS) server sends just a + single packet and then it is ready for processing more + commands. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: + NEXT_STAGE(READY_FOR_COMMAND); + return 0; + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_RESULT(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This stage is reached after a command which can produce a result set + (COM_QUERY or COM_STMT_EXECUTE). In this stage a single packet is + received from the server informing about the result of the query: + - ERR packet informs that error has happened when processing query, + - OK packet informs that query produced no result set, + - FILE_REQUEST packet asks client to send contents of a given file, + Otherwise information about the number of columns in the result set + is received. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: + { + byte *pkt= (byte*)args.pkt; + /* + If server sends ERR, query processing is done + and next stage is READY_FOR_COMMAND. + */ + if (ERR_PACKET(pkt) || EOF_PACKET(pkt)) + { + if (ERR_PACKET(pkt)) + LOG(("Server reports error")); + NEXT_STAGE(READY_FOR_COMMAND); + return 0; + } + + /* + If server sends FILE_REQUEST packet, we move to FILE_REQUEST + stage of the protocol. + */ + if (FILE_REQUEST(pkt)) + { + LOG(("Server requests file: %s", pkt+1)); + NEXT_STAGE(FILE_REQUEST); + return 0; + } + + /* + If query generates no data, server replies with OK packet. In + case of a multi-query, more result sets can follow, as + indicated by SERVER_MORE_RESULTS_EXISTS flag in the OK packet. + If the flag is set we move to WAIT_FOR_RESULTSET stage to + read the following result set(s). + */ + if (OK_PACKET(args.pkt)) + { + /* Extract flags from the OK packet */ + unsigned int flags; + unsigned int affected_rows; + unsigned int last_insert_id; + + pkt++; /* cmd header */ + affected_rows= net_field_length(&pkt); /* affected_rows */ + last_insert_id= net_field_length(&pkt); /* last_insert_id */ + flags= uint2korr(pkt); + + LOG(("OK from server; flags: 0x%02X, affected rows: %u, last insert_id: %u", + flags, affected_rows, last_insert_id)); + + if (SERVER_MORE_RESULTS_EXISTS & flags) + { + LOG(("Expecting next result set")); + NEXT_STAGE(WAIT_FOR_RESULT); + } + else + NEXT_STAGE(READY_FOR_COMMAND); + return 0; + } + + /* + Otherwise a result set is expected from the server so we move + to WAIT_FOR_FIELD_DEF stage. + */ + LOG(("Expecting result set with %lu columns", net_field_length(&pkt))); + NEXT_STAGE(WAIT_FOR_FIELD_DEF); + return 0; + } + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_FIELD_DEF(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + In this stage definitions of row fields are read from server. This + can happen when reading query result set, or after preparing + a statement which produces result set or upon explicit COM_FIELD_LIST + request. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: + { + /* + If the received packet is not an EOF packet, then it is description + of the next row field and we can continue, remaining in the same stage. + + To correctly recognize EOF packets we have to check its length, because + a field description packet can theoretically start with byte 0xFE - the + same as the first byte of the EOF packet. + + This can happen if the first length-encoded string in the packet starts + with 8-byte length-encoded integer whose first byte is 0xFE. In this + case the string and thus the whole packet is longer than 9 bytes and\ + EOF packet is always shorter than 9 bytes. + */ + if (!(EOF_PACKET(args.pkt) && args.pkt_len < 9)) + { + LOG(("Received next field definition")); + return 0; + } + + LOG(("No more fields")); + /* + If this WAIT_FOR_FIELD_DEF stage was reached after COM_STMT_PREPARE or + COM_FIELD_LIST then the EOF packet ends proccesing of the command and + next stage is READY_FOR_COMMAND. + Otherwise we are reading a result set and the field definitions have + ended - next stage is WAIT_FOR_ROW. + */ + switch (data->last_cmd) + { + case COM_STMT_PREPARE: + case COM_FIELD_LIST: + NEXT_STAGE(READY_FOR_COMMAND); + break; + default: + LOG(("Reading result set rows")); + NEXT_STAGE(WAIT_FOR_ROW); + } + + return 0; + } + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_ROW(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This stage is entered when reading a result set, after receiving + its metadata. In this stage server sends packets with rows unitl + EOF or ERR packet is sent. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: + { + unsigned int flags; + /* + If ERR packet is received, an error has happened and reading + the result set is done. Next stage is READY_FOR_COMMAND. + */ + if (ERR_PACKET(args.pkt)) + { + LOG(("Server signals error")); + NEXT_STAGE(READY_FOR_COMMAND); + return 0; + } + + /* + Otherwise row packets are received until we get an EOF packet. + We need to check packet length again, because a text-protocol + row packet starts with a length-encoded string and thus its + first byte can be 0xFE. + */ + if (!(EOF_PACKET(args.pkt) && args.pkt_len < 9)) + { + LOG(("Received next row")); + return 0; + } + + LOG(("End of data")); + /* + In case of a multi-resutset a SERVER_MORE_RESULTS_EXISTS flag can + be set in the EOF packet. In that case next resultset will follow + and the next stage is WAIT_FOR_RESULTSET. If + SERVER_MORE_RESULTS_EXISTS flag is not set, next stage is + READY_FOR_COMMAND. + */ + + flags= uint2korr(((char*)args.pkt)+3); + + if (SERVER_MORE_RESULTS_EXISTS & flags) + { + LOG(("Expecting next result set")); + NEXT_STAGE(WAIT_FOR_RESULT); + } + else + NEXT_STAGE(READY_FOR_COMMAND); + + return 0; + } + default: return 1; /* invalid event */ + }; +} + + +int check_event_WAIT_FOR_PS_DESCRIPTION(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This stage is entered after executing COM_PREPARE_STMT command. + Server should send stmt OK packet with information about the + statement. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 1; + case TRACE_EVENT_PACKET_RECEIVED: + { + byte *pkt= static_cast(const_cast(args.pkt)); + long unsigned int stmt_id; + unsigned int col_count, param_count; + + /* + If we do not get OK packet here, something is wrong. + */ + if (!OK_PACKET(args.pkt)) + { + LOG(("Wrong PS description")); + return 1; + } + + /* + Otherwise we read information about statement parameters + (param_count) and produced result set (col_count) and store + it in the ti structure. + */ + + stmt_id = uint4korr(pkt+1); + col_count = uint2korr(pkt+5); + param_count = uint2korr(pkt+7); + data->col_count= col_count; + + LOG(("Prepared statement %lu; params: %u, cols: %u", + stmt_id, param_count, col_count)); + + /* + If statement has parameters then next stage is + WAIT_FOR_PS_PARAMETER, where server sends parameter + descriptions. + */ + if (0 < param_count) + { + NEXT_STAGE(WAIT_FOR_PS_PARAMETER); + return 0; + } + + /* + Otherwise, if statement has no parameters but produces + a result set, the next stage is WAIT_FOR_FIELD_DEF where + server sends descriptions of result set fields. + */ + if (0 < col_count) + { + NEXT_STAGE(WAIT_FOR_FIELD_DEF); + return 0; + } + + /* + Otherwise (no parameters and no result set), preparing + the statement is done and next stage is READY_FOR_COMMAND. + */ + NEXT_STAGE(READY_FOR_COMMAND); + return 0; + } + default: return 1; + } +} + + +int check_event_WAIT_FOR_PS_PARAMETER(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This stage is reached after COM_PREPARE_STMT command and after + receiving the stmt OK packet from the server (if the statement + has parameters). Server sends descriptions of the parameters in + the same format in which result set fields are described. + */ + switch (ev) + { + case TRACE_EVENT_READ_PACKET: return 0; + case TRACE_EVENT_PACKET_RECEIVED: + { + /* + Sending parameter descriptions continues until an EOF + packet is received. To correctly recognize EOF packet + we must check the packet length the same as + in WAIT_FOR_FILED_DEF stage. + */ + if (!(EOF_PACKET(args.pkt) && args.pkt_len < 9)) + { + LOG(("Received next parameter description")); + return 0; + } + + LOG(("No more parameters")); + /* + After receiving EOF packets next stage depends on whether + the statement produces any result set, in which case column + definitions will follow, or not. + + We decide this based on statement info stored in the ti + structure. + */ + + if (0 < data->col_count) + NEXT_STAGE(WAIT_FOR_FIELD_DEF); + else + NEXT_STAGE(READY_FOR_COMMAND); + + return 0; + } + default: return 1; + } +} + + +int check_event_FILE_REQUEST(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + At this stage client sends packets with the file contents + followed by an empty packet. After that client waits for + a result set from server (which can be empty). + */ + switch (ev) + { + case TRACE_EVENT_SEND_FILE: return 0; + case TRACE_EVENT_PACKET_SENT: + { + /* + See if the packet sent was empty and if yes, move to + WAIT_FOR_RESULTSET stage. + */ + if (0 == args.pkt_len) + { + LOG(("File transfer done")); + NEXT_STAGE(WAIT_FOR_RESULT); + } + return 0; + } + + default: return 1; /* invalid event */ + }; +} + + +int check_event_DISCONNECTED(MYSQL *conn, + struct st_test_trace_plugin_data *data, + enum trace_event ev, + struct st_trace_event_args args, + enum protocol_stage *next_stage) +{ + /* + This is the final stage reached when connection with + server ends. No events should happen in this stage. + */ + return 1; +} + + + + + === modified file 'sql-common/client.c' --- a/sql-common/client.c 2012-08-23 19:41:04 +0000 +++ b/sql-common/client.c 2012-09-07 12:42:49 +0000 @@ -757,10 +757,61 @@ cli_advanced_command(MYSQL *mysql, enum MYSQL_TRACE(PACKET_SENT, mysql, (header_length + arg_length)); +#if defined(CLIENT_PROTOCOL_TRACING) + switch (command) + { + case COM_STMT_PREPARE: + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_PS_DESCRIPTION); + break; + + /* + No server reply is expected after these commands so we reamin ready + for the next command. + */ + case COM_REFRESH: + case COM_STMT_SEND_LONG_DATA: + case COM_STMT_CLOSE: + case COM_REGISTER_SLAVE: + case COM_QUIT: + break; + + /* + These replication commands are not supported and we bail out + by pretending that connection has been closed. + */ + case COM_BINLOG_DUMP: + case COM_BINLOG_DUMP_GTID: + case COM_TABLE_DUMP: + MYSQL_TRACE(DISCONNECTED, mysql, ()); + break; + + /* + After COM_CHANGE_USER a regular authentication exchange + is performed. + */ + case COM_CHANGE_USER: + MYSQL_TRACE_STAGE(mysql, AUTHENTICATE); + break; + + /* + Server replies to COM_STATISTICS with a single packet + containing a string with statistics information. + */ + case COM_STATISTICS: + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_PACKET); + break; + + default: MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); break; + } +#endif + result=0; if (!skip_check) + { result= ((mysql->packet_length=cli_safe_read(mysql)) == packet_error ? 1 : 0); + } + end: DBUG_PRINT("exit",("result: %d", result)); DBUG_RETURN(result); @@ -822,6 +873,12 @@ my_bool flush_one_result(MYSQL *mysql) mysql->server_status=uint2korr(pos); pos+=2; } +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif return FALSE; } @@ -860,6 +917,12 @@ my_bool opt_flush_ok_packet(MYSQL *mysql mysql->warning_count=uint2korr(pos); pos+=2; } +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif } return FALSE; } @@ -989,6 +1052,7 @@ void end_server(MYSQL *mysql) net_end(&mysql->net); free_old_query(mysql); errno= save_errno; + MYSQL_TRACE(DISCONNECTED, mysql, ()); DBUG_VOID_RETURN; } @@ -1594,6 +1658,12 @@ MYSQL_DATA *cli_read_rows(MYSQL *mysql,M DBUG_PRINT("info",("status: %u warning_count: %u", mysql->server_status, mysql->warning_count)); } +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif DBUG_PRINT("exit", ("Got %lu rows", (ulong) result->rows)); DBUG_RETURN(result); } @@ -1621,6 +1691,12 @@ read_one_row(MYSQL *mysql,uint fields,MY mysql->warning_count= uint2korr(net->read_pos+1); mysql->server_status= uint2korr(net->read_pos+3); } +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif return 1; /* End of data */ } prev_pos= 0; /* allowed to write at packet[-1] */ @@ -2340,7 +2416,7 @@ static auth_plugin_t sha256_password_cli #ifdef AUTHENTICATION_WIN extern auth_plugin_t win_auth_client_plugin; #endif -#ifdef TEST_TRACE_PLUGIN +#if defined(CLIENT_PROTOCOL_TRACING) && defined(TEST_TRACE_PLUGIN) extern auth_plugin_t test_trace_plugin; #endif @@ -2355,7 +2431,7 @@ struct st_mysql_client_plugin *mysql_cli #ifdef AUTHENTICATION_WIN (struct st_mysql_client_plugin *)&win_auth_client_plugin, #endif -#ifdef TEST_TRACE_PLUGIN +#if defined(CLIENT_PROTOCOL_TRACING) && defined(TEST_TRACE_PLUGIN) (struct st_mysql_client_plugin *)&test_trace_plugin, #endif 0 @@ -2664,6 +2740,8 @@ static int send_client_reply_packet(MCPV goto error; } + MYSQL_TRACE_STAGE(mysql, SSL_NEGOTIATION); + /* Create the VioSSLConnectorFd - init SSL and load certs */ if (!(ssl_fd= new_VioSSLConnectorFd(options->ssl_key, options->ssl_cert, @@ -2708,6 +2786,7 @@ static int send_client_reply_packet(MCPV } MYSQL_TRACE(SSL_CONNECTED, mysql, ()); + MYSQL_TRACE_STAGE(mysql, AUTHENTICATE); } #endif /* HAVE_OPENSSL */ @@ -3013,7 +3092,7 @@ int run_plugin_auth(MYSQL *mysql, char * mpvio.db= db; mpvio.plugin= auth_plugin; - MYSQL_TRACE(AUTH_PLUGIN, mysql, (auth_plugin)); + MYSQL_TRACE(AUTH_PLUGIN, mysql, (auth_plugin->name)); res= auth_plugin->authenticate_user((struct st_plugin_vio *)&mpvio, mysql); DBUG_PRINT ("info", ("authenticate_user returned %s", @@ -3087,7 +3166,7 @@ int run_plugin_auth(MYSQL *mysql, char * if (check_plugin_enabled(mysql, auth_plugin)) DBUG_RETURN(1); - MYSQL_TRACE(AUTH_PLUGIN, mysql, (auth_plugin)); + MYSQL_TRACE(AUTH_PLUGIN, mysql, (auth_plugin->name)); mpvio.plugin= auth_plugin; res= auth_plugin->authenticate_user((struct st_plugin_vio *)&mpvio, mysql); @@ -3259,6 +3338,7 @@ CLI_MYSQL_REAL_CONNECT(MYSQL *mysql,cons mysql->server_status=SERVER_STATUS_AUTOCOMMIT; DBUG_PRINT("info", ("Connecting")); + MYSQL_TRACE_STAGE(mysql, CONNECTING); MYSQL_TRACE(CONNECTING, mysql, ()); /* @@ -3610,6 +3690,7 @@ CLI_MYSQL_REAL_CONNECT(MYSQL *mysql,cons net->max_packet_size= mysql->options.max_allowed_packet; MYSQL_TRACE(CONNECTED, mysql, ()); + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_INIT_PACKET); /* Get version info */ mysql->protocol_version= PROTOCOL_VERSION; /* Assume this */ @@ -3743,7 +3824,8 @@ CLI_MYSQL_REAL_CONNECT(MYSQL *mysql,cons mysql->client_flag= client_flag; - MYSQL_TRACE(CHALLENGE_RECEIVED, mysql, (pkt_length, net->read_pos)); + MYSQL_TRACE(INIT_PACKET_RECEIVED, mysql, (pkt_length, net->read_pos)); + MYSQL_TRACE_STAGE(mysql, AUTHENTICATE); /* Part 2: invoke the plugin to send the authentication data to the server @@ -3753,6 +3835,8 @@ CLI_MYSQL_REAL_CONNECT(MYSQL *mysql,cons scramble_plugin, db)) goto error; + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); + /* Part 3: authenticated, finish the initialization of the connection */ @@ -4121,6 +4205,12 @@ get_info: mysql->server_status, mysql->warning_count)); if (pos < mysql->net.read_pos+length && net_field_length(&pos)) mysql->info=(char*) pos; +#if defined(CLIENT_PROTOCOL_TRACING) + if (mysql->server_status & SERVER_MORE_RESULTS_EXISTS) + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + else + MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); +#endif DBUG_RETURN(0); } #ifdef MYSQL_CLIENT @@ -4128,6 +4218,8 @@ get_info: { int error; + MYSQL_TRACE_STAGE(mysql, FILE_REQUEST); + if (!(mysql->options.client_flag & CLIENT_LOCAL_FILES)) { set_mysql_error(mysql, CR_MALFORMED_PACKET, unknown_sqlstate); @@ -4135,6 +4227,9 @@ get_info: } error= handle_local_infile(mysql,(char*) pos); + + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_RESULT); + if ((length= cli_safe_read(mysql)) == packet_error || error) DBUG_RETURN(1); goto get_info; /* Get info packet */ @@ -4143,6 +4238,8 @@ get_info: if (!(mysql->server_status & SERVER_STATUS_AUTOCOMMIT)) mysql->server_status|= SERVER_STATUS_IN_TRANS; + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_FIELD_DEF); + if (!(fields=cli_read_rows(mysql,(MYSQL_FIELD*)0, protocol_41(mysql) ? 7:5))) DBUG_RETURN(1); if (!(mysql->fields=unpack_fields(mysql, fields,&mysql->field_alloc, @@ -4151,6 +4248,9 @@ get_info: DBUG_RETURN(1); mysql->status= MYSQL_STATUS_GET_RESULT; mysql->field_count= (uint) field_count; + + MYSQL_TRACE_STAGE(mysql, WAIT_FOR_ROW); + DBUG_PRINT("exit",("ok")); DBUG_RETURN(0); } === modified file 'sql-common/client_plugin.c' --- a/sql-common/client_plugin.c 2012-07-20 16:36:35 +0000 +++ b/sql-common/client_plugin.c 2012-08-28 07:28:25 +0000 @@ -36,7 +36,10 @@ #include #include "errmsg.h" #include + +#if defined(CLIENT_PROTOCOL_TRACING) #include +#endif struct st_client_plugin_int { struct st_client_plugin_int *next; @@ -145,10 +148,9 @@ add_plugin(MYSQL *mysql, struct st_mysql goto err1; } -#ifndef MYSQL_SERVER +#if defined(CLIENT_PROTOCOL_TRACING) && !defined(MYSQL_SERVER) if (plugin->type == MYSQL_CLIENT_TRACE_PLUGIN && NULL != trace_plugin) { - // TODO: put names of plugins in the trace log errmsg= "Can not load another trace plugin while one is already loaded"; goto err1; } @@ -176,7 +178,7 @@ add_plugin(MYSQL *mysql, struct st_mysql plugin_list[plugin->type]= p; net_clear_error(&mysql->net); -#ifndef MYSQL_SERVER +#if defined(CLIENT_PROTOCOL_TRACING) && !defined(MYSQL_SERVER) if (plugin->type == MYSQL_CLIENT_TRACE_PLUGIN) { trace_plugin = (struct st_mysql_client_plugin_TRACE*)plugin; No bundle (reason: useless for push emails).