Tests innodb.log_encrypt_3_mk innodb.innodb-wl6742 innodb.innodb-wl6045-1 innodb.log_encrypt_3_rk fail

General

Escalation

General

Escalation

Description

I see the following test failures with current Percona Server 5.7 from GitHub:

[openxs@fc23 percona-server]$ git branch
* 5.7
[openxs@fc23 percona-server]$ git log -1
commit 6062aeb2a67aef7e2f8fb91cdb972aeee39a82b7 (HEAD -> 5.7, origin/HEAD, origin/5.7)
Merge: 49f3b278812 bb46036fb36
Author: Przemyslaw Skibinski <przemyslaw.skibinski@percona.com>
Date:   Thu Dec 6 10:26:20 2018 +0100

    Merge pull request #2752 from inikep/5.7-percona_bug1289599

    PS-5100: percona_bug1289599 fails if USER is not defined (5.7)
[openxs@fc23 percona-server]$

on up to date Fedora 27 box:

Failing test(s): innodb.log_encrypt_3_mk innodb.innodb-wl6742 innodb.innodb-wl6045-1 innodb.log_encrypt_3_rk

For example:

[openxs@fc23 mysql-test]$ ./mtr innodb.innodb-wl6742
Logging: ./mtr  innodb.innodb-wl6742
2018-12-07T11:14:33.949639Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2018-12-07T11:14:33.949736Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
MySQL Version 5.7.24
Checking supported features...
 - SSL connections supported
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/dbs/p5.7/mysql-test/var'...
Installing system database...
...
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
[100%] innodb.innodb-wl6742                     [ fail ]
        Test ended at 2018-12-07 13:15:02

CURRENT_TEST: innodb.innodb-wl6742
--- /home/openxs/dbs/p5.7/mysql-test/suite/innodb/r/innodb-wl6742.result       2016-02-25 12:44:41.000000000 +0300
+++ /home/openxs/dbs/p5.7/mysql-test/var/log/innodb-wl6742.reject       2018-12-07 14:15:02.126726907 +0300
@@ -1291,17 +1291,17 @@
 Note   1003    /* select#1 */ select `test`.`t1`.`c1` AS `c1`,`test`.`t1`.`c2` AS `c2`,`test`.`t1`.`c3` AS `c3`,`test`.`t1`.`c4` AS `c4` from `test`.`t1`
 EXPLAIN SELECT COUNT(*) FROM t1;
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      SIMPLE  NULL    NULL    NULL    NULL    NULL    NULL    NULL    NULL   NULL     Select tables optimized away
+1      SIMPLE  t1      NULL    index   NULL    k2      5       NULL    9      100.00   Using index
 Warnings:
 Note   1003    /* select#1 */ select count(0) AS `COUNT(*)` from `test`.`t1`
 EXPLAIN SELECT COUNT(*) FROM t3;
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      SIMPLE  NULL    NULL    NULL    NULL    NULL    NULL    NULL    NULL   NULL     Select tables optimized away
+1      SIMPLE  t3      p0,p1,p2,p3     index   NULL    k2      5       NULL   9100.00  Using index
 Warnings:
 Note   1003    /* select#1 */ select count(0) AS `COUNT(*)` from `test`.`t3`
 EXPLAIN SELECT COUNT(c1) FROM t1;
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      SIMPLE  NULL    NULL    NULL    NULL    NULL    NULL    NULL    NULL   NULL     Select tables optimized away
+1      SIMPLE  t1      NULL    index   NULL    k2      5       NULL    9      100.00   Using index
 Warnings:
 Note   1003    /* select#1 */ select count(`test`.`t1`.`c1`) AS `COUNT(c1)` from `test`.`t1`
 EXPLAIN SELECT COUNT(c2) FROM t1;
