[MDEV-13765] encryption.encrypt_and_grep failed in buildbot with wrong result (sporadic) - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.4.13, 10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5
Fix Version/s: 10.4.34, 10.5.25, 10.11.8, 10.6.18, 11.0.6, 11.1.5, 11.2.4
Component/s: Tests
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

Attachments

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2017-09-08 10:39 - edited

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.

Elena Stepanova added a comment - 2017-09-08 10:39 - edited 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.

Michael Widenius added a comment - 2020-01-30 09:19

Got a similar failure on this today in 10.4.13

Michael Widenius added a comment - 2020-01-30 09:19 Got a similar failure on this today in 10.4.13

Alice Sherepa added a comment - 2020-07-06 13:32

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

Alice Sherepa added a comment - 2020-07-06 13:32 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

Thirunarayanan Balathandayuthapani added a comment - 2024-03-06 06:39

https://github.com/MariaDB/server/pull/3108

Thirunarayanan Balathandayuthapani added a comment - 2024-03-06 06:39 https://github.com/MariaDB/server/pull/3108

Marko Mäkelä added a comment - 2024-03-06 07:31

Thank you, a very simple fix to the test.

Marko Mäkelä added a comment - 2024-03-06 07:31 Thank you, a very simple fix to the test.

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Alice Sherepa

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2017-09-08 07:50

Updated:: 2024-03-06 08:33

Resolved:: 2024-03-06 08:33

Git Integration

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

MariaDB Server