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>
2025-01-28 17:54:16 +01:00 · 2023-05-23 15:32:50 +03:00 · 2023-05-23 15:32:50 +03:00 · e9fe39d566
commit e9fe39d566
parent 7c9f275ee4
9 changed files with 71 additions and 19 deletions
--- a/include/mysql/plugin_audit.h
+++ b/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
 {
--- a/mysql-test/suite/plugins/r/audit_null.result
+++ b/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;
--- a/mysql-test/suite/plugins/r/server_audit.result
+++ b/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
--- a/mysql-test/suite/plugins/r/sql_error_log.result
+++ b/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
--- a/mysql-test/suite/plugins/t/server_audit.test
+++ b/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';
--- a/mysql-test/suite/plugins/t/sql_error_log.test
+++ b/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;
--- a/plugin/audit_null/audit_null.c
+++ b/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}
 };

--- a/plugin/sql_errlog/sql_errlog.c
+++ b/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);
    }
  }
 }
--- a/sql/sql_class.cc
+++ b/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);