WL#3984 (Revise locking of mysql.general_log and mysql.slow_log)

Bug#25422 (Hang with log tables)
Bug 17876 (Truncating mysql.slow_log in a SP after using cursor locks the
          thread)
Bug 23044 (Warnings on flush of a log table)
Bug 29129 (Resetting general_log while the GLOBAL READ LOCK is set causes
           a deadlock)

Prior to this fix, the server would hang when performing concurrent
ALTER TABLE or TRUNCATE TABLE statements against the LOG TABLES,
which are mysql.general_log and mysql.slow_log.

The root cause traces to the following code:
in sql_base.cc, open_table()
  if (table->in_use != thd)
  {
    /* wait_for_condition will unlock LOCK_open for us */
    wait_for_condition(thd, &LOCK_open, &COND_refresh);
  }
The problem with this code is that the current implementation of the
LOGGER creates 'fake' THD objects, like
- Log_to_csv_event_handler::general_log_thd
- Log_to_csv_event_handler::slow_log_thd
which are not associated to a real thread running in the server,
so that waiting for these non-existing threads to release table locks
cause the dead lock.

In general, the design of Log_to_csv_event_handler does not fit into the
general architecture of the server, so that the concept of general_log_thd
and slow_log_thd has to be abandoned:
- this implementation does not work with table locking
- it will not work with commands like SHOW PROCESSLIST
- having the log tables always opened does not integrate well with DDL
operations / FLUSH TABLES / SET GLOBAL READ_ONLY

With this patch, the fundamental design of the LOGGER has been changed to:
- always open and close a log table when writing a log
- remove totally the usage of fake THD objects
- clarify how locking of log tables is implemented in general.

See WL#3984 for details related to the new locking design.

Additional changes (misc bugs exposed and fixed):

1)

mysqldump which would ignore some tables in dump_all_tables_in_db(),
 but forget to ignore the same in dump_all_views_in_db().

2)

mysqldump would also issue an empty "LOCK TABLE" command when all the tables
to lock are to be ignored (numrows == 0), instead of not issuing the query.

3)

Internal errors handlers could intercept errors but not warnings
(see sql_error.cc).

4)

Implementing a nested call to open tables, for the performance schema tables,
exposed an existing bug in remove_table_from_cache(), which would perform:
  in_use->some_tables_deleted=1;
against another thread, without any consideration about thread locking.
This call inside remove_table_from_cache() was not required anyway,
since calling mysql_lock_abort() takes care of aborting -- cleanly -- threads
that might hold a lock on a table.
This line (in_use->some_tables_deleted=1) has been removed.


sql/handler.cc:
  Moved logic for system / log tables in the SQL layer.
sql/handler.h:
  Moved logic for system / log tables in the SQL layer.
sql/lock.cc:
  Revised locking of log tables
sql/log.cc:
  Major cleanup: changed how log tables are locked / written to.
sql/log.h:
  Major cleanup: changed how log tables are locked / written to.
sql/mysql_priv.h:
  performance schema helpers
sql/slave.cc:
  open_ltable() lock flags
sql/sp.cc:
  open_ltable() lock flags
sql/sql_acl.cc:
  open_ltable() lock flags
sql/sql_class.h:
  performance schema helpers
sql/sql_delete.cc:
  log tables cleanup in TRUNCATE
sql/sql_error.cc:
  Internal handlers can also intercept warnings
sql/sql_insert.cc:
  open_ltable() lock flags
sql/sql_parse.cc:
  performance schema helpers
sql/sql_plugin.cc:
  open_ltable() lock flags
sql/sql_rename.cc:
  log tables cleanup in RENAME
sql/sql_servers.cc:
  open_ltable() lock flags
sql/sql_show.cc:
  Move INFORMATION_SCHEMA_NAME to table.cc
sql/sql_table.cc:
  log tables cleanup (admin operations, ALTER TABLE)
sql/sql_udf.cc:
  open_ltable() lock flags
sql/table.cc:
  Implemented TABLE_CATEGORY.
