[MDEV-24799] Tests involving events fail if executed in the hour of daylight saving time switch Created: 2021-02-06  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Events, Tests
Affects Version/s: 10.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: None


 Description   

I am filing it as "Tests" issue for now, but it needs to be investigated further, possibly there is an underlying problem there bigger than just tests.

There were numerous test failures (none of which is from the usual sporadically failing bunch) on a build run on Nov 11 between 01:00 and 02:00 in one of US timezones, e.g. p801 running kvm-deb-bionic-ppc64le.

All failures are happening apparently because an event which is supposed to be executed was not.
Current time can be seen in timestamps on ".reject" files.

10.3

 
roles.definer                            w4 [ fail ]
 
        Test ended at 2020-11-01 01:01:29
 
 
 
CURRENT_TEST: roles.definer
 
--- /usr/share/mysql/mysql-test/suite/roles/definer.result	2020-10-31 21:03:42.000000000 -0400
 
+++ /dev/shm/var/4/log/definer.reject	2020-11-01 01:01:29.721397954 -0400
 
@@ -267,11 +267,15 @@
 
 show create event e2;
 
 Event	sql_mode	time_zone	Create Event	character_set_client	collation_connection	Database Collation
 
 e2	STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION	SYSTEM	CREATE DEFINER=`role2` EVENT `e2` ON SCHEDULE EVERY 1 SECOND STARTS '2000-01-01 00:00:00' ON COMPLETION NOT PRESERVE ENABLE DO insert t1 values (111, 4, 0)	latin1	latin1_swedish_ci	latin1_swedish_ci
 
+Timeout in wait_condition.inc for select count(*) >= 4 from t1
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+39	root	localhost	mysqltest1	Query	0	Init	show full processlist	0.000
 
+40	foo	localhost	mysqltest1	Sleep	30		NULL	0.000
 
+41	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
 set global event_scheduler=off;
 
 select distinct * from t1;
 
 a	b	c
 
 1	10	100
 
-111	4	0
 
 2	20	200
 
 delete from t1 where a=111;


main.create_drop_event                   w1 [ fail ]
 
        Test ended at 2020-11-01 01:02:08
 
 
 
CURRENT_TEST: main.create_drop_event
 
--- /usr/share/mysql/mysql-test/main/create_drop_event.result	2020-10-31 21:03:38.000000000 -0400
 
+++ /dev/shm/var/1/log/create_drop_event.reject	2020-11-01 01:02:08.489834905 -0400
 
@@ -10,9 +10,12 @@
 
 EVENT_NAME	EVENT_DEFINITION
 
 ev1	INSERT INTO t1 VALUES (10)
 
 SET GLOBAL event_scheduler=on;
 
+Timeout in wait_condition.inc for SELECT count(*)>0 FROM t1
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+1098	root	localhost	test	Query	0	Init	show full processlist	0.000
 
+1099	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
 SELECT DISTINCT a FROM t1;
 
 a
 
-10
 
 SET GLOBAL event_scheduler=off;
 
 DELETE FROM t1;
 
 CREATE EVENT ev1 ON SCHEDULE EVERY 1 SECOND DO INSERT INTO t1 VALUES (11);
 
@@ -34,9 +37,12 @@
 
 EVENT_NAME	EVENT_DEFINITION
 
 ev1	INSERT INTO t1 VALUES (13)
 
 SET GLOBAL event_scheduler=on;
 
+Timeout in wait_condition.inc for SELECT count(*)>0 FROM t1
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+1098	root	localhost	test	Query	0	Init	show full processlist	0.000
 
+1100	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
 SELECT DISTINCT a FROM t1;
 
 a
 
-13
 
 SET GLOBAL event_scheduler=off;
 
 DELETE FROM t1;
 
 DROP EVENT IF EXISTS ev1;
 
 
 
mysqltest: Result length mismatch


main.openssl_1                           w3 [ fail ]
 
        Test ended at 2020-11-01 01:02:53
 
 
 
CURRENT_TEST: main.openssl_1
 
mysqltest: At line 156: query 'SELECT variable_name, variable_value FROM thread_status' failed: 1146: Table 'test.thread_status' doesn't exist
 
 
 
The result from queries just before the failure was:
 
< snip >
 
End of 5.0 tests
 
DROP TABLE IF EXISTS thread_status;
 
DROP EVENT IF EXISTS event_status;
 
SET GLOBAL event_scheduler=1;
 
CREATE EVENT event_status
 
