[MDEV-13834] 10.2 wrongly recognizes 10.1.10 innodb_encrypt_log=ON data as after-crash and refuses to start Created: 2017-09-18  Updated: 2018-06-04  Resolved: 2018-05-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.4
Fix Version/s: 10.2.16, 10.3.8

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File data_without_ib_logfiles.tar.gz     File ib_logfiles.tar.gz     File mysql.err_orig     File mysql.log.gz    
Issue Links:
Problem/Incident
is caused by MDEV-11782 Redefine the innodb_encrypt_log format Closed

 Description   

The attached data directory was created by server 10.1.10 from release x86_64 new libc bintar which was run with the following options:

--no-defaults \
 
--file-key-management \
 
--file-key-management-filename=/data/bld/10.2/mysql-test/std_data/keys.txt \
 
--plugin-load-add=file_key_management.so \
 
--innodb-encrypt-tables --innodb-encrypt-log \
 
--innodb-encryption-threads=4 \
 
--aria-encrypt-tables=1 \
 
--encrypt-tmp-disk-tables=1 \
 
--encrypt-binlog \
 
--innodb-page-size=8K \
 
--innodb-compression-algorithm=zlib \
 
--loose-innodb-file-format=Barracuda \
 
--loose-innodb-file-per-table=1 \
 
--loose-lock-wait-timeout=20 \
 
--loose-innodb-lock-wait-timeout=10 \
 
--loose-innodb_log_compressed_pages=on

A bunch of tables were created, then DML was run for ~1 minute, then the server was shutdown normally. The error log confirming it is attached, as well as the general log in case it's needed.

Current 10.2 with the same server options refuses to start on this data, saying

2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Completed initialization of buffer pool
 
2017-09-18 16:59:14 140600128263936 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2017-09-18 16:59:14 140600868909120 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-09-18 16:59:14 140600868909120 [ERROR] InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10.2.2, and it appears corrupted. Please follow the instructions at http://dev.mysql.com/doc/refman/5.7/en/upgrading.html
 
2017-09-18 16:59:14 140600868909120 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2232] with error Data structure corruption

Current 10.1 does start, and does not say anything about crash recovery, only

2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Completed initialization of buffer pool
 
2017-09-18 16:45:56 140340660551808 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 0 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 3 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 2 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 1 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 15 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 16 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 17 from 0x8027 to 0x127
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 18 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 19 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 20 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 21 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 22 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 23 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 24 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 25 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 26 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 27 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 28 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 29 from 0x8027 to 0x127
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 30 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 31 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 32 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 33 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 34 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 35 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 36 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 37 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 38 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 39 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 40 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 41 from 0x8027 to 0x127
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 42 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 43 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 44 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 45 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 46 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 47 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 48 from 0x8361 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 49 from 0x80e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 50 from 0x84e1 to 0x10121
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 6 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 7 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 8 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 9 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 10 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 11 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 12 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 13 from 0x8000 to 0x100
 
2017-09-18 16:45:57 140340660551808 [Warning] InnoDB: adjusting FSP_SPACE_FLAGS of tablespace 14 from 0x8000 to 0x100
 
2017-09-18 16:45:58 140340660551808 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-09-18 16:45:58 140340660551808 [Note] InnoDB: Waiting for purge to start
 
2017-09-18 16:45:58 140340660551808 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 9116907

(similar with InnoDB plugin).

Note: The data has been split into two archives, one with ib_logfileX files, the other with everything else; it's just to allow archives to fit into JIRA limitation, everything is from the same test run, just put ib_logfiles back to the datadir.

 Comments   
Comment by Marko Mäkelä [ 2018-05-28 ]

I tested the ib_logfiles.tar.gz in 10.1. The crypt_info.size() actually is 6 and not 5, as I would have expected. Because the upgrade code in 10.2 uses an array of 5 elements, it is missing the encryption information for the checkpoint number 19, which is what is needed for parsing the log.

Comment by Marko Mäkelä [ 2018-05-28 ]

Another problem is that in 10.1, the log block checksum is not valid, but it is not checked either!
If I call log_block_checksum_is_ok_or_old_format() after the decryption took place in log_decrypt_after_read(), a message would be emitted to the error log:

BROKEN: block: 17807 checkpoint: 19 1daf6b82 82ffa2f9

So, we have to stop validating the checksum when upgrading an encrypted redo log of MariaDB 10.1. With that change, MariaDB 10.2 will perform an upgrade on the redo log as desired.

Comment by Marko Mäkelä [ 2018-06-04 ]

My first fix broke the upgrade from MariaDB 10.1 in some cases, because my revised code would return an error if the encryption key corresponding to the current checkpoint number is not found. MariaDB 10.1 would actually use the first encryption key in this case. This logic was added as part of MDEV-9422 (MariaDB 10.1.13), which also disabled the encryption key rotation. My second fix addresses that.

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