Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24799

Tests involving events fail if executed in the hour of daylight saving time switch

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Won't Fix
    • 10.3
    • N/A
    • Events, Tests
    • 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;
      

      Attachments

        Activity

          People

            Unassigned Unassigned
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.