ON SCHEDULE AT NOW()
 
ON COMPLETION NOT PRESERVE
 
DO
 
BEGIN
 
CREATE TABLE thread_status
 
SELECT variable_name, variable_value
 
FROM information_schema.session_status
 
WHERE variable_name LIKE 'SSL_ACCEPTS' OR
 
variable_name LIKE 'SSL_CALLBACK_CACHE_HITS';
 
END$$
 
Timeout in wait_condition.inc for select count(*) = 0 from information_schema.events where event_name='event_status'
 
Id	User	Host	db	Command	Time	State	Info	Progress
 
10958	root	localhost	test	Query	0	Init	show full processlist	0.000
 
10969	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
SELECT variable_name, variable_value FROM thread_status;
 
 
 
mysqltest: Result length mismatch


main.events_1                            w1 [ fail ]
 
        Test ended at 2020-11-01 01:04:44
 
 
 
CURRENT_TEST: main.events_1
 
--- /usr/share/mysql/mysql-test/main/events_1.result	2020-10-31 21:03:38.000000000 -0400
 
+++ /dev/shm/var/1/log/events_1.reject	2020-11-01 01:04:44.403567695 -0400
 
@@ -105,20 +105,27 @@
 
 insert into test_nested values(1);
 
 end|
 
 set global event_scheduler = on;
 
+Timeout in wait_condition.inc for SELECT count(*)>0 from mysql.event where name='e_43' and interval_value= 5
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+26	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
+29	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
 select db, name, body, status, interval_field, interval_value from mysql.event;
 
 db	name	body	status	interval_field	interval_value
 
 events_test	e_43	begin
 
 alter event e_43 on schedule every 5 minute;
 
 insert into test_nested values(1);
 
-end	ENABLED	MINUTE	5
 
+end	ENABLED	SECOND	1
 
 drop event e_43;
 
 drop table test_nested;
 
 "Let's check whether we can use non-qualified names"
 
 create table non_qualif(a int);
 
 create event non_qualif_ev on schedule every 10 minute do insert into non_qualif values (800219);
 
+Timeout in wait_condition.inc for SELECT count(*)= 1 from non_qualif where a=800219
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+26	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
+29	event_scheduler	localhost	NULL	Daemon	60	Waiting for next activation	NULL	0.000
 
 select * from non_qualif;
 
 a
 
-800219
 
 drop event non_qualif_ev;
 
 drop table non_qualif;
 
 alter event non_existant rename to non_existant_too;
 
 
 
mysqltest: Result length mismatch


main.events_slowlog                      w3 [ fail ]
 
        Test ended at 2020-11-01 01:06:00
 
 
 
CURRENT_TEST: main.events_slowlog
 
--- /usr/share/mysql/mysql-test/main/events_slowlog.result	2020-10-31 21:03:38.000000000 -0400
 
+++ /dev/shm/var/3/log/events_slowlog.reject	2020-11-01 01:06:00.760404303 -0400
 
@@ -6,7 +6,11 @@
 
 create table t1 (i int);
 
 insert into t1 values (0);
 
 create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=1+sleep(0.5);
 
-FOUND 1 /update t1 set i=1/ in mysqld-slow.log
 
+Timeout in wait_condition.inc for select i from t1 where i > 0
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+9	root	localhost	test	Query	0	Init	show full processlist	0.000
 
+10	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
+NOT FOUND /update t1 set i=1/ in mysqld-slow.log
 
 drop table t1;
 
 set global event_scheduler= @event_scheduler_save;
 
 set global slow_query_log= @slow_query_log_save;
 
 
 
mysqltest: Result length mismatch


main.events_2                            w2 [ fail ]
 
        Test ended at 2020-11-01 01:07:01
 
 
 
CURRENT_TEST: main.events_2
 
--- /usr/share/mysql/mysql-test/main/events_2.result	2020-10-31 21:03:38.000000000 -0400
 
+++ /dev/shm/var/2/log/events_2.reject	2020-11-01 01:07:00.693056404 -0400
 
@@ -54,13 +54,19 @@
 
 "Create an event which tries to acquire a mutex. The event locks on the mutex"
 
 create event закачка on schedule every 10 hour do select get_lock("test_lock2", 20);
 
 "Should have only 2 processes: the scheduler and the locked event"
 
+Timeout in wait_condition.inc for select count(*) = 2 from information_schema.processlist
 