sql/share/errmsg.txt:
  Changed the wording and name of ER_CANT_READ_LOCK_LOG_TABLE
sql/table.h:
  Implemented TABLE_CATEGORY.
storage/csv/ha_tina.cc:
  Moved logic for system / log tables in the SQL layer.
storage/csv/ha_tina.h:
  Moved logic for system / log tables in the SQL layer.
storage/myisam/ha_myisam.cc:
  Moved logic for system / log tables in the SQL layer.
storage/myisam/ha_myisam.h:
  Moved logic for system / log tables in the SQL layer.
client/mysqldump.c:
  Don't lock tables in the ignore list.
  Don't issue empty LOCK TABLES queries.
sql/sql_base.cc:
  log tables cleanup
  performance schema helpers
mysql-test/r/ps.result:
  Adjust test results
mysql-test/r/show_check.result:
  Adjust test results
mysql-test/r/status.result:
  Adjust test results
mysql-test/t/log_state.test:
  Added tests for Bug#29129
mysql-test/t/ps.test:
  Make the test output deterministic
mysql-test/t/show_check.test:
  Make the test output deterministic
mysql-test/r/log_state.result:
  Changed the default location of the log output to LOG_FILE,
  for backward compatibility with MySQL 5.0
  ---
  Adjust test results
mysql-test/r/log_tables.result:
  cleanup for -ps-protocol
mysql-test/t/log_tables.test:
  cleanup for -ps-protocol
sql/set_var.cc:
  Changed the default location of the log output to LOG_FILE,
  for backward compatibility with MySQL 5.0
  ---
  log tables cleanup

1 files changed, 269 insertions, 28 deletions

diff --git a/mysql-test/r/log_tables.result b/mysql-test/r/log_tables.result
index ce3dabe3a56..39349183276 100644
--- a/mysql-test/r/log_tables.result
+++ b/mysql-test/r/log_tables.result
@@ -29,30 +29,83 @@ on (mysql.general_log.command_type = join_test.command_type)
 drop table join_test;
 flush logs;
 lock tables mysql.general_log WRITE;
-ERROR HY000: You can't write-lock a log table. Only read access is possible
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.slow_log WRITE;
-ERROR HY000: You can't write-lock a log table. Only read access is possible
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.general_log READ;
-ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.slow_log READ;
-ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.slow_log READ LOCAL, mysql.general_log READ LOCAL;
-unlock tables;
-lock tables mysql.general_log READ LOCAL;
+ERROR HY000: You can't use locks with log tables.
+show create table mysql.general_log;
+Table	Create Table
+general_log	CREATE TABLE `general_log` (
+  `event_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
+  `user_host` mediumtext,
+  `thread_id` int(11) DEFAULT NULL,
+  `server_id` int(11) DEFAULT NULL,
+  `command_type` varchar(64) DEFAULT NULL,
+  `argument` mediumtext
+) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='General log'
+show fields from mysql.general_log;
+Field	Type	Null	Key	Default	Extra
+event_time	timestamp	NO		CURRENT_TIMESTAMP	
+user_host	mediumtext	YES		NULL	
+thread_id	int(11)	YES		NULL	
+server_id	int(11)	YES		NULL	
+command_type	varchar(64)	YES		NULL	
+argument	mediumtext	YES		NULL	
+show create table mysql.slow_log;
+Table	Create Table
+slow_log	CREATE TABLE `slow_log` (
+  `start_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
+  `user_host` mediumtext NOT NULL,
+  `query_time` time NOT NULL,
+  `lock_time` time NOT NULL,
+  `rows_sent` int(11) NOT NULL,
+  `rows_examined` int(11) NOT NULL,
+  `db` varchar(512) DEFAULT NULL,
+  `last_insert_id` int(11) DEFAULT NULL,
+  `insert_id` int(11) DEFAULT NULL,
+  `server_id` int(11) DEFAULT NULL,
+  `sql_text` mediumtext NOT NULL
+) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
+show fields from mysql.slow_log;
+Field	Type	Null	Key	Default	Extra
+start_time	timestamp	NO		CURRENT_TIMESTAMP	
+user_host	mediumtext	NO			
+query_time	time	NO			
+lock_time	time	NO			
+rows_sent	int(11)	NO			
+rows_examined	int(11)	NO			
+db	varchar(512)	YES		NULL	
+last_insert_id	int(11)	YES		NULL	
+insert_id	int(11)	YES		NULL	
+server_id	int(11)	YES		NULL	
+sql_text	mediumtext	NO			
 flush logs;
