MySQL Bugs: #80854: no whitespace between timestamp and threadid columns

Bug #80854	no whitespace between timestamp and threadid columns
Submitted:	24 Mar 2016 18:38	Modified:	15 Jun 2016 17:55
Reporter:	Viktor Štujber	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.7, 5.7.11	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
In 2013 the query logging code was rewritten - see https://github.com/mysql/mysql-server/commit/5ece4a68df45beb438012d3cb9778328e80ce458. The new code in File_query_log::write_general() says something like:

time_buff_len = make_iso8601_timestamp(local_time_buff, event_utime);
my_b_write(&log_file, time_buff, time_buff_len);
length = my_snprintf(buff, 32, "%5u ", thread_id);
my_b_write(&log_file, buff, length);

The "%5u" sequence adds left padding of up to 5 spaces, depending on the value to be printed. If thread_id has 5 or more decadic digits, no whitespace will be added, and the timestamp and thread_id strings get glued together. Example:

2016-03-24T15:26:20.234311Z 2541 Quit
2016-03-24T15:26:21.724378Z58854 Close Stmt

How to repeat:
Enable general_log on a mysql server and wait until client activity makes the thread id go into 5 digits.

Suggested fix:
Using " %5u " (one explicit whitespace character before the thread_id) would solve it.

I have a same issue and my patch has already been fixed by (only) 5.8 at Bug#79868.

Doesn't this fix at 5.7?

Interesting. No, the last change to log.cc on github was oct 2015. Your issue was closed but no action was taken. Latest 5.7 release still has this problem.

Your approach was to use a tab character ("\t") instead of a space, however you use a separate write call to do it, which seems a bit awkward. But it points out an inconsistency I missed: the Id column is surrounded by spaces, but the Command column is followed by a tab. It might be useful to normalize the file format to be fully tab-separated, maybe like this:

-length= my_snprintf(buff, 32, "%5u ", thread_id);
+length= my_snprintf(buff, 32, "\t%5u\t", thread_id);

I've just get to be same as another line which is putting tab character in File_query_log::write_general.

  https://github.com/mysql/mysql-server/blob/5.7/sql/log.cc#L692-L693

Hello Viktor Štujber,

Thank you for the report.

Thanks,
Umesh

Posted by developer:
 
Noted in 5.7.14 changelog.

Lines written to the error log had no space separating the timestamp
and thread ID columns if the thread ID took five or more characters.