[MDEV-17912] Aria with encryption fails upon crash recovery: Redo phase failed, "Got error 192" - Jira

Details

Type: Technical task
Status: Stalled (View Workflow)
Priority: Critical
Resolution: Unresolved
Affects Version/s: 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL)
Fix Version/s: 10.5, 10.6
Component/s: Encryption, Storage Engine - Aria
Labels:
- affects-tests

Description

10.4 470e9a9fb6
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting

The datadir after the initial crash, before any attempt to recover, is here:
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with

--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt

Adjust the path to keys.txt if needed.
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):

https://github.com/MariaDB/randgen --branch elenst-jira-refs b1facb0360

perl ./runall-new.pl  --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6  --scenario=CrashUpgrade   --redefine=conf/mariadb/bulk_insert.yy  --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the paths to basedir and keys file on the command line.

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

Attachments

Issue Links

relates to

MDEV-17864 Run regular crash recovery tests for Aria tables (system and user tables)

Closed

MDEV-17913 Encrypted transactional Aria tables remain corrupt after crash recovery, automatic repairment does not work

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2018-12-05 17:05

Elena Stepanova made changes - 2018-12-05 17:10

Field	Original Value	New Value
Description	{noformat:title=10.4 470e9a9fb6} 2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ... 2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery recovered pages: 0% 10% 9% 19% 29% 2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172 Got error 192 when executing record redo_new_row_head 2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files 2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error. 2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed. 2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO 2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!! 2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes 2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1 2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions 2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts) 2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool 2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812 2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active. 2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start 2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21 2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool 2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled. 2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded 2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins. 2018-12-05 18:38:34 0 [ERROR] Aborting {noformat} The datadir after the initial crash, before any attempt to recover, is here: Unpack and start the server with {noformat} --aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt {noformat} Adjust the path to {{keys.txt}} if needed. The general log for the test flow prior to the initial crash is in mysql.log. The test to run the complete flow (might require several trials): {noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360} perl ./runall-trials.pl --trials=5 --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt {noformat} RQG branch and revision are important here, you might not have some of the required files in other branches. Adjust the path to basedir and keys file on the command line.	{noformat:title=10.4 470e9a9fb6} 2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ... 2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery recovered pages: 0% 10% 9% 19% 29% 2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172 Got error 192 when executing record redo_new_row_head 2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files 2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error. 2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed. 2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO 2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!! 2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes 2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1 2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions 2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts) 2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool 2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812 2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active. 2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start 2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21 2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool 2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled. 2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded 2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins. 2018-12-05 18:38:34 0 [ERROR] Aborting {noformat} {color:red}The datadir after the initial crash, before any attempt to recover, is here:{color} ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz Unpack and start the server with {noformat} --aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt {noformat} Adjust the path to {{keys.txt}} if needed. The general log for the test flow prior to the initial crash is in mysql.log. The test to run the complete flow (might require several trials): {noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360} perl ./runall-trials.pl --trials=5 --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt {noformat} RQG branch and revision are important here, you might not have some of the required files in other branches. Adjust the path to basedir and keys file on the command line.

Elena Stepanova made changes - 2018-12-05 17:11

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

Elena Stepanova made changes - 2018-12-05 17:18

Link

This issue relates to ~~MDEV-17864~~ [ ~~MDEV-17864~~ ]

Elena Stepanova made changes - 2018-12-05 17:22

Fix Version/s		10.3 [ 22126 ]
Affects Version/s		10.3 [ 22126 ]

Elena Stepanova made changes - 2018-12-05 17:36

Fix Version/s		10.2 [ 14601 ]
Affects Version/s		10.2 [ 14601 ]

Elena Stepanova made changes - 2018-12-05 18:03

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.

Elena Stepanova made changes - 2018-12-05 18:29

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

Elena Stepanova made changes - 2018-12-05 18:30

Assignee

Elena Stepanova [ elenst ]

Michael Widenius [ monty ]