-unlock tables;
-select "Mark that we woke up from flush logs in the test"
-       as "test passed";
-test passed
-Mark that we woke up from flush logs in the test
-lock tables mysql.general_log READ LOCAL;
-truncate mysql.general_log;
-unlock tables;
-select "Mark that we woke up from TRUNCATE in the test"
-       as "test passed";
-test passed
-Mark that we woke up from TRUNCATE in the test
-use test;
+flush tables;
+SET GLOBAL GENERAL_LOG=ON;
+SET GLOBAL SLOW_QUERY_LOG=ON;
+show open tables;
+Database	Table	In_use	Name_locked
+mysql	general_log	0	0
+flush logs;
+show open tables;
+Database	Table	In_use	Name_locked
+mysql	general_log	0	0
+flush tables;
+show open tables;
+Database	Table	In_use	Name_locked
+mysql	general_log	0	0
+SET GLOBAL GENERAL_LOG=OFF;
+SET GLOBAL SLOW_QUERY_LOG=OFF;
+flush tables;
+show open tables;
+Database	Table	In_use	Name_locked
+SET GLOBAL GENERAL_LOG=ON;
+SET GLOBAL SLOW_QUERY_LOG=ON;
 truncate table mysql.general_log;
 set names utf8;
 create table bug16905 (s char(15) character set utf8 default 'пусто');
@@ -71,7 +124,7 @@ sleep(2)
 0
 select * from mysql.slow_log;
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
-TIMESTAMP	USER_HOST	QUERY_TIME	00:00:00	1	0	test	0	0	1	select sleep(2)
+TIMESTAMP	USER_HOST	QUERY_TIME	00:00:00	1	0	mysql	0	0	1	select sleep(2)
 alter table mysql.general_log engine=myisam;
 ERROR HY000: You cannot 'ALTER' a log table if logging is enabled
 alter table mysql.slow_log engine=myisam;
@@ -158,15 +211,13 @@ TIMESTAMP	USER_HOST	THREAD_ID	1	Query	set global slow_query_log='ON'
 TIMESTAMP	USER_HOST	THREAD_ID	1	Query	select * from mysql.general_log
 flush logs;
 lock tables mysql.general_log WRITE;
-ERROR HY000: You can't write-lock a log table. Only read access is possible
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.slow_log WRITE;
-ERROR HY000: You can't write-lock a log table. Only read access is possible
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.general_log READ;
-ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
+ERROR HY000: You can't use locks with log tables.
 lock tables mysql.slow_log READ;
-ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
-lock tables mysql.slow_log READ LOCAL, mysql.general_log READ LOCAL;
-unlock tables;
+ERROR HY000: You can't use locks with log tables.
 set global general_log='OFF';
 set global slow_query_log='OFF';
 set @save_storage_engine= @@session.storage_engine;
@@ -217,6 +268,7 @@ flush tables with read lock;
 unlock tables;
 use mysql;
 lock tables general_log read local, help_category read local;
+ERROR HY000: You can't use locks with log tables.
 unlock tables;
 use mysql;
 RENAME TABLE general_log TO renamed_general_log;
@@ -258,9 +310,9 @@ RENAME TABLE general_log TO general_log2;
 set global slow_query_log='OFF';
 RENAME TABLE slow_log TO slow_log2;
 set global general_log='ON';
-ERROR HY000: Cannot activate 'general' log
+ERROR 42S02: Table 'mysql.general_log' doesn't exist
 set global slow_query_log='ON';