@@ -1336,26 +1336,26 @@
 Note   1003    /* select#1 */ select avg(`test`.`t3`.`c1`) AS `AVG(c1)`,max(`test`.`t3`.`c1`) AS `MAX(c1)`,min(`test`.`t3`.`c2`) AS `MIN(c2)`,avg(`test`.`t3`.`c3`) AS `AVG(c3)`,sum(`test`.`t3`.`c4`) AS `SUM(c4)` from `test`.`t3`
 EXPLAIN SELECT c1, c2 FROM t1 WHERE c1 > ((SELECT COUNT(*) FROM t1) / 2);
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      PRIMARY t1      NULL    index   PRIMARY k2      5       NULL    #      100.00   Using where; Using index
-2      SUBQUERY        NULL    NULL    NULL    NULL    NULL    NULL    NULL   #NULL    Select tables optimized away
+1      PRIMARY t1      NULL    range   PRIMARY PRIMARY 4       NULL    #      100.00   Using where
+2      SUBQUERY        t1      NULL    index   NULL    k2      5       NULL   #100.00  Using index
 Warnings:
 Note   1003    /* select#1 */ select `test`.`t1`.`c1` AS `c1`,`test`.`t1`.`c2` AS `c2` from `test`.`t1` where (`test`.`t1`.`c1` > <cache>(((/* select#2 */ select count(0) from `test`.`t1`) / 2)))
 EXPLAIN SELECT c1, c2 FROM t1 WHERE c1 > ((SELECT COUNT(*) FROM t3) / 2);
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      PRIMARY t1      NULL    index   PRIMARY k2      5       NULL    #      100.00   Using where; Using index
-2      SUBQUERY        NULL    NULL    NULL    NULL    NULL    NULL    NULL   #NULL    Select tables optimized away
+1      PRIMARY t1      NULL    range   PRIMARY PRIMARY 4       NULL    #      100.00   Using where
+2      SUBQUERY        t3      p0,p1,p2,p3     index   NULL    k2      5      NULL     #       100.00  Using index
 Warnings:
 Note   1003    /* select#1 */ select `test`.`t1`.`c1` AS `c1`,`test`.`t1`.`c2` AS `c2` from `test`.`t1` where (`test`.`t1`.`c1` > <cache>(((/* select#2 */ select count(0) from `test`.`t3`) / 2)))
 EXPLAIN SELECT COUNT(c2) FROM t1 WHERE c1 > ((SELECT COUNT(*) FROM t1) / 2);
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      PRIMARY t1      NULL    index   PRIMARY k2      5       NULL    #      100.00   Using where; Using index
-2      SUBQUERY        NULL    NULL    NULL    NULL    NULL    NULL    NULL   #NULL    Select tables optimized away
+1      PRIMARY t1      NULL    range   PRIMARY PRIMARY 4       NULL    #      100.00   Using where
+2      SUBQUERY        t1      NULL    index   NULL    k2      5       NULL   #100.00  Using index
 Warnings:
 Note   1003    /* select#1 */ select count(`test`.`t1`.`c2`) AS `COUNT(c2)` from `test`.`t1` where (`test`.`t1`.`c1` > <cache>(((/* select#2 */ select count(0) from `test`.`t1`) / 2)))
 EXPLAIN SELECT COUNT(c2) FROM t1 WHERE c1 > ((SELECT COUNT(*) FROM t3) / 2);
 id     select_type     table   partitions      type    possible_keys   key    key_len  ref     rows    filtered        Extra
-1      PRIMARY t1      NULL    index   PRIMARY k2      5       NULL    #      100.00   Using where; Using index
-2      SUBQUERY        NULL    NULL    NULL    NULL    NULL    NULL    NULL   #NULL    Select tables optimized away
+1      PRIMARY t1      NULL    range   PRIMARY PRIMARY 4       NULL    #      100.00   Using where
+2      SUBQUERY        t3      p0,p1,p2,p3     index   NULL    k2      5      NULL     #       100.00  Using index
 Warnings:
 Note   1003    /* select#1 */ select count(`test`.`t1`.`c2`) AS `COUNT(c2)` from `test`.`t1` where (`test`.`t1`.`c1` > <cache>(((/* select#2 */ select count(0) from `test`.`t3`) / 2)))
 EXPLAIN SELECT COUNT(*) FROM t1 WHERE c1 > (SELECT AVG(c1) FROM t1);