+where ( (state like 'User lock%' AND info like 'select get_lock%')
 
+OR (command='Daemon' AND user='event_scheduler' AND
 
+state = 'Waiting for next activation'))
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+4	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
+5	event_scheduler	localhost	NULL	Daemon	30	Waiting for next activation	NULL	0.000
 
 select /*2*/ user, host, db, command, state, info
 
 from information_schema.processlist
 
 where (info like "select get_lock%" OR user='event_scheduler')
 
 order by info;
 
 user	host	db	command	state	info
 
 event_scheduler	localhost	NULL	Daemon	Waiting for next activation	NULL
 
-root	localhost	events_test	Connect	User lock	select get_lock("test_lock2", 20)
 
 "Release the mutex, the event worker should finish."
 
 select release_lock("test_lock2");
 
 release_lock("test_lock2")
 
@@ -72,21 +78,30 @@
 
 1
 
 create event закачка21 on schedule every 10 hour do select get_lock("test_lock2_1", 20);
 
 "Should have only 2 processes: the scheduler and the locked event"
 
+Timeout in wait_condition.inc for select count(*) = 2 from information_schema.processlist
 
+where ( (state like 'User lock%' AND info like 'select get_lock%')
 
+OR (command='Daemon' AND user='event_scheduler' AND
 
+state = 'Waiting for next activation'))
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+4	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
+5	event_scheduler	localhost	NULL	Daemon	60	Waiting for next activation	NULL	0.000
 
 select /*3*/ user, host, db, command, state, info
 
 from information_schema.processlist
 
 where (info like "select get_lock%" OR user='event_scheduler')
 
 order by info;
 
 user	host	db	command	state	info
 
 event_scheduler	localhost	NULL	Daemon	Waiting for next activation	NULL
 
-root	localhost	events_test	Connect	User lock	select get_lock("test_lock2_1", 20)
 
 set global event_scheduler=off;
 
+Timeout in wait_condition.inc for select count(*) =1 from information_schema.processlist
 
+where (info like "select get_lock%" OR user='event_scheduler')
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+4	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
 "Should have only our process now:"
 
 select /*4*/ user, host, db, command, state, info
 
 from information_schema.processlist
 
 where (info like "select get_lock%" OR user='event_scheduler')
 
 order by info;
 
 user	host	db	command	state	info
 
-root	localhost	events_test	Connect	User lock	select get_lock("test_lock2_1", 20)
 
 select release_lock("test_lock2_1");
 
 release_lock("test_lock2_1")
 
 1
 
 
 
mysqltest: Result length mismatch


main.events_scheduling                   w4 [ fail ]
 
        Test ended at 2020-11-01 01:07:31
 
 
 
CURRENT_TEST: main.events_scheduling
 
mysqltest: At line 100: query 'DROP EVENT event_3' succeeded - should have failed with errno 1539...
 
 
 
The result from queries just before the failure was:
 
< snip >
 
Id	User	Host	db	Command	Time	State	Info	Progress
 
11	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
13	event_scheduler	localhost	NULL	Daemon	60	Waiting for next activation	NULL	0.000
 
Timeout in wait_condition.inc for select count(*) = 0 from information_schema.events
 
where event_name='event_3'
 
Id	User	Host	db	Command	Time	State	Info	Progress
 
11	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
13	event_scheduler	localhost	NULL	Daemon	90	Waiting for next activation	NULL	0.000
 
Timeout in wait_condition.inc for select count(*) = 0 from information_schema.events
 
where event_name='event_4' and status='enabled'
 
Id	User	Host	db	Command	Time	State	Info	Progress
 
11	root	localhost	events_test	Query	0	Init	show full processlist	0.000
 
13	event_scheduler	localhost	NULL	Daemon	120	Waiting for next activation	NULL	0.000
 
SELECT IF(TIME_TO_SEC(TIMEDIFF(ENDS,STARTS))=6, 'OK', 'ERROR')
 
FROM INFORMATION_SCHEMA.EVENTS
 
WHERE EVENT_SCHEMA=DATABASE() AND EVENT_NAME='event_2';
 
IF(TIME_TO_SEC(TIMEDIFF(ENDS,STARTS))=6, 'OK', 'ERROR')
 
OK
 
"Already dropped because ended. Therefore an error."
 
DROP EVENT event_3;



 Comments   
Comment by Elena Stepanova [ 2023-11-29 ]

Setting fix version to 10.4 to avoid it being closed because 10.3 reached EOL. I didn't check that it's still happening on newer versions.

Generated at Thu Feb 08 09:32:45 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.