-ERROR HY000: Cannot activate 'slow query' log
+ERROR 42S02: Table 'mysql.slow_log' doesn't exist
 RENAME TABLE general_log2 TO general_log;
 RENAME TABLE slow_log2 TO slow_log;
 set global general_log='ON';
@@ -355,3 +407,192 @@ SET SESSION long_query_time =@old_long_query_time;
 FLUSH LOGS;
 ALTER TABLE mysql.slow_log DROP COLUMN seq;
 ALTER TABLE mysql.slow_log ENGINE = CSV;
+drop procedure if exists proc25422_truncate_slow;
+drop procedure if exists proc25422_truncate_general;
+drop procedure if exists proc25422_alter_slow;
+drop procedure if exists proc25422_alter_general;
+use test//
+create procedure proc25422_truncate_slow (loops int)
+begin
+declare v1 int default 0;
+while v1 < loops do
+truncate mysql.slow_log;
+set v1 = v1 + 1;
+end while;
+end//
+create procedure proc25422_truncate_general (loops int)
+begin
+declare v1 int default 0;
+while v1 < loops do
+truncate mysql.general_log;
+set v1 = v1 + 1;
+end while;
+end//
+create procedure proc25422_alter_slow (loops int)
+begin
+declare v1 int default 0;
+declare ER_BAD_LOG_STATEMENT condition for 1575;
+declare continue handler for ER_BAD_LOG_STATEMENT begin end;
+while v1 < loops do
+set @old_log_state = @@global.slow_query_log;
+set global slow_query_log = 'OFF';
+alter table mysql.slow_log engine = CSV;
+set global slow_query_log = @old_log_state;
+set v1 = v1 + 1;
+end while;
+end//
+create procedure proc25422_alter_general (loops int)
+begin
+declare v1 int default 0;
+declare ER_BAD_LOG_STATEMENT condition for 1575;
+declare continue handler for ER_BAD_LOG_STATEMENT begin end;
+while v1 < loops do
+set @old_log_state = @@global.general_log;
+set global general_log = 'OFF';
+alter table mysql.general_log engine = CSV;
+set global general_log = @old_log_state;
+set v1 = v1 + 1;
+end while;
+end//
+"Serial test (proc25422_truncate_slow)"
+call proc25422_truncate_slow(100);
+"Serial test (proc25422_truncate_general)"
+call proc25422_truncate_general(100);
+"Serial test (proc25422_alter_slow)"
+call proc25422_alter_slow(100);
+"Serial test (proc25422_alter_general)"
+call proc25422_alter_general(100);
+"Parallel test"
+call proc25422_truncate_slow(100);
+call proc25422_truncate_slow(100);
+call proc25422_truncate_general(100);
+call proc25422_truncate_general(100);
+call proc25422_alter_slow(100);
+call proc25422_alter_slow(100);
+call proc25422_alter_general(100);
+call proc25422_alter_general(100);
+drop procedure proc25422_truncate_slow;
+drop procedure proc25422_truncate_general;
+drop procedure proc25422_alter_slow;
+drop procedure proc25422_alter_general;
+FLUSH TABLE mysql.general_log;
+show warnings;
+Level	Code	Message
+FLUSH TABLE mysql.slow_log;
+show warnings;
+Level	Code	Message
+DROP TABLE IF EXISTS `db_17876.slow_log_data`;
+DROP TABLE IF EXISTS `db_17876.general_log_data`;
+DROP PROCEDURE IF EXISTS `db_17876.archiveSlowLog`;
+DROP PROCEDURE IF EXISTS `db_17876.archiveGeneralLog`;
+DROP DATABASE IF EXISTS `db_17876`;
+CREATE DATABASE db_17876;
+CREATE TABLE `db_17876.slow_log_data` (
+`start_time` timestamp  default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
+`user_host` mediumtext ,
+`query_time` time ,
+`lock_time` time ,
+`rows_sent` int(11) ,
+`rows_examined` int(11) ,
+`db` varchar(512) default NULL,
+`last_insert_id` int(11) default NULL,
+`insert_id` int(11) default NULL,
+`server_id` int(11) default NULL,
+`sql_text` mediumtext 
+);
+CREATE TABLE `db_17876.general_log_data` (
+`event_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
+`user_host` mediumtext,
+`thread_id` int(11) DEFAULT NULL,
+`server_id` int(11) DEFAULT NULL,
+`command_type` varchar(64) DEFAULT NULL,
+`argument` mediumtext
+);
+CREATE procedure `db_17876.archiveSlowLog`()
+BEGIN
+DECLARE start_time, query_time, lock_time CHAR(20);
+DECLARE user_host MEDIUMTEXT;
+DECLARE rows_set, rows_examined, last_insert_id, insert_id, server_id INT;
+DECLARE dbname MEDIUMTEXT;
+DECLARE sql_text BLOB;
+DECLARE done INT DEFAULT 0;
+DECLARE ER_SP_FETCH_NO_DATA CONDITION for 1329;
+DECLARE cur1 CURSOR FOR SELECT * FROM mysql.slow_log;
+OPEN cur1;
+REPEAT
+BEGIN
+BEGIN
+DECLARE CONTINUE HANDLER FOR ER_SP_FETCH_NO_DATA SET done = 1;
+FETCH cur1 INTO
+start_time, user_host, query_time, lock_time,
+rows_set, rows_examined, dbname, last_insert_id,
+insert_id, server_id, sql_text;
+END;
+IF NOT done THEN
+BEGIN
+INSERT INTO
+`db_17876.slow_log_data`
+            VALUES(start_time, user_host, query_time, lock_time, rows_set, rows_examined,
+dbname, last_insert_id,  insert_id, server_id, sql_text);
+END;
+END IF;
+END;
+UNTIL done END REPEAT;
+CLOSE cur1;
+TRUNCATE mysql.slow_log;
+END //
+CREATE procedure `db_17876.archiveGeneralLog`()
+BEGIN
+DECLARE event_time CHAR(20);
+DECLARE user_host, argument MEDIUMTEXT;
+DECLARE thread_id, server_id INT;
+DECLARE sql_text BLOB;
+DECLARE done INT DEFAULT 0;
+DECLARE command_type VARCHAR(64);
+DECLARE ER_SP_FETCH_NO_DATA CONDITION for 1329;
+DECLARE cur1 CURSOR FOR SELECT * FROM mysql.general_log;
+OPEN cur1;
+REPEAT
+BEGIN
+BEGIN
+DECLARE CONTINUE HANDLER FOR ER_SP_FETCH_NO_DATA SET done = 1;
+FETCH cur1 INTO
+event_time, user_host, thread_id, server_id,
+command_type, argument;
+END;
+IF NOT done THEN
+BEGIN
+INSERT INTO
+`db_17876.general_log_data`
+            VALUES(event_time, user_host, thread_id, server_id,
+command_type, argument);
+END;
+END IF;
+END;
+UNTIL done END REPEAT;
+CLOSE cur1;
+TRUNCATE mysql.general_log;
+END //
+SET @old_general_log_state = @@global.general_log;
+SET @old_slow_log_state = @@global.slow_query_log;
+SET GLOBAL general_log = ON;
+SET GLOBAL slow_query_log = ON;
+select "put something into general_log";
+put something into general_log
+put something into general_log
+select "... and something more ...";
+... and something more ...
+... and something more ...
+call `db_17876.archiveSlowLog`();
+call `db_17876.archiveGeneralLog`();
+SET GLOBAL general_log = OFF;
+SET GLOBAL slow_query_log = OFF;
+call `db_17876.archiveSlowLog`();
+call `db_17876.archiveGeneralLog`();
+DROP TABLE `db_17876.slow_log_data`;
+DROP TABLE `db_17876.general_log_data`;
+DROP PROCEDURE IF EXISTS `db_17876.archiveSlowLog`;
+DROP PROCEDURE IF EXISTS `db_17876.archiveGeneralLog`;
+DROP DATABASE IF EXISTS `db_17876`;
+SET GLOBAL general_log = @old_general_log_state;
+SET GLOBAL slow_query_log = @old_slow_log_state;