mysqltest: Result content mismatch

safe_process[25537]: Child process: 25538, exit: 1



Server [mysqld.1 - pid: 25508, winpid: 25508] log:
Server log from this test:
----------SERVER LOG START-----------
2018-12-07T11:14:49.058111Z 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2018-12-07T11:14:49.058183Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2018-12-07T11:14:49.230869Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-07T11:14:49.232971Z 0 [Warning] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2018-12-07T11:14:49.233027Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2018-12-07T11:14:49.233098Z 0 [Note] /home/openxs/dbs/p5.7/bin/mysqld (mysqld 5.7.24-26-log) starting as process 25509 ...
2018-12-07T11:14:49.237189Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-12-07T11:14:49.237218Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-07T11:14:49.237228Z 0 [Note] InnoDB: Uses event mutexes
2018-12-07T11:14:49.237237Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-12-07T11:14:49.237246Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-07T11:14:49.237255Z 0 [Note] InnoDB: Using Linux native AIO
2018-12-07T11:14:49.237601Z 0 [Note] InnoDB: Number of pools: 1
2018-12-07T11:14:49.237740Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2018-12-07T11:14:49.239697Z 0 [Note] InnoDB: Initializing buffer pool, total size = 24M, instances = 1, chunk size = 24M
2018-12-07T11:14:49.241391Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-07T11:14:49.242460Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-12-07T11:14:49.254634Z 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /home/openxs/dbs/p5.7/mysql-test/var/mysqld.1/data/xb_doublewrite
2018-12-07T11:14:49.255703Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-07T11:14:49.495456Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /home/openxs/dbs/p5.7/mysql-test/var/mysqld.1/data/xb_doublewrite, size 3932160 bytes
2018-12-07T11:14:49.502953Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-07T11:14:49.503103Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-07T11:14:49.745882Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-07T11:14:49.747176Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-12-07T11:14:49.747200Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-12-07T11:14:49.747894Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.24-26 started; log sequence number 1356216
2018-12-07T11:14:49.748070Z 0 [Note] InnoDB: Loading buffer pool(s) from /home/openxs/dbs/p5.7/mysql-test/var/mysqld.1/data/ib_buffer_pool
2018-12-07T11:14:49.748515Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-12-07T11:14:49.751139Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181207 14:14:49
2018-12-07T11:14:49.751168Z 0 [Warning] unknown variable 'loose-mysqlx-port=13009'
2018-12-07T11:14:49.751182Z 0 [Warning] unknown variable 'loose-mysqlx-socket=/home/openxs/dbs/p5.7/mysql-test/var/tmp/mysqlx.1.sock'
2018-12-07T11:14:49.751191Z 0 [Warning] unknown variable 'loose-sha256_password_auto_generate_rsa_keys=0'
2018-12-07T11:14:49.751199Z 0 [Warning] unknown variable 'loose-debug-sync-timeout=600'
2018-12-07T11:14:49.751876Z 0 [Note] Salting uuid generator variables, current_pid: 25509, server_start_time: 1544181289, bytes_sent: 0,
2018-12-07T11:14:49.752020Z 0 [Note] Generated uuid: '4ff31a1f-fa11-11e8-9c19-485b3952834f', server_start_time: 7180145182456330702, bytes_sent: 40206128
2018-12-07T11:14:49.752045Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 4ff31a1f-fa11-11e8-9c19-485b3952834f.
2018-12-07T11:14:49.780704Z 0 [Warning] CA certificate /home/openxs/dbs/p5.7/mysql-test/std_data/cacert.pem is self signed.
2018-12-07T11:14:49.783069Z 0 [Note] Server hostname (bind-address): '*'; port: 13001
2018-12-07T11:14:49.783135Z 0 [Note] IPv6 is available.
2018-12-07T11:14:49.783147Z 0 [Note]   - '::' resolves to '::';
2018-12-07T11:14:49.783184Z 0 [Note] Server socket created on IP: '::'.
2018-12-07T11:14:49.810646Z 0 [Note] Failed to start slave threads for channel ''
2018-12-07T11:14:49.820039Z 0 [Note] Event Scheduler: Loaded 0 events
2018-12-07T11:14:49.820293Z 0 [Note] /home/openxs/dbs/p5.7/bin/mysqld: ready for connections.
Version: '5.7.24-26-log'  socket: '/home/openxs/dbs/p5.7/mysql-test/var/tmp/mysqld.1.sock'  port: 13001  MySQL Community Server (GPL)
2018-12-07T11:14:58.801110Z 3 [ERROR] Got error 155 when reading table './test/t4'
----------SERVER LOG END-------------


 - the logfile can be found in '/home/openxs/dbs/p5.7/mysql-test/var/log/innodb.innodb-wl6742/innodb-wl6742.log'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 29 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): innodb.innodb-wl6742

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

