MDEV-7389 Request: log warnings into SQL_ERROR_LOG

Changes:
- Audit_null records and displays warning count
- sql_error_log prints warnings

Reviewer: Alexey Botchkov <holyfoot@askmonty.org>

include/mysql/plugin_audit.h

@@ -48,6 +48,7 @@ extern "C" {
 #define MYSQL_AUDIT_GENERAL_ERROR 1
 #define MYSQL_AUDIT_GENERAL_RESULT 2
 #define MYSQL_AUDIT_GENERAL_STATUS 3
+#define MYSQL_AUDIT_GENERAL_WARNING 4
 
 struct mysql_event_general
 {

mysql-test/suite/plugins/r/audit_null.result

@@ -14,6 +14,7 @@ Audit_null_called	9
 Audit_null_general_error	1
 Audit_null_general_log	3
 Audit_null_general_result	2
+Audit_null_general_warning	1
 create procedure au1(x char(16)) select concat("test1", x);
 call au1("-12");
 concat("test1", x)
@@ -24,6 +25,7 @@ Audit_null_called	22
 Audit_null_general_error	1
 Audit_null_general_log	7
 Audit_null_general_result	5
+Audit_null_general_warning	1
 create table t1 (a int);
 insert t1 values (1), (2);
 select * from t1;

mysql-test/suite/plugins/r/server_audit.result

@@ -268,6 +268,13 @@ drop database sa_db;
 select length('01234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789');
 length('0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456
 2750
+CREATE TABLE test.t1 (a char(4));
+set sql_mode="";
+insert into test.t1 value("12345");
+Warnings:
+Warning	1265	Data truncated for column 'a' at row 1
+set sql_mode=default;
+drop table test.t1;
 set global server_audit_file_path='.';
 show status like 'server_audit_current_log';
 Variable_name	Value
@@ -505,6 +512,21 @@ TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,proc,
 TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,event,
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'drop database sa_db',0
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'select length(\'012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567',0
+TIME,HOSTNAME,root,localhost,ID,ID,CREATE,test,t1,
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'CREATE TABLE test.t1 (a char(4))',0
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'set sql_mode=""',0
+TIME,HOSTNAME,root,localhost,ID,ID,WRITE,test,t1,
+TIME,HOSTNAME,root,localhost,ID,ID,READ,mysql,table_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,READ,mysql,column_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,READ,mysql,index_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'insert into test.t1 value("12345")',0
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'SHOW WARNINGS',0
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'set sql_mode=default',0
+TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,table_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,column_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,WRITE,mysql,index_stats,
+TIME,HOSTNAME,root,localhost,ID,ID,DROP,test,t1,
+TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'drop table test.t1',0
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'set global server_audit_file_path=\'.\'',0
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'set global server_audit_file_path=\'.\'',0
 TIME,HOSTNAME,root,localhost,ID,ID,QUERY,sa_db,'show status like \'server_audit_current_log\'',0

mysql-test/suite/plugins/r/sql_error_log.result

@@ -44,6 +44,13 @@ END|
 CALL e1();
 ERROR 42S02: Table 'test.non_exists' doesn't exist
 DROP PROCEDURE e1;
+CREATE TABLE t1 (a char(4));
+set sql_mode="";
+insert into t1 value("12345");
+Warnings:
+Warning	1265	Data truncated for column 'a' at row 1
+set sql_mode=default;
+drop table t1;
 uninstall plugin SQL_ERROR_LOG;
 Warnings:
 Warning	1620	Plugin is busy and will be uninstalled on shutdown
@@ -55,3 +62,5 @@ MYSQL_ERRNO = 1000,
 MESSAGE_TEXT = 'new message'
 TIME HOSTNAME ERROR 1366: Incorrect integer value: 'aa' for column `test`.`t1`.`id` at row 1 : insert into t1 values ('aa')
 TIME HOSTNAME ERROR 1146: Table 'test.non_exists' doesn't exist : INSERT INTO test.non_exists VALUES (0,0,0) /* e1  */
+TIME HOSTNAME WARNING 1265: Data truncated for column 'a' at row 1 : insert into t1 value("12345")
+TIME HOSTNAME WARNING 1620: Plugin is busy and will be uninstalled on shutdown : uninstall plugin SQL_ERROR_LOG

mysql-test/suite/plugins/t/server_audit.test

@@ -218,6 +218,12 @@ drop database sa_db;
 
 select length('01234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789');
 
+CREATE TABLE test.t1 (a char(4));
+set sql_mode="";
+insert into test.t1 value("12345");
+set sql_mode=default;
+drop table test.t1;
+
 set global server_audit_file_path='.';
 --replace_regex /\.[\\\/]/HOME_DIR\//
 show status like 'server_audit_current_log';

mysql-test/suite/plugins/t/sql_error_log.test

@@ -1,4 +1,3 @@
-
 --source include/not_embedded.inc
 
 if (!$SQL_ERRLOG_SO) {
@@ -66,10 +65,16 @@ DELIMITER ;|
 CALL e1();
 DROP PROCEDURE e1;
 
+CREATE TABLE t1 (a char(4));
+set sql_mode="";
+insert into t1 value("12345");
+set sql_mode=default;
+drop table t1;
+
 uninstall plugin SQL_ERROR_LOG;
 
 let $MYSQLD_DATADIR= `SELECT @@datadir`;
 # replace the timestamp and the hostname with constant values
---replace_regex /[1-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [ 0-9][0-9]:[0-9][0-9]:[0-9][0-9] [^E]*/TIME HOSTNAME /
+--replace_regex /[1-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [ 0-9][0-9]:[0-9][0-9]:[0-9][0-9] [^EW]*/TIME HOSTNAME /
 cat_file $MYSQLD_DATADIR/sql_errors.log;
-
+remove_file $MYSQLD_DATADIR/sql_errors.log;

plugin/audit_null/audit_null.c

@@ -30,6 +30,7 @@
 static volatile int ncalls; /* for SHOW STATUS, see below */
 static volatile int ncalls_general_log;
 static volatile int ncalls_general_error;
+static volatile int ncalls_general_warning;
 static volatile int ncalls_general_result;
 
 FILE *f;
@@ -53,6 +54,7 @@ static int audit_null_plugin_init(void *arg __attribute__((unused)))
   ncalls= 0;
   ncalls_general_log= 0;
   ncalls_general_error= 0;
+  ncalls_general_warning= 0;
   ncalls_general_result= 0;
 
   f = fopen("audit_null_tables.log", "w");
@@ -113,6 +115,9 @@ static void audit_null_notify(MYSQL_THD thd __attribute__((unused)),
     case MYSQL_AUDIT_GENERAL_ERROR:
       ncalls_general_error++;
       break;
+    case MYSQL_AUDIT_GENERAL_WARNING:
+      ncalls_general_warning++;
+      break;
     case MYSQL_AUDIT_GENERAL_RESULT:
       ncalls_general_result++;
       break;
@@ -179,6 +184,7 @@ static struct st_mysql_show_var simple_status[]=
   { "general_error", (char *) &ncalls_general_error, SHOW_INT },
   { "general_log", (char *) &ncalls_general_log, SHOW_INT },
   { "general_result", (char *) &ncalls_general_result, SHOW_INT },
+  { "general_warning", (char *) &ncalls_general_error, SHOW_INT },
   { 0, 0, 0}
 };
 

plugin/sql_errlog/sql_errlog.c

@@ -84,8 +84,11 @@ static void log_sql_errors(MYSQL_THD thd __attribute__((unused)),
   const struct mysql_event_general *event =
          (const struct mysql_event_general*)ev;
   if (rate &&
-      event->event_subclass == MYSQL_AUDIT_GENERAL_ERROR)
+      (event->event_subclass == MYSQL_AUDIT_GENERAL_ERROR ||
+       event->event_subclass == MYSQL_AUDIT_GENERAL_WARNING))
   {
+    const char *type= (event->event_subclass == MYSQL_AUDIT_GENERAL_ERROR ?
+                       "ERROR" : "WARNING");
     if (++count >= rate)
     {
       struct tm t;
@@ -94,11 +97,11 @@ static void log_sql_errors(MYSQL_THD thd __attribute__((unused)),
       count = 0;
       (void) localtime_r(&event_time, &t);
       logger_printf(logfile, "%04d-%02d-%02d %2d:%02d:%02d "
-                      "%s ERROR %d: %s : %s\n",
-              t.tm_year + 1900, t.tm_mon + 1,
-              t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec,
-              event->general_user, event->general_error_code,
-              event->general_command, event->general_query);
+                      "%s %s %d: %s : %s\n",
+                    t.tm_year + 1900, t.tm_mon + 1,
+                    t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec,
+                    event->general_user, type, event->general_error_code,
+                    event->general_command, event->general_query);
     }
   }
 }

sql/sql_class.cc

@@ -1082,19 +1082,13 @@ Sql_condition* THD::raise_condition(const Sql_condition *cond)
     goto ret;
 
   switch (level) {
-  case Sql_condition::WARN_LEVEL_NOTE:
   case Sql_condition::WARN_LEVEL_WARN:
+    mysql_audit_general(this, MYSQL_AUDIT_GENERAL_WARNING, sql_errno, msg);
+    /* fall through */
+  case Sql_condition::WARN_LEVEL_NOTE:
     got_warning= 1;
     break;
   case Sql_condition::WARN_LEVEL_ERROR:
-    break;
-  case Sql_condition::WARN_LEVEL_END:
-    /* Impossible */
-    break;
-  }
-
-  if (level == Sql_condition::WARN_LEVEL_ERROR)
-  {
     mysql_audit_general(this, MYSQL_AUDIT_GENERAL_ERROR, sql_errno, msg);
 
     is_slave_error=  1; // needed to catch query errors during replication
@@ -1103,7 +1097,7 @@ Sql_condition* THD::raise_condition(const Sql_condition *cond)
     /*
       With wsrep we allow converting BF abort error to warning if
       errors are ignored.
-     */
+    */
     if (!is_fatal_error && no_errors &&
         (wsrep_trx().bf_aborted() || wsrep_retry_counter))
     {
@@ -1118,6 +1112,10 @@ Sql_condition* THD::raise_condition(const Sql_condition *cond)
 	da->set_error_status(sql_errno, msg, sqlstate, *cond, raised);
       }
     }
+    break;
+  case Sql_condition::WARN_LEVEL_END:
+    /* Impossible */
+    break;
   }
 
   query_cache_abort(this, &query_cache_tls);