Elena Stepanova made changes - 2018-12-05 19:27

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.4 --vardir=/dev/shm/vardir --duration=250 --threads=6 --seed=1543986852 --scenario=CrashUpgrade --reporters=Backtrace,ErrorLog,Deadlock --views --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=5 --mysqld=--loose-innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/10.4/mysql-test/std_data/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
Adjust the path to basedir and keys file on the command line.

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-new.pl --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
*Adjust the paths to basedir and keys file on the command line.*

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

Elena Stepanova made changes - 2018-12-05 19:27

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-new.pl --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
*Adjust the paths to basedir and keys file on the command line.*

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

----

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-new.pl --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
*Adjust the paths to basedir and keys file on the command line.*

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

Elena Stepanova made changes - 2018-12-05 19:56

Link

This issue relates to ~~MDEV-17913~~ [ ~~MDEV-17913~~ ]

Elena Stepanova made changes - 2019-03-14 00:00

Assignee

Michael Widenius [ monty ]

Vladislav Lesin [ vlad.lesin ]

Elena Stepanova made changes - 2019-05-16 13:45

Priority

Major [ 3 ]

Critical [ 2 ]

Vladislav Lesin made changes - 2019-05-28 11:49

Status

Open [ 1 ]

In Progress [ 3 ]

Elena Stepanova made changes - 2019-06-20 12:52

Parent		MDEV-19813 [ 76916 ]
Issue Type	Bug [ 1 ]	Technical task [ 7 ]

Elena Stepanova made changes - 2019-07-06 20:59

Labels

affects-tests

Elena Stepanova made changes - 2019-07-07 22:57

Summary

Aria with encryption fails upon crash recovery: Redo phase failed

Aria with encryption fails upon crash recovery: Redo phase failed, "Got error 192"

Elena Stepanova made changes - 2020-02-06 01:24

Description

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

----

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-dev b1facb0360}
perl ./runall-new.pl --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
*Adjust the paths to basedir and keys file on the command line.*

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

{noformat:title=10.4 470e9a9fb6}
2018-12-05 18:38:27 0 [Note] /home/travis/server/10.4/bin/mysqld (mysqld 10.4.1-MariaDB-debug-log) starting as process 21315 ...
2018-12-05 18:38:27 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 9% 19% 29%
2018-12-05 18:38:33 0 [ERROR] mysqld: failed to decrypt './test/oltp46' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2018-12-05 18:38:33 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables and delete all aria_log.######## files
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' init function returned error.
2018-12-05 18:38:33 0 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
2018-12-05 18:38:33 0 [Note] InnoDB: Using Linux native AIO
2018-12-05 18:38:33 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2018-12-05 18:38:33 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-12-05 18:38:33 0 [Note] InnoDB: Uses event mutexes
2018-12-05 18:38:33 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-12-05 18:38:33 0 [Note] InnoDB: Number of pools: 1
2018-12-05 18:38:33 0 [Note] InnoDB: Using SSE2 crc32 instructions
2018-12-05 18:38:33 0 [Note] mysqld: O_TMPFILE is not supported on /home/travis/logs/vardir/tmp (disabling future attempts)
2018-12-05 18:38:33 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-12-05 18:38:33 0 [Note] InnoDB: Completed initialization of buffer pool
2018-12-05 18:38:33 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-05 18:38:33 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=139812
2018-12-05 18:38:34 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2018-12-05 18:38:34 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-12-05 18:38:34 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-12-05 18:38:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-12-05 18:38:34 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-12-05 18:38:34 0 [Note] InnoDB: Waiting for purge to start
2018-12-05 18:38:34 0 [Note] InnoDB: 10.4.1 started; log sequence number 139821; transaction id 21
2018-12-05 18:38:34 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/data/ib_buffer_pool
2018-12-05 18:38:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2018-12-05 18:38:34 0 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
2018-12-05 18:38:34 0 [ERROR] Failed to initialize plugins.
2018-12-05 18:38:34 0 [ERROR] Aborting
{noformat}

{color:red}The datadir after the initial crash, before any attempt to recover, is here:{color}
ftp://ftp.askmonty.org/public/mdev17912-data.tar.gz

