Bug #27638: slow logging to CSV table inserts bad query_time and lock_time values

When MySQL logged slow query information to a CSV table, it stored the
query_time and lock_time values with an incorrect formula.

If the time was over 59 seconds, this caused incorrect statistics (either the
slow query was not logged, or the time was far from correct).  This change
fixes the method used to store those TIME values in the slow_log table.

6 files changed, 84 insertions, 2 deletions

diff --git a/include/my_time.h b/include/my_time.h
index d96c5822069..6aa25487cf1 100644
--- a/include/my_time.h
+++ b/include/my_time.h
@@ -72,6 +72,8 @@ typedef long my_time_t;
 #define TIME_MAX_SECOND 59
 #define TIME_MAX_VALUE (TIME_MAX_HOUR*10000 + TIME_MAX_MINUTE*100 + \
                         TIME_MAX_SECOND)
+#define TIME_MAX_VALUE_SECONDS (TIME_MAX_HOUR * 3600L + \
+                                TIME_MAX_MINUTE * 60L + TIME_MAX_SECOND)
 
 my_bool check_date(const MYSQL_TIME *ltime, my_bool not_zero_date,
                    ulong flags, int *was_cut);
diff --git a/mysql-test/r/log_tables-big.result b/mysql-test/r/log_tables-big.result
new file mode 100644
index 00000000000..9b81127c825
--- /dev/null
+++ b/mysql-test/r/log_tables-big.result
@@ -0,0 +1,29 @@
+set session long_query_time=10;
+select get_lock('bug27638', 1);
+get_lock('bug27638', 1)
+1
+set session long_query_time=1;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 2);
+get_lock('bug27638', 2)
+0
+select if (query_time between '00:00:01' and '00:00:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 2)
+truncate table mysql.slow_log;
+select get_lock('bug27638', 60);
+get_lock('bug27638', 60)
+0
+select if (query_time between '00:00:59' and '00:01:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 60)
+truncate table mysql.slow_log;
+select get_lock('bug27638', 101);
+get_lock('bug27638', 101)
+0
+select if (query_time between '00:01:40' and '00:01:50', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+qt	sql_text
+OK	select get_lock('bug27638', 101)
+select release_lock('bug27638');
+release_lock('bug27638')
+1
diff --git a/mysql-test/t/log_tables-big-master.opt b/mysql-test/t/log_tables-big-master.opt
new file mode 100644
index 00000000000..35ff7911705
--- /dev/null
+++ b/mysql-test/t/log_tables-big-master.opt
@@ -0,0 +1 @@
+--log-slow-queries
diff --git a/mysql-test/t/log_tables-big.test b/mysql-test/t/log_tables-big.test
new file mode 100644
index 00000000000..8c956fa6f55
--- /dev/null
+++ b/mysql-test/t/log_tables-big.test
@@ -0,0 +1,35 @@
+# this test needs multithreaded mysqltest
+-- source include/not_embedded.inc
+
+# Test sleeps for long times
+--source include/big_test.inc
+
+# check that CSV engine was compiled in
+--source include/have_csv.inc
+
+connect (con1,localhost,root,,);
+connect (con2,localhost,root,,);
+
+#
+# Bug #27638: slow logging to CSV table inserts bad query_time and lock_time values
+#
+connection con1;
+set session long_query_time=10;
+select get_lock('bug27638', 1);
+connection con2;
+set session long_query_time=1;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 2);
+select if (query_time between '00:00:01' and '00:00:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 60);
+select if (query_time between '00:00:59' and '00:01:10', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+truncate table mysql.slow_log;
+select get_lock('bug27638', 101);
+select if (query_time between '00:01:40' and '00:01:50', 'OK', 'WRONG') as qt, sql_text from mysql.slow_log;
+connection con1;
+select release_lock('bug27638');
+connection default;
+
+disconnect con1;
+disconnect con2;
diff --git a/sql/log.cc b/sql/log.cc
index 57f16a1e11e..3cfcabd8363 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -569,11 +569,21 @@ bool Log_to_csv_event_handler::
 
   if (query_start_arg)
   {
+    /*
+      A TIME field can not hold the full longlong range; query_time or
+      lock_time may be truncated without warning here, if greater than
+      839 hours (~35 days)
+    */
+    TIME t;
+    t.neg= 0;
+
     /* fill in query_time field */
-    if (table->field[2]->store(query_time, TRUE))
+    calc_time_from_sec(&t, (long) min(query_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
+    if (table->field[2]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* lock_time */
-    if (table->field[3]->store(lock_time, TRUE))
+    calc_time_from_sec(&t, (long) min(lock_time, (longlong) TIME_MAX_VALUE_SECONDS), 0);
+    if (table->field[3]->store_time(&t, MYSQL_TIMESTAMP_TIME))
       goto err;
     /* rows_sent */
     if (table->field[4]->store((longlong) thd->sent_row_count, TRUE))
diff --git a/sql/time.cc b/sql/time.cc
index 4854206b1c8..ef2c87673d5 100644
--- a/sql/time.cc
+++ b/sql/time.cc
@@ -313,6 +313,11 @@ void localtime_to_TIME(TIME *to, struct tm *from)
 void calc_time_from_sec(TIME *to, long seconds, long microseconds)
 {
   long t_seconds;
+  // to->neg is not cleared, it may already be set to a useful value
+  to->time_type= MYSQL_TIMESTAMP_TIME;
+  to->year= 0;
+  to->month= 0;
+  to->day= 0;
   to->hour= seconds/3600L;
   t_seconds= seconds%3600L;
   to->minute= t_seconds/60L;