[MDEV-13765] encryption.encrypt_and_grep failed in buildbot with wrong result (sporadic) Created: 2017-09-08  Updated: 2023-04-27

Status: Confirmed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.1, 10.4.13, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Thirunarayanan Balathandayuthapani
Resolution: Unresolved Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9511/steps/test_2/logs/stdio

encryption.encrypt_and_grep 'cbc,innodb' w4 [ fail ]
 
        Test ended at 2017-09-08 05:21:32
 
 
 
CURRENT_TEST: encryption.encrypt_and_grep
 
--- /mnt/buildbot/build/mariadb-10.2.9/mysql-test/suite/encryption/r/encrypt_and_grep.result	2017-09-08 01:57:14.000000000 +0300
 
+++ /mnt/buildbot/build/mariadb-10.2.9/mysql-test/suite/encryption/r/encrypt_and_grep.reject	2017-09-08 05:21:32.000000000 +0300
 
@@ -14,11 +14,8 @@
 
 test/t3
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION <> 0;
 
 NAME
 
-mysql/innodb_table_stats
 
-mysql/innodb_index_stats
 
 test/t1
 
 test/t2
 
-innodb_system
 
 # t1 yes on expecting NOT FOUND
 
 NOT FOUND /foobarsecret/ in t1.ibd
 
 # t2 ... on expecting NOT FOUND
 
@@ -30,10 +27,16 @@
 
 # Now turn off encryption and wait for threads to decrypt everything
 
 SET GLOBAL innodb_encrypt_tables = off;
 
 # Wait max 10 min for key encryption threads to decrypt all spaces
 
+Timeout in wait_condition.inc for SELECT COUNT(*) = 5 FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0 AND CURRENT_KEY_VERSION = 0;
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+1	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
+2	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
+8	root	localhost	test	Query	0	init	show full processlist	0.000
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0;
 
 NAME
 
-mysql/innodb_table_stats
 
-mysql/innodb_index_stats
 
 test/t2
 
 test/t3
 
 innodb_system
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Elena Stepanova [ 2017-09-08 ]

This is a basic race condition.
The test assumes, that all existing tablespaces are immediately visible in INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION, and then only the key version changes when the tablespaces get encrypted; but it is not so. It takes time for tablespaces to appear in the I_S table, the simple crude test below shows it (it's for demonstration purposes only, do not put it in the test suite!):

suite/encryption/t/t1.opt

 
--innodb-encrypt-tables=ON
 
--innodb-encrypt-log=ON
 
--innodb-encryption-rotate-key-age=15
 
--innodb-encryption-threads=4
 
--innodb-tablespaces-encryption
 
--plugin-load-add=file_key_management
 
--file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys.txt

suite/encryption/t/t1.test

 
-- source include/have_innodb.inc
 
 
 
SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION ORDER BY NAME;
 
--sleep 5
 
SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION ORDER BY NAME;

If you run it with --repeat=N --force-restart, you get all kinds of results:

SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION ORDER BY NAME;
 
NAME
 
innodb_system
 
mysql/innodb_index_stats
 
mysql/innodb_table_stats


SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION ORDER BY NAME;
 
NAME
 
innodb_system


SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION ORDER BY NAME;
 
NAME
 
innodb_system
 
mysql/innodb_table_stats

etc.

I'll leave it to jplindst to decide whether it's the test that has unreasonable expectations, or something goes wrong with INNODB_TABLESPACES_ENCRYPTION.

Upd:
While it doesn't seem to be happening in buildbot on 10.1, the same race condition technically applies there, so I've added it to Affects/Fix versions.

Comment by Michael Widenius [ 2020-01-30 ]

Got a similar failure on this today in 10.4.13

Comment by Alice Sherepa [ 2020-07-06 ]

10.4 http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos6-amd64/builds/18962/steps/mtr/logs/stdio

encryption.encrypt_and_grep 'ctr,innodb' w4 [ fail ]
 
        Test ended at 2020-07-01 12:38:27
 
 
 
CURRENT_TEST: encryption.encrypt_and_grep
 
--- /usr/share/mysql-test/suite/encryption/r/encrypt_and_grep.result	2020-07-01 10:02:48.000000000 +0300
 
+++ /dev/shm/var/4/log/encrypt_and_grep.reject	2020-07-01 12:38:27.516151145 +0300
 
@@ -10,13 +10,10 @@
 
 # Wait max 10 min for key encryption threads to encrypt all spaces
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0;
 
 NAME
 
+innodb_system
 
 test/t3
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION <> 0;
 
 NAME
 
-innodb_system
 
-mysql/innodb_index_stats
 
-mysql/innodb_table_stats
 
-mysql/transaction_registry
 
 test/t1
 
 test/t2
 
 # t1 yes on expecting NOT FOUND
 
@@ -31,12 +28,17 @@
 
 # Now turn off encryption and wait for threads to decrypt everything
 
 SET GLOBAL innodb_encrypt_tables = off;
 
 # Wait max 10 min for key encryption threads to decrypt all spaces
 
+Timeout in wait_condition.inc for SELECT COUNT(*) = 6 FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0 AND CURRENT_KEY_VERSION = 0;
 
+Id	User	Host	db	Command	Time	State	Info	Progress
 
+2	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+1	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
+3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
+5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
+8	root	localhost	test	Query	0	Init	show full processlist	0.000
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0;
 
 NAME
 
 innodb_system
 
-mysql/innodb_index_stats
 
-mysql/innodb_table_stats
 
-mysql/transaction_registry
 
 test/t2
 
 test/t3
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION <> 0;
 
 
 
mysqltest: Result length mismatch

10.5 http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-trusty-amd64/builds/17864/steps/mtr/logs/stdio

encryption.encrypt_and_grep 'cbc,innodb' w2 [ fail ]
 
        Test ended at 2020-07-06 10:59:40
 
 
 
CURRENT_TEST: encryption.encrypt_and_grep
 
--- /usr/local/mariadb-10.5.5-linux-x86_64/mysql-test/suite/encryption/r/encrypt_and_grep.result	2020-07-06 10:10:00.000000000 +0000
 
+++ /usr/local/mariadb-10.5.5-linux-x86_64/mysql-test/suite/encryption/r/encrypt_and_grep.reject	2020-07-06 10:59:40.282586978 +0000
 
@@ -10,13 +10,10 @@
 
 # Wait max 10 min for key encryption threads to encrypt all spaces
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION = 0;
 
 NAME
 
+innodb_system
 
 test/t3
 
 SELECT NAME FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION WHERE MIN_KEY_VERSION <> 0;
 
 NAME
 
-innodb_system
 
-mysql/innodb_index_stats
 
-mysql/innodb_table_stats
 
-mysql/transaction_registry
 
 test/t1
 
 test/t2
 
 # t1 yes on expecting NOT FOUND
 
 
 
mysqltest: Result length mismatch

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