Environment

[openxs@fc23 ~]$ uname -a
Linux fc23 4.18.19-100.fc27.x86_64 #1 SMP Wed Nov 14 22:04:34 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Smart Checklist

Activity

Show:

Lenz Grimmer January 31, 2023 at 12:03 PM

Resolving as "cannot reproduce" - this issue has not been observed as part of our regular 5.7 QA test runs. Please re-open, if it's still reproducible for you.

Lalit Choudhary December 11, 2018 at 11:15 AM

Thank you for the update @Valeriy Kravchuk.

validated as described

Test:

OS:

DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.5 LTS"

cmake . -DWITH_SSL=system -DCMAKE_BUILD_TYPE=Debug -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DDEBUG_EXTNAME=OFF -DWITH_EMBEDDED_SERVER=0 -DENABLE_DOWNLOADS=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp/boost_176319 -DENABLED_LOCAL_INFILE=1 -DENABLE_DTRACE=0 -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 -DWITH_ZLIB=system -DWITH_ROCKSDB=1 -DWITH_PAM=ON

$ ./mysql-test-run innodb.log_encrypt_3_mk
Logging: ./mysql-test-run innodb.log_encrypt_3_mk
MySQL Version 5.7.23
Checking supported features...
- SSL connections supported
- binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory '/qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var'...
Installing system database...
Using parallel: 1
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
innodb.log_encrypt_3_mk [ fail ] Found warnings/errors in server log file!
Test ended at 2018-12-11 05:51:46
line
2018-12-11T10:51:11.619960Z 0 [ERROR] InnoDB: Encryption can't find master key, please check the keyring plugin is loaded.
2018-12-11T10:51:11.619989Z 0 [ERROR] InnoDB: Can't set redo log tablespace to be encrypted.
^ Found warnings in /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/log/mysqld.1.err
ok
Server [mysqld.1 - pid: 20847, winpid: 20847] log:
Server log from this test:
----------SERVER LOG START-----------
2018-12-11T10:51:10.233646Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-11T10:51:10.234554Z 0 [Warning] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2018-12-11T10:51:10.234563Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2018-12-11T10:51:10.234586Z 0 [Note] /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/bin/mysqld (mysqld 5.7.23-24-debug-log) starting as process 20692 ...
2018-12-11T10:51:10.238169Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-12-11T10:51:10.238185Z 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-11T10:51:10.238190Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-11T10:51:10.238194Z 0 [Note] InnoDB: Uses event mutexes
2018-12-11T10:51:10.238197Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-12-11T10:51:10.238201Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-12-11T10:51:10.238205Z 0 [Note] InnoDB: Using Linux native AIO
2018-12-11T10:51:10.238498Z 0 [Note] InnoDB: Number of pools: 1
2018-12-11T10:51:10.238584Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-12-11T10:51:10.239542Z 0 [Note] InnoDB: Initializing buffer pool, total size = 24M, instances = 1, chunk size = 24M
2018-12-11T10:51:10.245874Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-11T10:51:10.246378Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-12-11T10:51:10.257236Z 0 [Note] InnoDB: Crash recovery did not find the parallel doublewrite buffer at /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data/xb_doublewrite
2018-12-11T10:51:10.258743Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-12-11T10:51:10.388374Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data/xb_doublewrite, size 3932160 bytes
2018-12-11T10:51:10.419277Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-11T10:51:10.419344Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-11T10:51:10.555228Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-11T10:51:10.561705Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-12-11T10:51:10.561718Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-12-11T10:51:10.562769Z 0 [Note] InnoDB: Waiting for purge to start
2018-12-11T10:51:10.613046Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.23-24 started; log sequence number 1358041
2018-12-11T10:51:10.613212Z 0 [Note] InnoDB: Loading buffer pool(s) from /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data/ib_buffer_pool
2018-12-11T10:51:10.613557Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-12-11T10:51:10.615686Z 0 [Warning] unknown variable 'loose-mysqlx-port=13009'
2018-12-11T10:51:10.615696Z 0 [Warning] unknown variable 'loose-mysqlx-socket=/qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/tmp/mysqlx.1.sock'
2018-12-11T10:51:10.616242Z 0 [Note] Salting uuid generator variables, current_pid: 20692, server_start_time: 1544525470, bytes_sent: 0,
2018-12-11T10:51:10.616284Z 0 [Note] Generated uuid: 'abbb2c7c-fd32-11e8-95b4-002590e9b7a2', server_start_time: 5824280219641440114, bytes_sent: 73255680
2018-12-11T10:51:10.616314Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: abbb2c7c-fd32-11e8-95b4-002590e9b7a2.
2018-12-11T10:51:10.632317Z 0 [Note] InnoDB: Buffer pool(s) load completed at 181211 13:51:10
2018-12-11T10:51:10.657845Z 0 [Note] Skipping generation of SSL certificates as options related to SSL are specified.
2018-12-11T10:51:10.658368Z 0 [Warning] CA certificate /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/std_data/cacert.pem is self signed.
2018-12-11T10:51:10.658399Z 0 [Note] Skipping generation of RSA key pair as --sha256_password_auto_generate_rsa_keys is set to OFF.
2018-12-11T10:51:10.658414Z 0 [Note] RSA private key file not found: /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data//private_key.pem. Some authentication plugins will not work.
2018-12-11T10:51:10.658421Z 0 [Note] RSA public key file not found: /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data//public_key.pem. Some authentication plugins will not work.
2018-12-11T10:51:10.658429Z 0 [Note] Server hostname (bind-address): '*'; port: 13001
2018-12-11T10:51:10.658454Z 0 [Note] IPv6 is available.
2018-12-11T10:51:10.659037Z 0 [Note] - '::' resolves to '::';
2018-12-11T10:51:10.659079Z 0 [Note] Server socket created on IP: '::'.
2018-12-11T10:51:10.701123Z 0 [Note] Event Scheduler: Loaded 0 events
2018-12-11T10:51:10.701410Z 0 [Note] /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.7.23-24-debug-log' socket: '/qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/tmp/mysqld.1.sock' port: 13001 MySQL Community Server (GPL)
2018-12-11T10:51:11.619960Z 0 [ERROR] InnoDB: Encryption can't find master key, please check the keyring plugin is loaded.
2018-12-11T10:51:11.619989Z 0 [ERROR] InnoDB: Can't set redo log tablespace to be encrypted.
2018-12-11T10:51:12.395466Z 0 [Note] Giving 0 client threads a chance to die gracefully
2018-12-11T10:51:12.395480Z 0 [Note] Shutting down slave threads
2018-12-11T10:51:12.395487Z 0 [Note] Forcefully disconnecting 0 remaining clients
2018-12-11T10:51:12.395495Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2018-12-11T10:51:12.395574Z 0 [Note] Binlog end
2018-12-11T10:51:12.397688Z 0 [Note] Shutting down plugin 'ngram'
2018-12-11T10:51:12.397699Z 0 [Note] Shutting down plugin 'ARCHIVE'
2018-12-11T10:51:12.397703Z 0 [Note] Shutting down plugin 'partition'
2018-12-11T10:51:12.397706Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2018-12-11T10:51:12.397711Z 0 [Note] Shutting down plugin 'MEMORY'
2018-12-11T10:51:12.397715Z 0 [Note] Shutting down plugin 'MRG_MYISAM'
2018-12-11T10:51:12.397719Z 0 [Note] Shutting down plugin 'CSV'
2018-12-11T10:51:12.397724Z 0 [Note] Shutting down plugin 'INNODB_TABLESPACES_SCRUBBING'
2018-12-11T10:51:12.397728Z 0 [Note] Shutting down plugin 'INNODB_TABLESPACES_ENCRYPTION'
2018-12-11T10:51:12.397731Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2018-12-11T10:51:12.397734Z 0 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
2018-12-11T10:51:12.397737Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2018-12-11T10:51:12.397740Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2018-12-11T10:51:12.397743Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2018-12-11T10:51:12.397747Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2018-12-11T10:51:12.397750Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2018-12-11T10:51:12.397753Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2018-12-11T10:51:12.397756Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2018-12-11T10:51:12.397759Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2018-12-11T10:51:12.397763Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2018-12-11T10:51:12.397766Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2018-12-11T10:51:12.397769Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2018-12-11T10:51:12.397772Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2018-12-11T10:51:12.397775Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2018-12-11T10:51:12.397778Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2018-12-11T10:51:12.397782Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2018-12-11T10:51:12.397790Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
2018-12-11T10:51:12.397793Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2018-12-11T10:51:12.397796Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2018-12-11T10:51:12.397800Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2018-12-11T10:51:12.397803Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2018-12-11T10:51:12.397806Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2018-12-11T10:51:12.397809Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2018-12-11T10:51:12.397813Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2018-12-11T10:51:12.397816Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2018-12-11T10:51:12.397819Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2018-12-11T10:51:12.397822Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2018-12-11T10:51:12.397825Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2018-12-11T10:51:12.397829Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2018-12-11T10:51:12.397832Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2018-12-11T10:51:12.397835Z 0 [Note] Shutting down plugin 'XTRADB_ZIP_DICT_COLS'
2018-12-11T10:51:12.397838Z 0 [Note] Shutting down plugin 'XTRADB_ZIP_DICT'
2018-12-11T10:51:12.397842Z 0 [Note] Shutting down plugin 'XTRADB_RSEG'
2018-12-11T10:51:12.397845Z 0 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2018-12-11T10:51:12.397848Z 0 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2018-12-11T10:51:12.397852Z 0 [Note] Shutting down plugin 'MyISAM'
2018-12-11T10:51:12.397862Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2018-12-11T10:51:12.397917Z 0 [Note] Shutting down plugin 'sha256_password'
2018-12-11T10:51:12.397920Z 0 [Note] Shutting down plugin 'mysql_native_password'
2018-12-11T10:51:12.398008Z 0 [Note] Shutting down plugin 'binlog'
2018-12-11T10:51:12.398018Z 0 [Note] Shutting down plugin 'InnoDB'
2018-12-11T10:51:12.398083Z 0 [Note] InnoDB: FTS optimize thread exiting.
2018-12-11T10:51:12.398188Z 0 [Note] InnoDB: Starting shutdown...
2018-12-11T10:51:12.498373Z 0 [Note] InnoDB: Dumping buffer pool(s) to /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/mysql-test/var/mysqld.1/data/ib_buffer_pool
2018-12-11T10:51:12.498589Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 181211 13:51:12
2018-12-11T10:51:12.798620Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-12-11T10:51:14.443862Z 0 [Note] InnoDB: Shutdown completed; log sequence number 2994054
2018-12-11T10:51:14.445302Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-11T10:51:14.499197Z 0 [Note] Debug sync points hit: 15466
2018-12-11T10:51:14.499212Z 0 [Note] Debug sync points executed: 0
2018-12-11T10:51:14.499215Z 0 [Note] Debug sync points max active per thread: 0
2018-12-11T10:51:14.499264Z 0 [Note] /qa/PS311018-percona-server-5.7.23-24-linux-x86_64-debug/bin/mysqld: Shutdown complete
2018-12-11T10:51:15.721593Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-12-11T10:51:1...

