Bug#27858 (Failing to log to a log table doesn't log anything to error log)

Before this patch, failures to write to the log tables (mysql.slow_log
and mysql.general_log) were improperly printed (the time was printed twice),
or not printed at all.

With this patch, failures to write to the log tables is reported in the
error log, for all cases of failures.

mysql-test/r/log_tables.result

@@ -270,6 +270,10 @@ use mysql;
 lock tables general_log read local, help_category read local;
 ERROR HY000: You can't use locks with log tables.
 unlock tables;
+drop table if exists mysql.renamed_general_log;
+drop table if exists mysql.renamed_slow_log;
+drop table if exists mysql.general_log_new;
+drop table if exists mysql.slow_log_new;
 use mysql;
 RENAME TABLE general_log TO renamed_general_log;
 ERROR HY000: Cannot rename 'general_log'. When logging enabled, rename to/from log table must rename two tables: the log table to an archive table and another table back to 'general_log'

mysql-test/t/log_tables.test

@@ -295,6 +295,13 @@ unlock tables;
 # Bug #21785 Server crashes after rename of the log table
 #
 
+--disable_warnings
+drop table if exists mysql.renamed_general_log;
+drop table if exists mysql.renamed_slow_log;
+drop table if exists mysql.general_log_new;
+drop table if exists mysql.slow_log_new;
+--enable_warnings
+
 use mysql;
 # Should result in error
 --error ER_CANT_RENAME_LOG_TABLE
@@ -358,6 +365,55 @@ flush logs;
 drop table renamed_general_log, renamed_slow_log;
 use test;
 
+#
+# Bug#27858 (Failing to log to a log table doesn't log anything to error log)
+#
+# This test works as expected, it's a negative test.
+# The message "[ERROR] Failed to write to mysql.general_log"
+# is printed to master.err when writing to the table mysql.general_log
+# failed.
+# However, this message is picked up by mysql-test-run.pl,
+# and reported as a test failure, which is a false negative.
+# There is no current way to *selectively* filter out these expected error conditions
+# (see mysql-test/lib/mtr_report.pl, mtr_report_stats()).
+# Instead of filtering all occurences of "Failed to write to
+# mysql.general_log", which could hide bugs when the error is not expected,
+# this test case is commented instead.
+# TODO: improve filtering of expected errors in master.err in
+# mysql-test-run.pl (based on the test name ?), and uncomment this test.
+
+# --disable_warnings
+# drop table if exists mysql.bad_general_log;
+# drop table if exists mysql.bad_slow_log;
+# drop table if exists mysql.general_log_hide;
+# drop table if exists mysql.slow_log_hide;
+# --enable_warnings
+# 
+# create table mysql.bad_general_log (a int) engine= CSV;
+# create table mysql.bad_slow_log (a int) engine= CSV;
+# 
+# # Rename does not perform checks on the table structure,
+# # exploiting this to force a failure to log
+# rename table mysql.general_log to mysql.general_log_hide, mysql.bad_general_log TO mysql.general_log;
+# rename table mysql.slow_log to mysql.slow_log_hide, mysql.bad_slow_log TO mysql.slow_log;
+# 
+# # The following message should be printed in master.log:
+# # [ERROR] Failed to write to mysql.general_log
+# # TODO: See how verifying this could be automated
+# 
+# flush tables;
+# select "logging this should fail";
+# 
+# # Restore the log tables
+# 
+# rename table mysql.general_log to mysql.bad_general_log, mysql.general_log_hide TO mysql.general_log;
+# rename table mysql.slow_log to mysql.bad_slow_log, mysql.slow_log_hide TO mysql.slow_log;
+# 
+# flush tables;
+# 
+# drop table mysql.bad_general_log;
+# drop table mysql.bad_slow_log;
+
 #
 # Bug #21966 Strange warnings on repair of the log tables
 #

sql/log.cc

@@ -387,10 +387,15 @@ bool Log_to_csv_event_handler::
   if (table->field[1]->store(user_host, user_host_len, client_cs) ||
       table->field[2]->store((longlong) thread_id, TRUE) ||
       table->field[3]->store((longlong) server_id, TRUE) ||
-      table->field[4]->store(command_type, command_type_len, client_cs) ||
-      table->field[5]->store(sql_text, sql_text_len, client_cs))
+      table->field[4]->store(command_type, command_type_len, client_cs))
     goto err;
 
+  /*
+    A positive return value in store() means truncation.
+    Still logging a message in the log in this case.
+  */
+  if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0)
+    goto err;
 
   /* mark all fields as not null */
   table->field[1]->set_notnull();
@@ -407,19 +412,14 @@ bool Log_to_csv_event_handler::
 
   /* log table entries are not replicated */
   if (table->file->ha_write_row(table->record[0]))
-  {
-    struct tm start;
-    localtime_r(&event_time, &start);
-
-    sql_print_error("%02d%02d%02d %2d:%02d:%02d - Failed to write to mysql.general_log",
-                    start.tm_year % 100, start.tm_mon + 1,
-                    start.tm_mday, start.tm_hour,
-                    start.tm_min, start.tm_sec);
-  }
+    goto err;
 
   result= FALSE;
 
 err:
+  if (result)
+    sql_print_error("Failed to write to mysql.general_log");
+
   if (need_rnd_end)
   {
     table->file->ha_rnd_end();
@@ -595,25 +595,24 @@ bool Log_to_csv_event_handler::
     goto err;
   table->field[9]->set_notnull();
 
-  /* sql_text */
-  if (table->field[10]->store(sql_text,sql_text_len, client_cs))
+  /*
+    Column sql_text.
+    A positive return value in store() means truncation.
+    Still logging a message in the log in this case.
+  */
+  if (table->field[10]->store(sql_text, sql_text_len, client_cs) < 0)
     goto err;
 
   /* log table entries are not replicated */
   if (table->file->ha_write_row(table->record[0]))
-  {
-    struct tm start;
-    localtime_r(&current_time, &start);
-
-    sql_print_error("%02d%02d%02d %2d:%02d:%02d - Failed to write to mysql.slow_log",
-                    start.tm_year % 100, start.tm_mon + 1,
-                    start.tm_mday, start.tm_hour,
-                    start.tm_min, start.tm_sec);
-  }
+    goto err;
 
   result= FALSE;
 
 err:
+  if (result)
+    sql_print_error("Failed to write to mysql.slow_log");
+
   if (need_rnd_end)
   {
     table->file->ha_rnd_end();