Skip to content

M
MariaDB
Commit 8f9168df authored by kostja@bodhi.(none)'s avatar kostja@bodhi.(none)
Browse files
Options

A fix for Bug#30212 events_logs_tests not deterministic; SLEEP(2), others 

Make the test deterministic.
parent 3ecef8c0
Show whitespace changes
Inline Side-by-side
Showing with 138 additions and 196 deletions
mysql-test/r/events_logs_tests.result
View file @ 8f9168df
CREATE DATABASE IF NOT EXISTS events_test; drop database if exists events_test;
USE events_test; create database if not exists events_test;
"We use procedure here because its statements won't be logged into the general log" use events_test;
"If we had used normal select that are logged in different ways depending on whether"
"the test suite is run in normal mode or with --ps-protocol" We use procedure here because its statements won't be
CREATE procedure select_general_log() logged into the general log. If we had used normal select
BEGIN that are logged in different ways depending on whether the
SELECT user_host, argument FROM mysql.general_log WHERE argument LIKE '%alabala%'; test suite is run in normal mode or with --ps-protocol
END|
"Check General Query Log" create procedure select_general_log()
CALL select_general_log(); begin
select user_host, argument from mysql.general_log
where argument like '%events_logs_test%';
end|
Check that general query log works, but sub-statements
of the stored procedure do not leave traces in it.
truncate mysql.general_log;
select 'events_logs_tests' as outside_event;
outside_event
events_logs_tests
call select_general_log();
user_host argument user_host argument
USER_HOST CREATE procedure select_general_log() USER_HOST select 'events_logs_tests' as outside_event
BEGIN
SELECT user_host, argument FROM mysql.general_log WHERE argument LIKE '%alabala%'; Check that unlike sub-statements of stored procedures,
END sub-statements of events are present in the general log.
SET GLOBAL event_scheduler=on;
TRUNCATE mysql.general_log; set global event_scheduler=on;
CREATE EVENT log_general ON SCHEDULE EVERY 1 MINUTE DO SELECT 'alabala', SLEEP(1) FROM DUAL; truncate mysql.general_log;
"Wait the scheduler to start" create event ev_log_general on schedule at now() on completion not preserve do select 'events_logs_test' as inside_event;
"Should see 2 rows - the 'SELECT' is in the middle. The other two are selects from general_log" call select_general_log();
CALL select_general_log();
user_host argument user_host argument
USER_HOST CREATE EVENT log_general ON SCHEDULE EVERY 1 MINUTE DO SELECT 'alabala', SLEEP(1) FROM DUAL USER_HOST create event ev_log_general on schedule at now() on completion not preserve do select 'events_logs_test' as inside_event
USER_HOST SELECT 'alabala', SLEEP(1) FROM DUAL USER_HOST select 'events_logs_test' as inside_event
DROP PROCEDURE select_general_log;
DROP EVENT log_general; Check slow query log
SET GLOBAL event_scheduler=off;
"Check slow query log" Ensure that slow logging is on
"Save the values" show variables like 'log_slow_queries';
SET @old_global_long_query_time:=(select get_value());
SET @old_session_long_query_time:=@@long_query_time;
SHOW VARIABLES LIKE 'log_slow_queries';
Variable_name Value Variable_name Value
log_slow_queries ON log_slow_queries ON
DROP FUNCTION get_value;
"Make it quite long" Demonstrate that session value has no effect
SET SESSION long_query_time=300;
TRUNCATE mysql.slow_log; set @@session.long_query_time=1;
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; set @@global.long_query_time=300;
user_host query_time db sql_text truncate mysql.slow_log;
"Set new values" create event ev_log_general on schedule at now() on completion not preserve
SET GLOBAL long_query_time=4; do select 'events_logs_test' as inside_event, sleep(1.5);
SET SESSION long_query_time=0.5;
"Check that logging is working" Nothing should be logged
SELECT SLEEP(2);
SLEEP(2) select user_host, db, sql_text from mysql.slow_log where sql_text not like 'create event%';
0 user_host db sql_text
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; set @@global.long_query_time=1;
user_host query_time db sql_text truncate mysql.slow_log;
USER_HOST SLEEPVAL events_test SELECT SLEEP(2) create event ev_log_general on schedule at now() on completion not preserve
SET SESSION long_query_time=300; do select 'events_logs_test' as inside_event, sleep(1.5);
"Make it quite long"
TRUNCATE mysql.slow_log; Event sub-statement should be logged.
CREATE TABLE slow_event_test (slo_val tinyint, val tinyint);
SET SESSION long_query_time=1; select user_host, db, sql_text from mysql.slow_log where sql_text not like 'create event%';
"This won't go to the slow log" user_host db sql_text
SELECT * FROM slow_event_test; USER_HOST events_test select 'events_logs_test' as inside_event, sleep(1.5)
slo_val val drop database events_test;
SET SESSION long_query_time=1; set global event_scheduler=off;
SET GLOBAL event_scheduler=on; set @@global.long_query_time=default;
SET GLOBAL long_query_time=20; set @@session.long_query_time=default;
CREATE EVENT long_event ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(1.5);
"Sleep some more time than the actual event run will take"
SHOW VARIABLES LIKE 'event_scheduler';
Variable_name Value
event_scheduler ON
"Check our table. Should see 1 row"
SELECT * FROM slow_event_test;
slo_val val
20 0
"Check slow log. Should not see anything because 1.5 is under the threshold of 20 for GLOBAL, though over SESSION which is 1"
"This should show that the GLOBAL value is regarded and not the SESSION one of the current connection"
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
user_host query_time db sql_text
"Another test to show that GLOBAL is regarded and not SESSION."
"This should go to the slow log"
SET SESSION long_query_time=10;
DROP EVENT long_event;
SET GLOBAL long_query_time=1;
CREATE EVENT long_event2 ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(2);
"Sleep some more time than the actual event run will take"
"Check our table. Should see 2 rows"
SELECT * FROM slow_event_test;
slo_val val
20 0
1 0
"Check slow log. Should see 1 row because 2 is over the threshold of 1 for GLOBAL, though under SESSION which is 10"
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
user_host query_time db sql_text
USER_HOST SLEEPVAL events_test INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(2)
DROP EVENT long_event2;
"Make it quite long"
SET SESSION long_query_time=300;
TRUNCATE mysql.slow_log;
DROP TABLE slow_event_test;
SET GLOBAL long_query_time =@old_global_long_query_time;
SET SESSION long_query_time =@old_session_long_query_time;
DROP DATABASE events_test;
SET GLOBAL event_scheduler=off;
mysql-test/t/events_logs_tests.test
View file @ 8f9168df
# Can't test with embedded server that doesn't support grants # Can't test with embedded server that doesn't support grants
-- source include/not_embedded.inc -- source include/not_embedded.inc
CREATE DATABASE IF NOT EXISTS events_test; --disable_warnings
USE events_test; drop database if exists events_test;
--echo "We use procedure here because its statements won't be logged into the general log" --enable_warnings
--echo "If we had used normal select that are logged in different ways depending on whether" create database if not exists events_test;
--echo "the test suite is run in normal mode or with --ps-protocol" use events_test;
--echo
--echo We use procedure here because its statements won't be
--echo logged into the general log. If we had used normal select
--echo that are logged in different ways depending on whether the
--echo test suite is run in normal mode or with --ps-protocol
--echo
delimiter |; delimiter |;
CREATE procedure select_general_log() create procedure select_general_log()
BEGIN begin
SELECT user_host, argument FROM mysql.general_log WHERE argument LIKE '%alabala%'; select user_host, argument from mysql.general_log
END| where argument like '%events_logs_test%';
end|
delimiter ;| delimiter ;|
--echo "Check General Query Log" --echo
--echo Check that general query log works, but sub-statements
--echo of the stored procedure do not leave traces in it.
--echo
truncate mysql.general_log;
# Logging format in ps protocol is slightly different
--disable_ps_protocol
select 'events_logs_tests' as outside_event;
--enable_ps_protocol
--replace_column 1 USER_HOST --replace_column 1 USER_HOST
CALL select_general_log(); call select_general_log();
SET GLOBAL event_scheduler=on; --echo
TRUNCATE mysql.general_log; --echo Check that unlike sub-statements of stored procedures,
CREATE EVENT log_general ON SCHEDULE EVERY 1 MINUTE DO SELECT 'alabala', SLEEP(1) FROM DUAL; --echo sub-statements of events are present in the general log.
--echo "Wait the scheduler to start" --echo
--sleep 1.5 set global event_scheduler=on;
--echo "Should see 2 rows - the 'SELECT' is in the middle. The other two are selects from general_log" truncate mysql.general_log;
create event ev_log_general on schedule at now() on completion not preserve do select 'events_logs_test' as inside_event;
--let $wait_condition=select count(*)=0 from information_schema.events where event_name='ev_log_general'
--source include/wait_condition.inc
--replace_column 1 USER_HOST --replace_column 1 USER_HOST
CALL select_general_log(); call select_general_log();
DROP PROCEDURE select_general_log;
DROP EVENT log_general;
SET GLOBAL event_scheduler=off;
--echo "Check slow query log" --echo
--disable_query_log --echo Check slow query log
DELIMITER |; --echo
CREATE FUNCTION get_value() --echo Ensure that slow logging is on
returns INT show variables like 'log_slow_queries';
deterministic --echo
BEGIN --echo Demonstrate that session value has no effect
DECLARE var_name CHAR(255); --echo
DECLARE var_val INT; set @@session.long_query_time=1;
DECLARE done INT DEFAULT 0; set @@global.long_query_time=300;
DECLARE cur1 CURSOR FOR SHOW GLOBAL VARIABLES LIKE 'long_query_time'; truncate mysql.slow_log;
DECLARE CONTINUE HANDLER FOR SQLSTATE '02000' SET done = 1; create event ev_log_general on schedule at now() on completion not preserve
OPEN cur1; do select 'events_logs_test' as inside_event, sleep(1.5);
FETCH cur1 INTO var_name, var_val; --let $wait_condition=select count(*)=0 from information_schema.events where event_name='ev_log_general'
CLOSE cur1; --source include/wait_condition.inc
RETURN var_val; --echo
end| --echo Nothing should be logged
DELIMITER ;| --echo
--enable_query_log
--echo "Save the values"
SET @old_global_long_query_time:=(select get_value());
SET @old_session_long_query_time:=@@long_query_time;
SHOW VARIABLES LIKE 'log_slow_queries';
DROP FUNCTION get_value;
--echo "Make it quite long"
SET SESSION long_query_time=300;
TRUNCATE mysql.slow_log;
--replace_column 1 USER_HOST --replace_column 1 USER_HOST
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; select user_host, db, sql_text from mysql.slow_log where sql_text not like 'create event%';
--echo "Set new values" set @@global.long_query_time=1;
SET GLOBAL long_query_time=4; truncate mysql.slow_log;
SET SESSION long_query_time=0.5; create event ev_log_general on schedule at now() on completion not preserve
--echo "Check that logging is working" do select 'events_logs_test' as inside_event, sleep(1.5);
SELECT SLEEP(2); --let $wait_condition=select count(*)=0 from information_schema.events where event_name='ev_log_general'
--replace_column 1 USER_HOST 2 SLEEPVAL
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
SET SESSION long_query_time=300;
--echo "Make it quite long"
TRUNCATE mysql.slow_log;
CREATE TABLE slow_event_test (slo_val tinyint, val tinyint);
SET SESSION long_query_time=1;
--echo "This won't go to the slow log"
SELECT * FROM slow_event_test;
SET SESSION long_query_time=1;
SET GLOBAL event_scheduler=on;
SET GLOBAL long_query_time=20;
CREATE EVENT long_event ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(1.5);
--echo "Sleep some more time than the actual event run will take"
--sleep 2
SHOW VARIABLES LIKE 'event_scheduler';
--echo "Check our table. Should see 1 row"
SELECT * FROM slow_event_test;
--echo "Check slow log. Should not see anything because 1.5 is under the threshold of 20 for GLOBAL, though over SESSION which is 1"
--echo "This should show that the GLOBAL value is regarded and not the SESSION one of the current connection"
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
--echo "Another test to show that GLOBAL is regarded and not SESSION."
--echo "This should go to the slow log"
SET SESSION long_query_time=10;
DROP EVENT long_event;
SET GLOBAL long_query_time=1;
CREATE EVENT long_event2 ON SCHEDULE EVERY 1 MINUTE DO INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(2);
--echo "Sleep some more time than the actual event run will take"
let $wait_timeout= 30;
let $wait_condition= SELECT COUNT(*) = 1 FROM mysql.slow_log;
--source include/wait_condition.inc --source include/wait_condition.inc
--echo "Check our table. Should see 2 rows" --echo
SELECT * FROM slow_event_test; --echo Event sub-statement should be logged.
--echo "Check slow log. Should see 1 row because 2 is over the threshold of 1 for GLOBAL, though under SESSION which is 10" --echo
--replace_column 1 USER_HOST 2 SLEEPVAL --replace_column 1 USER_HOST
SELECT user_host, query_time, db, sql_text FROM mysql.slow_log; select user_host, db, sql_text from mysql.slow_log where sql_text not like 'create event%';
DROP EVENT long_event2;
--echo "Make it quite long"
SET SESSION long_query_time=300;
TRUNCATE mysql.slow_log;
DROP TABLE slow_event_test;
SET GLOBAL long_query_time =@old_global_long_query_time;
SET SESSION long_query_time =@old_session_long_query_time;
DROP DATABASE events_test;
SET GLOBAL event_scheduler=off; drop database events_test;
set global event_scheduler=off;
set @@global.long_query_time=default;
set @@session.long_query_time=default;
#
# Safety
#
let $wait_condition= let $wait_condition=
select count(*) = 0 from information_schema.processlist select count(*) = 0 from information_schema.processlist
where db='events_test' and command = 'Connect' and user=current_user(); where db='events_test' and command = 'Connect' and user=current_user();
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7