Valeriy Kravchuk December 8, 2018 at 2:31 PM

Indeed, those two tests could be leftovers from some older version. But I was able to reproduce other two failures also on Ubuntu 14.04:

openxs@ao756:~/git/percona-server/mysql-test$ ./mtr innodb.log_encrypt_3_mk
Logging: ./mtr  innodb.log_encrypt_3_mk
2018-12-08T14:16:45.938520Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2018-12-08T14:16:45.938669Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
MySQL Version 5.7.24
Checking supported features...
 - SSL connections supported
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/openxs/git/percona-server/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
[100%] innodb.log_encrypt_3_mk                  [ fail ]  Found warnings/errors
in server log file!
        Test ended at 2018-12-08 16:19:53
line
2018-12-08T14:18:59.002648Z 0 [ERROR] InnoDB: Encryption can't find master key, please check the keyring plugin is loaded.
2018-12-08T14:18:59.002700Z 0 [ERROR] InnoDB: Can't set redo log tablespace to be encrypted.
^ Found warnings in /home/openxs/git/percona-server/mysql-test/var/log/mysqld.1.err
ok



Server [mysqld.1 - pid: 30313, winpid: 30313] log:
Server log from this test:
----------SERVER LOG START-----------
2018-12-08T14:18:57.116402Z 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2018-12-08T14:18:57.116635Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)