Unpack and start the server with
{noformat}
--aria-encrypt-tables=1 --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt
{noformat}
*Adjust the path to {{keys.txt}} if needed.*
The general log for the test flow prior to the initial crash is in mysql.log.

----

The test to run the complete flow (might require several trials):
{noformat:title=https://github.com/MariaDB/randgen --branch elenst-jira-refs b1facb0360}
perl ./runall-new.pl --basedir=/data/bld/10.2 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=/data/bld/keys.txt
{noformat}

RQG branch and revision are important here, you might not have some of the required files in other branches.
*Adjust the paths to basedir and keys file on the command line.*

Couldn't reproduce on 10.1 with the given test, but possibly there is some difference in the test flow.
Couldn't reproduce so far without encryption.

Roel Van de Paar made changes - 2020-10-04 23:00

Assignee

Vladislav Lesin [ vlad.lesin ]

Michael Widenius [ monty ]

Michael Widenius added a comment - 2021-10-25 16:18 - edited

This looks very like something that is related to MDEV-17912.
The data files has the same kind of corruption that would happen if one did a repair on encrypted tables before MDEV-17912. (Either manual or atomic).

When testing with 10.7, I get the following new warnings, which where added to detect the MDEV-17912 issue:

2021-10-25 19:01:36 0 [ERROR] mariadbd: Table ./test/oltp33.MAI has wrong LSN: (2694473,0x2da478dd) on page: 1

Elenst, any chance you could do a new run of the test case on the latest 10.6 or 10.7 to check if this bug still exists?

Michael Widenius added a comment - 2021-10-25 16:18 - edited This looks very like something that is related to MDEV-17912 . The data files has the same kind of corruption that would happen if one did a repair on encrypted tables before MDEV-17912 . (Either manual or atomic). When testing with 10.7, I get the following new warnings, which where added to detect the MDEV-17912 issue: 2021-10-25 19:01:36 0 [ERROR] mariadbd: Table ./test/oltp33.MAI has wrong LSN: (2694473,0x2da478dd) on page: 1 Elenst, any chance you could do a new run of the test case on the latest 10.6 or 10.7 to check if this bug still exists?

Elena Stepanova added a comment - 2021-10-31 19:30

monty,

The same test still fails the same way on current 10.6/10.7. I modified the test a little bit just to avoid false positives (because when the recovery does not fail, it can take longer on 10.6+ than it used to on earlier versions, and the test wouldn't wait that long), but it's just a technicality.
Please note that as the description says, it doesn't fail every time. You don't need to restart it, the command line below runs it up to 5 times (--trials=5) unless it fails earlier, and you can increase the value as needed. It usually fails for me within 2-3 attempts.
IMPORTANT: The command line uses `pwd` which known to cause trouble on certain systems. Replace it by the actual path if needed.
IMPORTANT: The test expects that the server would use the file_key_management plugin, so it must be available in the plugin directory. Unless <basedir>/lib/plugin contains it in your build, point the test/server to it via --mysqld=--plugin-dir=<path>.
IMPORTANT: Remember to change the path to the basedir.

git clone https://github.com/MariaDB/randgen --branch mdev17912 rqg-mdev17912

cd rqg-mdev17912

perl ./runall-trials.pl --trials=5  --basedir=/data/bld/10.6 --vardir=/dev/shm/vardir --duration=250 --threads=6  --scenario=CrashUpgrade   --redefine=conf/mariadb/bulk_insert.yy  --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/data/file_key_management_keys.txt

10.6 fdc4c3a2
2021-10-31 21:11:26 0 [Note] /data/bld/10.6/bin/mysqld (server 10.6.5-MariaDB-debug-log) starting as process 985080 ...
2021-10-31 21:11:26 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 20% 30% 40% 50%
2021-10-31 21:11:47 0 [ERROR] mysqld: failed to decrypt './test/oltp88' rc: -1 dstlen: 0 size: 8172

Got error 192 when executing record redo_new_row_head
2021-10-31 21:11:47 0 [ERROR] mysqld: Aria engine: Redo phase failed
tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
2021-10-31 21:11:47 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables (*.MAI) and delete all aria_log.######## files
2021-10-31 21:11:48 0 [ERROR] Plugin 'Aria' init function returned error.

Elena Stepanova added a comment - 2021-10-31 19:30 monty , The same test still fails the same way on current 10.6/10.7. I modified the test a little bit just to avoid false positives (because when the recovery does not fail, it can take longer on 10.6+ than it used to on earlier versions, and the test wouldn't wait that long), but it's just a technicality. Please note that as the description says, it doesn't fail every time. You don't need to restart it, the command line below runs it up to 5 times (--trials=5) unless it fails earlier, and you can increase the value as needed. It usually fails for me within 2-3 attempts. IMPORTANT : The command line uses `pwd` which known to cause trouble on certain systems. Replace it by the actual path if needed. IMPORTANT : The test expects that the server would use the file_key_management plugin, so it must be available in the plugin directory. Unless <basedir>/lib/plugin contains it in your build, point the test/server to it via --mysqld=--plugin-dir=<path> . IMPORTANT : Remember to change the path to the basedir. git clone https://github.com/MariaDB/randgen --branch mdev17912 rqg-mdev17912 cd rqg-mdev17912 perl ./runall-trials.pl --trials=5 --basedir=/data/bld/10.6 --vardir=/dev/shm/vardir --duration=250 --threads=6 --scenario=CrashUpgrade --redefine=conf/mariadb/bulk_insert.yy --engine=Aria --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--aria-encrypt-tables=1 --grammar=conf/mariadb/generic-dml.yy --gendata=conf/mariadb/oltp-aria.zz --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/data/file_key_management_keys.txt 10.6 fdc4c3a2 2021-10-31 21:11:26 0 [Note] /data/bld/10.6/bin/mysqld (server 10.6.5-MariaDB-debug-log) starting as process 985080 ... 2021-10-31 21:11:26 0 [Note] mysqld: Aria engine: starting recovery recovered pages: 0% 10% 20% 30% 40% 50% 2021-10-31 21:11:47 0 [ERROR] mysqld: failed to decrypt './test/oltp88' rc: -1 dstlen: 0 size: 8172 Got error 192 when executing record redo_new_row_head 2021-10-31 21:11:47 0 [ERROR] mysqld: Aria engine: Redo phase failed tables to flush: 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 2021-10-31 21:11:47 0 [ERROR] mysqld: Aria recovery failed. Please run aria_chk -r on all Aria tables (*.MAI) and delete all aria_log.######## files 2021-10-31 21:11:48 0 [ERROR] Plugin 'Aria' init function returned error.

Elena Stepanova made changes - 2021-10-31 19:30

Fix Version/s		10.5 [ 23123 ]
Fix Version/s		10.6 [ 24028 ]
Affects Version/s		10.5 [ 23123 ]
Affects Version/s		10.6 [ 24028 ]
Affects Version/s		10.7 [ 24805 ]

Sergei Golubchik made changes - 2021-12-06 21:36

Workflow

MariaDB v3 [ 91062 ]

MariaDB v4 [ 144494 ]

Ralf Gebhardt made changes - 2022-08-04 08:41

Fix Version/s

10.2 [ 14601 ]

Julien Fritsch made changes - 2023-04-27 14:19

Fix Version/s

10.3 [ 22126 ]

Julien Fritsch made changes - 2023-12-05 10:04

Comment

[ Automated message:
----------------------------
Since this issue has not been updated since 6 weeks, it's time to move it back to Stalled. ]

Julien Fritsch made changes - 2023-12-07 10:26

Status

In Progress [ 3 ]

Stalled [ 10000 ]

Julien Fritsch made changes - 2024-09-10 15:07

Fix Version/s

10.4 [ 22408 ]

People

Assignee:: Michael Widenius

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2018-12-05 17:05

Updated:: 2024-09-10 15:07

Git Integration

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

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration