MySQL Bugs: #65715: Wrong connection ID (thread ID) in the general and slow query logs

Bug #65715	Wrong connection ID (thread ID) in the general and slow query logs
Submitted:	22 Jun 2012 19:51	Modified:	23 Aug 2012 16:27
Reporter:	Davi Arnaut (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.5.25	OS:	Any (x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	connection ID, general query log, slow query log, thread ID

Description:
Connection IDs above 2^32 are not properly written to the general and/or slow query logs. The problem is that the methods used to write commands to the log (e.g. MYSQL_QUERY_LOG::write) use a 32-bits wide integer to store the connection ID value, which is actually a 64-bits wide integer value. For example, if the connection ID has a value greater than 2^32, the wrong value gets printed to the log.

How to repeat:
Use gdb to set thread_id to a large value and observe the results in the general log.

Thank you for the problem report. Verified by code review. In sql/sql_class.h THD member thread_id is defined as:

my_thread_id  thread_id;

that is, ulong:

include/my_pthread.h:806:typedef ulong my_thread_id;

while in sql/log.cc functions use int to represent it:

macbook-pro:mysql-5.5-work openxs$ grep -n thread_id sql/log.cc
532:  @param  thread_id         Id of the thread, issued a query
555:              uint user_host_len, int thread_id,
635:      table->field[2]->store((longlong) thread_id, TRUE) ||
961:              uint user_host_len, int thread_id,
969:                               thread_id, command_type, command_type_len,
1283:                  user_host_len, thd->thread_id,
2541:    thread_id         Id of the thread, issued a query
2557:                            uint user_host_len, int thread_id,
2595:      /* command_type, thread_id */
2596:      length= my_snprintf(buff, 32, "%5ld ", (long) thread_id);

Like this:

/**
   Wrapper around MYSQL_LOG::write() for general log. We need it since we
   want all log event handlers to have the same signature.
*/

bool Log_to_file_event_handler::
  log_general(THD *thd, time_t event_time, const char *user_host,
              uint user_host_len, int thread_id,
              const char *command_type, uint command_type_len,
              const char *sql_text, uint sql_text_len,
              CHARSET_INFO *client_cs)
{
...

and then pass THD::thread_id to this function:

  while (*current_handler)
    error|= (*current_handler++)->
      log_general(thd, current_time, user_host_buff,
                  user_host_len, thd->thread_id,
                  command_name[(uint) command].str,
                  command_name[(uint) command].length,
                  query, query_length,
                  thd->variables.character_set_client) || error;
...

Use the correct type for passing thread ID values. (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: Bug#65715-Wrong-connection-ID-thread-ID-in-the-gener.patch (application/octet-stream, text), 4.71 KiB.

Noted in 5.7.0 changelog.

Connection ID (thread ID) values greater than 32 bits can occur on
some systems (such as 64-bit systems), causing these problems:

* Connection IDs written to the general query log and slow query log
  were incorrect. This was true for logging to both files and tables.

* The CONNECTION_ID() function could return a value with a data type
  too small for values larger than 32 bits.

* The mysql_thread_id() and mysql_kill() C API functions did not handle
  ID values larger than 32 bits. This could result in killing the wrong
thread; for example, if you invoked mysql_kill(mysql_thread_id()).

Connection IDs now are permitted to be 64-bit values when possible,
which has these effects:

* Connection IDs are logged correctly to the general query log and slow
  query log.

  Note: This change involves a modification to the log tables, so after
  upgrading to this release, you must run mysql_upgrade and restart the
  server.

* CONNECTION_ID() returns a data type appropriate for values larger
  than 32 bits.

* mysql_thread_id() is unchanged; the client/server protocal has only 4
  bytes for the ID value. This function returns an incorrect
  (truncated) value for connection IDs larger than 32 bits and should
  be avoided.

* mysql_kill() still cannot handle values larger than 32 bits but to
  guard against killing the wrong thread now returns an error in these
  cases:

  * If given an ID larger than 32 bits, mysql_kill() returns a
    CR_INVALID_CONN_HANDLE error.

  * After the server's internal thread ID counter reaches a value larger
    than 32 bits, it returns an ER_DATA_OUT_OF_RANGE error for any
    mysql_kill() invocation and mysql_kill() fails.

* To avoid problems with mysql_thread_id() and mysql_kill(), you should
  not use them. To get the connection ID, execute a SELECT
  CONNECTION_ID() query and retrieve the result. To kill a thread,
  execute a KILL statement.

Backported to 5.6.9. Noted in 5.6.9 changelog.