...

2018-12-08T14:19:50.760367Z 0 [Note] /home/openxs/git/percona-server/sql/mysqld:
 ready for connections.
Version: '5.7.24-26-log'  socket: '/home/openxs/git/percona-server/mysql-test/var/tmp/mysqld.1.sock'  port: 13001  MySQL Community Server (GPL)
2018-12-08T14:19:51.365216Z 2 [Note] Shutting down plugin 'keyring_file'
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
CREATE DATABASE tde_db;
USE tde_db;
SET GLOBAL innodb_redo_log_encrypt = MASTER_KEY;
SHOW WARNINGS;
Level   Code    Message
CREATE TABLE tde_db.t4 (a BIGINT PRIMARY KEY, b LONGBLOB) ENGINE=InnoDB;
INSERT INTO t4 (a, b) VALUES (1, REPEAT('a', 6*512*512));
SELECT a,LEFT(b,10) FROM tde_db.t4;
a       LEFT(b,10)
1       aaaaaaaaaa
# restart

...

SELECT @@global.innodb_redo_log_encrypt;
@@global.innodb_redo_log_encrypt
master_key
# In connection default
UNINSTALL PLUGIN keyring_file;
DROP TABLE tde_db.t1,tde_db.t2,tde_db.t3,tde_db.t4;


 - the logfile can be found in '/home/openxs/git/percona-server/mysql-test/var/log/innodb.log_encrypt_3_mk/log_encrypt_3_mk.log'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 79 seconds executing testcases
mysql-test-run: WARNING: Got errors/warnings while running tests, please examine
 '/home/openxs/git/percona-server/mysql-test/var/log/warnings' for details.

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): innodb.log_encrypt_3_mk

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

The following cmake command line was used:

cmake . -DCMAKE_BUILD_TYPE=RelWithDebInfo -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/p5.7 -DWITH_BOOST=/home/openxs/boost -DDOWNLOAD_BOOST=1

Versions in case of Ubuntu 14.04:

openxs@ao756:~/git/percona-server/mysql-test$ openssl version
OpenSSL 1.0.1f 6 Jan 2014
openxs@ao756:~/git/percona-server/mysql-test$ gcc --version
gcc (Ubuntu 4.8.4-2ubuntu1~14.04.4) 4.8.4
Copyright (C) 2013 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

openxs@ao756:~/git/percona-server/mysql-test$

Lalit Choudhary December 7, 2018 at 2:58 PM

Hi @Valeriy Kravchuk,

Thank you for the report.

Please share cmake command that using for source compilation. Also let us know if you are using any other special option(gcc, openssl version etc)

Tested on Ubuntu18, listed tests passing , Test not found: innodb.innodb-wl6742 innodb.innodb-wl6045-1

$ git log -1
commit 6062aeb2a67aef7e2f8fb91cdb972aeee39a82b7 (HEAD -> 5.7, origin/HEAD, origin/5.7)
Merge: 49f3b278812 bb46036fb36
Author: Przemyslaw Skibinski <przemyslaw.skibinski@percona.com>
Date: Thu Dec 6 10:26:20 2018 +0100
Merge pull request #2752 from inikep/5.7-percona_bug1289599
 
PS-5100: percona_bug1289599 fails if USER is not defined (5.7)

cmake . -DWITH_SSL=system -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=1 -DWITH_VALGRIND=1 -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DDEBUG_EXTNAME=OFF -DWITH_SSL=system -DWITH_INNODB_MEMCACHED=ON -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_EMBEDDED_SERVER=0 -DENABLE_DOWNLOADS=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/home/lalit/git/ -DENABLED_LOCAL_INFILE=1 -DENABLE_DTRACE=0 -DWITH_PERFSCHEMA_STORAGE_ENGINE=1 -DWITH_ZLIB=system -DWITH_ROCKSDB=1 -DWITH_PAM=ON

$ ./mtr innodb.log_encrypt_3_rk
Logging: ./mtr innodb.log_encrypt_3_rk
MySQL Version 5.7.24
Too long tmpdir path '/home/lalit/git/PS071218-percona-server-5.7.24-26-linux-x86_64-debug/mysql-test/var/tmp' creating a shorter one...
- using tmpdir: '/tmp/jhsbW5EAWW'
Checking supported features...
- SSL connections supported
- binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/lalit/git/PS071218-percona-server-5.7.24-26-linux-x86_64-debug/mysql-test/var'...
Installing system database...
Using parallel: 1
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
[100%] innodb.log_encrypt_3_rk [ pass ] 19991
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 19.991 of 30 seconds executing testcases
Completed: All 1 tests were successful.

Test not found: innodb.innodb-wl6742 innodb.innodb-wl6045-1

$ ./mtr innodb.innodb-wl6045-1
Logging: ./mtr innodb.innodb-wl6045-1
MySQL Version 5.7.24
Too long tmpdir path '/home/lalit/git/PS071218-percona-server-5.7.24-26-linux-x86_64-debug/mysql-test/var/tmp' creating a shorter one...
- using tmpdir: '/tmp/vQ3M0e7BLZ'
Checking supported features...
- SSL connections supported
- binaries are debug compiled
Collecting tests...
mysql-test-run: *** ERROR: Could not find 'innodb-wl6045-1' in 'innodb' suite

Cannot Reproduce

Details

Assignee

Unassigned

Reporter

Valeriy Kravchuk

Labels

cirotated-key-encryption

Affects versions

5.7.24-26

Priority

Medium

Smart Checklist

Created December 7, 2018 at 11:18 AM

Updated March 6, 2024 at 12:37 PM

Resolved January 31, 2023 at 12:03 PM

Configure

Tests innodb.log_encrypt_3_mk innodb.innodb-wl6742 innodb.innodb-wl6045-1 innodb.log_encrypt_3_rk fail

Description

Environment

Smart Checklist

Activity

Lenz Grimmer January 31, 2023 at 12:03 PM

Lalit Choudhary December 11, 2018 at 11:15 AM

Valeriy Kravchuk December 8, 2018 at 2:31 PM

Lalit Choudhary December 7, 2018 at 2:58 PM

Details

Assignee

Reporter

Labels

Affects versions

Priority

Smart Checklist

Flag notifications

Something's gone wrong