Skip to:

  1. Skip to Jira Navigation
  2. Skip to Side Navigation
  3. Skip to Main Content

Test encryption.innodb-redo-nokeys failed

Description

1 .I have compiled the MySQL Version 8.0.15 with following options (clang version 8.0.0 (Fedora 8.0.0-1.fc30)):

cmake ../percona-server -DCMAKE_CXX_COMPILER=clang++ -DCMAKE_C_COMPILER=clang -DWITH_BOOST=~/percona -DWITHOUT_TOKUDB_STORAGE_ENGINE=1 -DWITHOUT_ROCKSDB_STORAGE_ENGINE=1 -DCMAKE_BUILD_TYPE=Debug

2. Then I have started the test

./mysql-test-run.pl --do-test=innodb

3. I optained the following error:

encryption.innodb-redo-nokeys [ fail ]
"Unexpected checkpoint 1 after 18913760 (0:28=18913760,0:29=19058313)"
mysqltest: Result length mismatch
In included file ./include/no_checkpoint_end.inc: 37
included from /home/romz/percona/percona-server/mysql-test/suite/encryption/t/innodb-redo-nokeys.test: 49
safe_process[20832]: Child process: 20833, exit: 1

4. The log file is following

erver log from this test:
----------SERVER LOG START-----------
2019-06-16T06:59:27.719548Z 0 [Warning] [MY-010099] [Server] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2019-06-16T06:59:27.719570Z 0 [Warning] [MY-010101] [Server] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2019-06-16T06:59:27.719639Z 0 [Note] [MY-010949] [Server] Basedir set to /home/romz/percona/percona-server-build-clang-8.0/.
2019-06-16T06:59:27.719659Z 0 [System] [MY-010116] [Server] /home/romz/percona/percona-server-build-clang-8.0/runtime_output_directory/mysqld (mysqld 8.0.15-6-debug) starting as process 20786
2019-06-16T06:59:27.752782Z 0 [Note] [MY-012366] [InnoDB] Using Linux native AIO
2019-06-16T06:59:27.753425Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2019-06-16T06:59:27.758068Z 1 [Note] [MY-012932] [InnoDB] PUNCH HOLE support available
2019-06-16T06:59:27.758135Z 1 [Note] [MY-012937] [InnoDB] !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2019-06-16T06:59:27.758168Z 1 [Note] [MY-012943] [InnoDB] Mutexes and rw_locks use GCC atomic builtins
2019-06-16T06:59:27.758206Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2019-06-16T06:59:27.758243Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2019-06-16T06:59:27.758271Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.11
2019-06-16T06:59:27.759351Z 1 [Note] [MY-013251] [InnoDB] Number of pools: 1
2019-06-16T06:59:27.759715Z 1 [Note] [MY-012951] [InnoDB] Using CPU crc32 instructions
2019-06-16T06:59:27.761303Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'
2019-06-16T06:59:27.761515Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2019-06-16T06:59:27.763970Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 6 files.
2019-06-16T06:59:27.766245Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 24.000000M, instances = 1, chunk size =24.000000M
2019-06-16T06:59:27.780696Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2019-06-16T06:59:27.782846Z 0 [Note] [MY-011952] [InnoDB] If the mysqld execution user is authorized, page cleaner and LRU manager thread priority can be changed. See the man page of setpriority().
2019-06-16T06:59:27.795165Z 1 [Note] [MY-011825] [InnoDB] Crash recovery did not find the parallel doublewrite buffer at /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/xb_doublewrite
2019-06-16T06:59:27.859242Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 18913342, whereas checkpoint_lsn = 18913760
2019-06-16T06:59:28.072916Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2019-06-16T06:59:28.250156Z 1 [Note] [MY-011825] [InnoDB] Created parallel doublewrite buffer at /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/xb_doublewrite, size 3932160 bytes
2019-06-16T06:59:28.250329Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...
2019-06-16T06:59:28.250417Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2019-06-16T06:59:28.251589Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2019-06-16T06:59:28.252924Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2019-06-16T06:59:28.283941Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2019-06-16T06:59:28.418123Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2019-06-16T06:59:28.418276Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-06-16T06:59:28.980746Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2019-06-16T06:59:28.981531Z 1 [Note] [MY-011825] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2019-06-16T06:59:29.696671Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2019-06-16T06:59:29.698135Z 1 [Note] [MY-012976] [InnoDB] Percona XtraDB (http://www.percona.com) 8.0.15-6 started; log sequence number 18913760
2019-06-16T06:59:29.756334Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80014'.
2019-06-16T06:59:30.815643Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2019-06-16T06:59:30.824222Z 1 [Note] [MY-012356] [InnoDB] Validated 8/8 tablespaces
2019-06-16T06:59:30.826010Z 0 [Note] [MY-011946] [InnoDB] Loading buffer pool(s) from /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/ib_buffer_pool
2019-06-16T06:59:30.833716Z 0 [Note] [MY-011946] [InnoDB] Buffer pool(s) load completed at 190616 9:59:30
2019-06-16T06:59:31.154692Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80014'.
2019-06-16T06:59:33.112459Z 0 [Note] [MY-010902] [Server] Thread priority attribute setting in Resource Group SQL shall be ignored due to unsupported platform or insufficient privilege.
2019-06-16T06:59:33.179264Z 0 [Note] [MY-012487] [InnoDB] DDL log recovery : begin
2019-06-16T06:59:33.179465Z 0 [Note] [MY-012488] [InnoDB] DDL log recovery : end
2019-06-16T06:59:33.179747Z 0 [Note] [MY-012922] [InnoDB] Waiting for purge to start
2019-06-16T06:59:33.231213Z 0 [Warning] [MY-010075] [Server] 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: 4b7dacaf-9004-11e9-bd2a-f01faf664c0f.
2019-06-16T06:59:33.328347Z 0 [Note] [MY-010303] [Server] Skipping generation of SSL certificates as options related to SSL are specified.
2019-06-16T06:59:33.330851Z 0 [Warning] [MY-010068] [Server] CA certificate /home/romz/percona/percona-server/mysql-test/std_data/cacert.pem is self signed.
2019-06-16T06:59:33.330975Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --sha256_password_auto_generate_rsa_keys is set to OFF.
2019-06-16T06:59:33.331014Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --caching_sha2_password_auto_generate_rsa_keys is set to OFF.
2019-06-16T06:59:33.331093Z 0 [Warning] [MY-010284] [Server] RSA private key file not found: /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data//private_key.pem. Some authentication plugins will not work.
2019-06-16T06:59:33.331148Z 0 [Warning] [MY-010284] [Server] RSA public key file not found: /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data//public_key.pem. Some authentication plugins will not work.
2019-06-16T06:59:33.331438Z 0 [Note] [MY-010252] [Server] Server hostname (bind-address): '*'; port: 13001
2019-06-16T06:59:33.331561Z 0 [Note] [MY-010253] [Server] IPv6 is available.
2019-06-16T06:59:33.331607Z 0 [Note] [MY-010264] [Server] - '::' resolves to '::';
2019-06-16T06:59:33.331776Z 0 [Note] [MY-010251] [Server] Server socket created on IP: '::'.
2019-06-16T06:59:33.366944Z 0 [Warning] [MY-000067] [Server] unknown variable 'loose-mysqlx-ssl=DISABLED'.
2019-06-16T06:59:33.522254Z 0 [Note] [MY-011025] [Repl] Failed to start slave threads for channel ''.
2019-06-16T06:59:33.540110Z 4 [Note] [MY-010051] [Server] Event Scheduler: scheduler thread started with id 4
2019-06-16T06:59:33.541608Z 0 [System] [MY-010931] [Server] /home/romz/percona/percona-server-build-clang-8.0/runtime_output_directory/mysqld: ready for connections. Version: '8.0.15-6-debug' socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqld.1.sock' port: 13001 Source distribution.
2019-06-16T06:59:33.683653Z 0 [Note] [MY-011240] [Server] Plugin mysqlx reported: 'Using SSL configuration from MySQL Server'
2019-06-16T06:59:33.685005Z 0 [Note] [MY-011243] [Server] Plugin mysqlx reported: 'Using OpenSSL for TLS connections'
2019-06-16T06:59:33.685145Z 0 [Note] [MY-011332] [Server] Plugin mysqlx reported: 'IPv6 is available'
2019-06-16T06:59:33.708501Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. bind-address: '::' port: 13010'
2019-06-16T06:59:33.708561Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqlx.1.sock''
2019-06-16T06:59:33.708621Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqlx.1.sock' bind-address: '::' port: 13010
safe_process[20785]: Child process: 20786, killed by signal: 9
2019-06-16T06:59:41.970779Z 0 [Warning] [MY-010099] [Server] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2019-06-16T06:59:41.970801Z 0 [Warning] [MY-010101] [Server] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2019-06-16T06:59:41.970864Z 0 [Note] [MY-010949] [Server] Basedir set to /home/romz/percona/percona-server-build-clang-8.0/.
2019-06-16T06:59:41.970883Z 0 [System] [MY-010116] [Server] /home/romz/percona/percona-server-build-clang-8.0/runtime_output_directory/mysqld (mysqld 8.0.15-6-debug) starting as process 20840
2019-06-16T06:59:41.989346Z 0 [Note] [MY-012366] [InnoDB] Using Linux native AIO
2019-06-16T06:59:41.989940Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2019-06-16T06:59:41.995071Z 1 [Note] [MY-012932] [InnoDB] PUNCH HOLE support available
2019-06-16T06:59:41.995119Z 1 [Note] [MY-012937] [InnoDB] !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2019-06-16T06:59:41.995147Z 1 [Note] [MY-012943] [InnoDB] Mutexes and rw_locks use GCC atomic builtins
2019-06-16T06:59:41.995178Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2019-06-16T06:59:41.995206Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2019-06-16T06:59:41.995247Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.11
2019-06-16T06:59:41.996095Z 1 [Note] [MY-013251] [InnoDB] Number of pools: 1
2019-06-16T06:59:41.996408Z 1 [Note] [MY-012951] [InnoDB] Using CPU crc32 instructions
2019-06-16T06:59:41.997678Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'
2019-06-16T06:59:41.997847Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2019-06-16T06:59:41.999869Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 10 files.
2019-06-16T06:59:42.001843Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 24.000000M, instances = 1, chunk size =24.000000M
2019-06-16T06:59:42.021603Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2019-06-16T06:59:42.023165Z 0 [Note] [MY-011952] [InnoDB] If the mysqld execution user is authorized, page cleaner and LRU manager thread priority can be changed. See the man page of setpriority().
2019-06-16T06:59:42.035381Z 1 [Note] [MY-011825] [InnoDB] Recovering partial pages from the parallel doublewrite buffer at /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/xb_doublewrite
2019-06-16T06:59:42.130382Z 1 [Note] [MY-012560] [InnoDB] The log sequence number 18913760 in the system tablespace does not match the log sequence number 19058313 in the ib_logfiles!
2019-06-16T06:59:42.130403Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2019-06-16T06:59:42.130432Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2019-06-16T06:59:42.313988Z 1 [Note] [MY-011825] [InnoDB] Created parallel doublewrite buffer at /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/xb_doublewrite, size 3932160 bytes
2019-06-16T06:59:42.314389Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 19058256, whereas checkpoint_lsn = 19058313
2019-06-16T06:59:42.633583Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 189 redo log records ...
2019-06-16T06:59:42.656829Z 1 [Note] [MY-012533] [InnoDB] 10%
2019-06-16T06:59:42.656885Z 1 [Note] [MY-012533] [InnoDB] 20%
2019-06-16T06:59:42.661342Z 1 [Note] [MY-012533] [InnoDB] 30%
2019-06-16T06:59:42.664322Z 1 [Note] [MY-012533] [InnoDB] 40%
2019-06-16T06:59:42.666641Z 1 [Note] [MY-012533] [InnoDB] 50%
2019-06-16T06:59:42.667209Z 1 [Note] [MY-012533] [InnoDB] 60%
2019-06-16T06:59:42.667591Z 1 [Note] [MY-012533] [InnoDB] 70%
2019-06-16T06:59:42.669896Z 1 [Note] [MY-012533] [InnoDB] 80%
2019-06-16T06:59:42.672405Z 1 [Note] [MY-012533] [InnoDB] 90%
2019-06-16T06:59:42.672449Z 1 [Note] [MY-012533] [InnoDB] 100%
2019-06-16T06:59:43.185105Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2019-06-16T06:59:43.228387Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 22553992
2019-06-16T06:59:43.239229Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2019-06-16T06:59:43.240019Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 163 redo log records ...
2019-06-16T06:59:43.251988Z 1 [Note] [MY-012533] [InnoDB] 10%
2019-06-16T06:59:43.254935Z 1 [Note] [MY-012533] [InnoDB] 20%
2019-06-16T06:59:43.254995Z 1 [Note] [MY-012533] [InnoDB] 30%
2019-06-16T06:59:43.255052Z 1 [Note] [MY-012533] [InnoDB] 40%
2019-06-16T06:59:43.257192Z 1 [Note] [MY-012533] [InnoDB] 50%
2019-06-16T06:59:43.265756Z 1 [Note] [MY-012533] [InnoDB] 60%
2019-06-16T06:59:43.265831Z 1 [Note] [MY-012533] [InnoDB] 70%
2019-06-16T06:59:43.268121Z 1 [Note] [MY-012533] [InnoDB] 80%
2019-06-16T06:59:43.268173Z 1 [Note] [MY-012533] [InnoDB] 90%
2019-06-16T06:59:43.269055Z 1 [Note] [MY-012533] [InnoDB] 100%
2019-06-16T06:59:43.771352Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2019-06-16T06:59:43.771492Z 1 [Note] [MY-013022] [InnoDB] Last MySQL binlog file position 0 3377582, file name binlog.000001
2019-06-16T06:59:43.889971Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2019-06-16T06:59:43.890264Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2019-06-16T06:59:43.915118Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2019-06-16T06:59:44.054734Z 1 [Note] [MY-013029] [InnoDB] Transaction 1590 was in the XA prepared state.
2019-06-16T06:59:44.054896Z 1 [Note] [MY-013031] [InnoDB] Transaction 1590 was in the XA prepared state.
2019-06-16T06:59:44.055241Z 1 [Note] [MY-013023] [InnoDB] 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2019-06-16T06:59:44.055269Z 1 [Note] [MY-013024] [InnoDB] Trx id counter is 2048
2019-06-16T06:59:44.057335Z 1 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"
2019-06-16T06:59:44.057359Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables
2019-06-16T06:59:44.057500Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-06-16T06:59:44.610746Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.
2019-06-16T06:59:44.612398Z 1 [Note] [MY-011825] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'
2019-06-16T06:59:45.102240Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2019-06-16T06:59:45.102983Z 1 [Note] [MY-012976] [InnoDB] Percona XtraDB (http://www.percona.com) 8.0.15-6 started; log sequence number 22553992
2019-06-16T06:59:45.156322Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80014'.
2019-06-16T06:59:46.185121Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2019-06-16T06:59:46.196107Z 1 [Note] [MY-012356] [InnoDB] Validated 12/12 tablespaces
2019-06-16T06:59:46.245640Z 0 [Note] [MY-011946] [InnoDB] Loading buffer pool(s) from /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data/ib_buffer_pool
2019-06-16T06:59:46.257775Z 0 [Note] [MY-011946] [InnoDB] Buffer pool(s) load completed at 190616 9:59:46
2019-06-16T06:59:46.449305Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80014'.
2019-06-16T06:59:46.676102Z 0 [Note] [MY-010902] [Server] Thread priority attribute setting in Resource Group SQL shall be ignored due to unsupported platform or insufficient privilege.
2019-06-16T06:59:46.734652Z 0 [Note] [MY-010855] [Server] Recovering after a crash using binlog
2019-06-16T06:59:46.771685Z 0 [System] [MY-010229] [Server] Starting crash recovery...
2019-06-16T06:59:46.781023Z 0 [Note] [MY-013032] [InnoDB] Starting recovery for XA transactions...
2019-06-16T06:59:46.781048Z 0 [Note] [MY-013033] [InnoDB] Transaction 1590 in prepared state after recovery
2019-06-16T06:59:46.781067Z 0 [Note] [MY-013034] [InnoDB] Transaction contains changes to 84 rows
2019-06-16T06:59:46.781086Z 0 [Note] [MY-013035] [InnoDB] 1 transactions in prepared state after recovery
2019-06-16T06:59:46.781119Z 0 [Note] [MY-010224] [Server] Found 1 prepared transaction(s) in InnoDB
2019-06-16T06:59:46.781159Z 0 [Note] [MY-010227] [Server] commit xid 'MySQLXid\1\0\0\0\0\0\0\0V\0\0\0\0\0\0\0'
2019-06-16T06:59:46.808742Z 0 [System] [MY-010232] [Server] Crash recovery finished.
2019-06-16T06:59:46.828089Z 0 [Note] [MY-012487] [InnoDB] DDL log recovery : begin
2019-06-16T06:59:46.828273Z 0 [Note] [MY-012488] [InnoDB] DDL log recovery : end
2019-06-16T06:59:46.834275Z 0 [Note] [MY-012922] [InnoDB] Waiting for purge to start
2019-06-16T06:59:47.018816Z 0 [Note] [MY-010303] [Server] Skipping generation of SSL certificates as options related to SSL are specified.
2019-06-16T06:59:47.022599Z 0 [Warning] [MY-010068] [Server] CA certificate /home/romz/percona/percona-server/mysql-test/std_data/cacert.pem is self signed.
2019-06-16T06:59:47.022816Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --sha256_password_auto_generate_rsa_keys is set to OFF.
2019-06-16T06:59:47.022880Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --caching_sha2_password_auto_generate_rsa_keys is set to OFF.
2019-06-16T06:59:47.022976Z 0 [Warning] [MY-010284] [Server] RSA private key file not found: /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data//private_key.pem. Some authentication plugins will not work.
2019-06-16T06:59:47.023055Z 0 [Warning] [MY-010284] [Server] RSA public key file not found: /home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/mysqld.1/data//public_key.pem. Some authentication plugins will not work.
2019-06-16T06:59:47.023547Z 0 [Note] [MY-010252] [Server] Server hostname (bind-address): '*'; port: 13001
2019-06-16T06:59:47.023699Z 0 [Note] [MY-010253] [Server] IPv6 is available.
2019-06-16T06:59:47.023773Z 0 [Note] [MY-010264] [Server] - '::' resolves to '::';
2019-06-16T06:59:47.023867Z 0 [Note] [MY-010251] [Server] Server socket created on IP: '::'.
2019-06-16T06:59:47.066179Z 0 [Warning] [MY-000067] [Server] unknown variable 'loose-mysqlx-ssl=DISABLED'.
2019-06-16T06:59:47.209960Z 0 [Note] [MY-011025] [Repl] Failed to start slave threads for channel ''.
2019-06-16T06:59:47.228365Z 4 [Note] [MY-010051] [Server] Event Scheduler: scheduler thread started with id 4
2019-06-16T06:59:47.230198Z 0 [System] [MY-010931] [Server] /home/romz/percona/percona-server-build-clang-8.0/runtime_output_directory/mysqld: ready for connections. Version: '8.0.15-6-debug' socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqld.1.sock' port: 13001 Source distribution.
2019-06-16T06:59:47.474010Z 0 [Note] [MY-011240] [Server] Plugin mysqlx reported: 'Using SSL configuration from MySQL Server'
2019-06-16T06:59:47.476195Z 0 [Note] [MY-011243] [Server] Plugin mysqlx reported: 'Using OpenSSL for TLS connections'
2019-06-16T06:59:47.476458Z 0 [Note] [MY-011332] [Server] Plugin mysqlx reported: 'IPv6 is available'
2019-06-16T06:59:47.504302Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. bind-address: '::' port: 13010'
2019-06-16T06:59:47.504378Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqlx.1.sock''
2019-06-16T06:59:47.504528Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/home/romz/percona/percona-server-build-clang-8.0/mysql-test/var/tmp/mysqlx.1.sock' bind-address: '::' port: 13010
----------SERVER LOG END-------------

Environment

None

Smart Checklist

Activity

mohit.joshi September 15, 2020 at 10:32 AM

Thanks Lalit. Closing the ticket as the reported MTR testcase is passing in https://perconadev.atlassian.net/browse/PS-8#icft=PS-8.0.20

Lalit Choudhary September 15, 2020 at 10:27 AM

reported test passing 

 

[ 28%] encryption.innodb-redo-nokeys [ pass ] 16858

Lalit Choudhary September 15, 2020 at 10:22 AM

PS 8.0.20

 

============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ [100%] encryption.innodb-page_encryption-32k [ pass ] 12431 ------------------------------------------------------------------------------ The servers were restarted 0 times The servers were reinitialized 1 times Spent 12.431 of 32 seconds executing testcases Completed: All 1 tests were successful. ./mysql-test-run.pl --do-test=innodb The servers were restarted 24 times The servers were reinitialized 1 times Spent 846.688 of 968 seconds executing testcases Completed: Failed 1/29 tests, 96.55% were successful. Failing test(s): keyring_vault.innodb_row_log_encryption 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 136 tests were skipped, 3 by the test itself.

 

mysql logs,

 

[ 31%] keyring_vault.innodb_row_log_encryption [ fail ] Test ended at 2020-09-15 05:14:11 CURRENT_TEST: keyring_vault.innodb_row_log_encryption Please export MTR_VAULT_TOKEN variable at /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/var/tmp0GGzJk line 4. mysqltest: At line 6: Command "perl" failed with error 255. my_errno=2. In included file /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/suite/keyring_vault/generate_conf_file.inc: 25 included from /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/suite/keyring_vault/generate_default_mount_conf_files.inc: 8 included from /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/suite/keyring_vault/innodb_row_log_encryption.test: 5 The result from queries just before the failure was: safe_process[41884]: Child process: 41888, exit: 1   Server [mysqld.1 - pid: 41801, winpid: 41801] log: Server log from this test: ----------SERVER LOG START----------- 2020-09-15T09:14:10.290253Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 1024 (requested 8161) 2020-09-15T09:14:10.290268Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 431 (requested 4000) 2020-09-15T09:14:10.522010Z 0 [Warning] [MY-010099] [Server] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory. 2020-09-15T09:14:10.522028Z 0 [Warning] [MY-010101] [Server] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory. 2020-09-15T09:14:10.522142Z 0 [Note] [MY-010949] [Server] Basedir set to /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/. 2020-09-15T09:14:10.522157Z 0 [System] [MY-010116] [Server] /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/bin/mysqld (mysqld 8.0.20-11) starting as process 41802 2020-09-15T09:14:10.531852Z 0 [Note] [MY-012366] [InnoDB] Using Linux native AIO 2020-09-15T09:14:10.532314Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled. 2020-09-15T09:14:10.535033Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2020-09-15T09:14:10.535161Z 1 [Note] [MY-013546] [InnoDB] Atomic write enabled 2020-09-15T09:14:10.535271Z 1 [Note] [MY-012932] [InnoDB] PUNCH HOLE support available 2020-09-15T09:14:10.535359Z 1 [Note] [MY-012943] [InnoDB] Mutexes and rw_locks use GCC atomic builtins 2020-09-15T09:14:10.535436Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes 2020-09-15T09:14:10.535515Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier 2020-09-15T09:14:10.535617Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.3 2020-09-15T09:14:10.540393Z 1 [Note] [MY-013251] [InnoDB] Number of pools: 1 2020-09-15T09:14:10.540696Z 1 [Note] [MY-012951] [InnoDB] Using CPU crc32 instructions 2020-09-15T09:14:10.541518Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './' 2020-09-15T09:14:10.541723Z 1 [Note] [MY-012204] [InnoDB] Scanning './' 2020-09-15T09:14:10.544010Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 6 files. 2020-09-15T09:14:10.545703Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 24.000000M, instances = 1, chunk size =24.000000M 2020-09-15T09:14:10.550463Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool 2020-09-15T09:14:10.551846Z 0 [Note] [MY-011952] [InnoDB] If the mysqld execution user is authorized, page cleaner and LRU manager thread priority can be changed. See the man page of setpriority(). 2020-09-15T09:14:10.552816Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite 2020-09-15T09:14:10.553788Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite 2020-09-15T09:14:10.659937Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 2 2020-09-15T09:14:10.660134Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 4 2020-09-15T09:14:10.660298Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite 2020-09-15T09:14:10.660469Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite 2020-09-15T09:14:10.661072Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 17437738, whereas checkpoint_lsn = 17437845 2020-09-15T09:14:10.666178Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started... 2020-09-15T09:14:10.666766Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ... 2020-09-15T09:14:10.666944Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed! 2020-09-15T09:14:10.667325Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'. 2020-09-15T09:14:10.667710Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'. 2020-09-15T09:14:10.671463Z 1 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces. 2020-09-15T09:14:10.671647Z 1 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 1296 2020-09-15T09:14:10.685747Z 1 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables 2020-09-15T09:14:10.686158Z 1 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2020-09-15T09:14:10.705151Z 1 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB. 2020-09-15T09:14:10.705613Z 1 [Note] [MY-011825] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/' 2020-09-15T09:14:10.755238Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active. 2020-09-15T09:14:10.755952Z 1 [Note] [MY-012976] [InnoDB] Percona XtraDB (http://www.percona.com) 8.0.20-11 started; log sequence number 17437845 2020-09-15T09:14:10.756475Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. 2020-09-15T09:14:10.764658Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80017'. 2020-09-15T09:14:10.884748Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files 2020-09-15T09:14:10.886859Z 1 [Note] [MY-012356] [InnoDB] Validated 8/8 tablespaces 2020-09-15T09:14:10.911839Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80017'. 2020-09-15T09:14:10.927653Z 0 [Note] [MY-011332] [Server] Plugin mysqlx reported: 'IPv6 is available' 2020-09-15T09:14:10.928950Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. bind-address: '::' port: 13010' 2020-09-15T09:14:10.929212Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. socket: '/bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/var/tmp/mysqlx.1.sock'' 2020-09-15T09:14:10.929458Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/var/tmp/mysqlx.1.sock' bind-address: '::' port: 13010 2020-09-15T09:14:10.929843Z 0 [Warning] [MY-013129] [Server] A message intended for a client cannot be sent there as no client-session is attached. Therefore, we're sending the information to the error-log instead: MY-000029 - File '' not found (OS errno 2 - No such file or directory) 2020-09-15T09:14:10.930107Z 0 [ERROR] [MY-011370] [Server] Plugin keyring_vault reported: 'File '' not found (OS errno 2 - No such file or directory)' 2020-09-15T09:14:10.930381Z 0 [System] [MY-011197] [Server] Plugin keyring_vault reported: 'Could not open file with credentials.' 2020-09-15T09:14:10.930645Z 0 [System] [MY-011197] [Server] Plugin keyring_vault reported: 'keyring_vault initialization failure. Please check that the keyring_vault_config_file points to readable keyring_vault configuration file. Please also make sure Vault is running and accessible. The keyring_vault will stay unusable until correct configuration file gets provided.' 2020-09-15T09:14:10.930908Z 0 [Warning] [MY-013129] [Server] A message intended for a client cannot be sent there as no client-session is attached. Therefore, we're sending the information to the error-log instead: MY-042000 - keyring_vault initialization failure. Please check the server log. 2020-09-15T09:14:11.080277Z 0 [Note] [MY-010902] [Server] Thread priority attribute setting in Resource Group SQL shall be ignored due to unsupported platform or insufficient privilege. 2020-09-15T09:14:11.107299Z 0 [Note] [MY-012487] [InnoDB] DDL log recovery : begin 2020-09-15T09:14:11.107708Z 0 [Note] [MY-012488] [InnoDB] DDL log recovery : end 2020-09-15T09:14:11.108206Z 0 [Note] [MY-011946] [InnoDB] Loading buffer pool(s) from /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/var/mysqld.1/data/ib_buffer_pool 2020-09-15T09:14:11.113535Z 0 [Note] [MY-011946] [InnoDB] Buffer pool(s) load completed at 200915 12:14:11 2020-09-15T09:14:11.119248Z 0 [Note] [MY-012922] [InnoDB] Waiting for purge to start 2020-09-15T09:14:11.170467Z 0 [Warning] [MY-010075] [Server] 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: d1193214-f733-11ea-abd6-90b11c553129. 2020-09-15T09:14:11.176642Z 0 [Note] [MY-010303] [Server] Skipping generation of SSL certificates as options related to SSL are specified. 2020-09-15T09:14:11.192243Z 0 [Warning] [MY-010068] [Server] CA certificate /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/std_data/cacert.pem is self signed. 2020-09-15T09:14:11.192611Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --sha256_password_auto_generate_rsa_keys is set to OFF. 2020-09-15T09:14:11.192909Z 0 [Note] [MY-010310] [Server] Skipping generation of RSA key pair as --caching_sha2_password_auto_generate_rsa_keys is set to OFF. 2020-09-15T09:14:11.193574Z 0 [Note] [MY-010252] [Server] Server hostname (bind-address): '*'; port: 13000 2020-09-15T09:14:11.193968Z 0 [Note] [MY-010253] [Server] IPv6 is available. 2020-09-15T09:14:11.194326Z 0 [Note] [MY-010264] [Server] - '::' resolves to '::'; 2020-09-15T09:14:11.194685Z 0 [Note] [MY-010251] [Server] Server socket created on IP: '::'. 2020-09-15T09:14:11.199475Z 0 [Warning] [MY-000067] [Server] unknown variable 'loose-mysqlx-ssl=DISABLED'. 2020-09-15T09:14:11.199820Z 0 [Warning] [MY-000067] [Server] unknown variable 'loose-debug-sync-timeout=600'. 2020-09-15T09:14:11.226072Z 0 [Note] [MY-011025] [Repl] Failed to start slave threads for channel ''. 2020-09-15T09:14:11.229335Z 5 [Note] [MY-010051] [Server] Event Scheduler: scheduler thread started with id 5 2020-09-15T09:14:11.230437Z 0 [Note] [MY-011240] [Server] Plugin mysqlx reported: 'Using SSL configuration from MySQL Server' 2020-09-15T09:14:11.242074Z 0 [Note] [MY-011243] [Server] Plugin mysqlx reported: 'Using OpenSSL for TLS connections' 2020-09-15T09:14:11.242342Z 0 [System] [MY-010931] [Server] /bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/bin/mysqld: ready for connections. Version: '8.0.20-11' socket: '/bigdisk/lalit/Percona-Server-8.0.20-11-Linux.x86_64.glibc2.12/mysql-test/var/tmp/mysqld.1.sock' port: 13000 Percona Server (GPL), Release 11, Revision 159f0eb. ----------SERVER LOG END-------------

 

 

Lalit Choudhary June 27, 2019 at 2:55 PM

 In my test issue with encryption.innodb-redo-nokeys getting skipped and few encryption related test fails.

$ ./mtr encryption.innodb-redo-nokeys Logging: ./mtr encryption.innodb-redo-nokeys MySQL Version 8.0.15 Checking supported features - Binaries are debug compiled Using 'all' suites Collecting tests Checking leftover processes Removing old var directory Creating var directory '/mysql/ps80/usr/local/mysql/mysql-test/var' Installing system database Using parallel: 1 ============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ [100%] encryption.innodb-redo-nokeys [ skipped ] id="82"�2 ------------------------------------------------------------------------------ The servers were restarted 0 times Spent 0.000 of 23 seconds executing testcases Completed: All 0 tests were successful. 1 tests were skipped, 1 by the test itself.

 

$ ./mysql-test-run.pl --do-test=innodb [ 8%] encryption.innodb-page_encryption-32k [ fail ] Test ended at 2019-06-27 10:47:33 Result file '/mysql/ps80/usr/local/mysql/mysql-test/suite/encryption/r/innodb-page_encryption-32k.result' doesn't exist.
Done

Details

Assignee

Reporter

Labels

Fix versions

Priority

Smart Checklist

Created June 16, 2019 at 7:19 AM
Updated March 6, 2024 at 12:04 PM
Resolved September 15, 2020 at 10:33 AM

Flag notifications