[MDEV-13167] InnoDB key rotation is not skipping unused pages Created: 2017-06-24  Updated: 2017-08-31  Resolved: 2017-08-23

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.1
Fix Version/s: 10.1.27, 10.2.9, 10.3.2

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

Attachments: File bootstrap.log     File datadir.tar.gz     File mysqld.1.err.gz     File test.out    
Issue Links:
Duplicate
duplicates MDEV-13586 [Draft] InnoDB: Failing assertion: bl... Closed

 Description   

It has been happening in buildbot on different 10.1-based trees since 06.06.2017 – not very frequently (partially because only debug builds are affected), but quite regularly, 11 occurrences by now, all of ps-protocol, embedded and normal variants.

https://internal.askmonty.org/buildbot/builders/kvm-fulltest2/builds/8544/steps/test_3/logs/stdio

encryption.innodb-checksum-algorithm '8k,cbc,xtradb' w4 [ fail ]
 
        Test ended at 2017-06-22 01:05:03
 
 
 
CURRENT_TEST: encryption.innodb-checksum-algorithm
 
mysqltest: At line 110: query 'ALTER TABLE t_$checksum DISCARD TABLESPACE' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
restore: t_crc32 .ibd and .cfg files
 
restore: tpe_crc32 .ibd and .cfg files
 
restore: tp_crc32 .ibd and .cfg files
 
ALTER TABLE tce_crc32 IMPORT TABLESPACE;
 
update tce_crc32 set b=substr(b,1);
 
ALTER TABLE tc_crc32 IMPORT TABLESPACE;
 
update tc_crc32 set b=substr(b,1);
 
ALTER TABLE te_crc32 IMPORT TABLESPACE;
 
update te_crc32 set b=substr(b,1);
 
ALTER TABLE t_crc32 IMPORT TABLESPACE;
 
update t_crc32 set b=substr(b,1);
 
ALTER TABLE tpe_crc32 IMPORT TABLESPACE;
 
update tpe_crc32 set b=substr(b,1);
 
ALTER TABLE tp_crc32 IMPORT TABLESPACE;
 
update tp_crc32 set b=substr(b,1);
 
SET GLOBAL innodb_checksum_algorithm=crc32;
 
ALTER TABLE tce_crc32 DISCARD TABLESPACE;
 
ALTER TABLE tc_crc32 DISCARD TABLESPACE;
 
ALTER TABLE te_crc32 DISCARD TABLESPACE;
 
ALTER TABLE t_crc32 DISCARD TABLESPACE;
 
 
 
More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.1.25/mysql-test/var/4/log/innodb-checksum-algorithm.log
 
 
 
 
 
Server [mysqld.1 - pid: 30197, winpid: 30197, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2017-06-22  1:05:00 3072244032 [Note] /mnt/buildbot/build/mariadb-10.1.25/sql/mysqld (mysqld 10.1.25-MariaDB-debug) starting as process 30198 ...
 
2017-06-22  1:05:00 3072244032 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2017-06-22  1:05:00 3072244032 [Note] Plugin 'SEQUENCE' is disabled.
 
2017-06-22  1:05:00 3072244032 [Note] Plugin 'partition' is disabled.
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB:  innodb-page-size has been changed from the default value 16384 to 8192 .
 
innodb_open_files should not be greater than the open_files_limit.
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.
 
 
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: The InnoDB memory heap is disabled
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Using Linux native AIO
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Using generic crc32 instructions
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Completed initialization of buffer pool
 
2017-06-22  1:05:00 3072244032 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-06-22  1:05:01 3072244032 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-06-22  1:05:01 3072244032 [Note] InnoDB: Waiting for purge to start
 
2017-06-22  1:05:01 3072244032 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 934005
 
2017-06-22  1:05:01 2824854336 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_CMP' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_CHANGED_PAGES' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2017-06-22  1:05:01 3072244032 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2017-06-22  1:05:01 3072244032 [Warning] /mnt/buildbot/build/mariadb-10.1.25/sql/mysqld: unknown option '--loose-pam-debug'
 
2017-06-22  1:05:01 3072244032 [Note] Server socket created on IP: '127.0.0.1'.
 
2017-06-22  1:05:01 3072244032 [Note] /mnt/buildbot/build/mariadb-10.1.25/sql/mysqld: ready for connections.
 
Version: '10.1.25-MariaDB-debug'  socket: '/mnt/buildbot/build/mariadb-10.1.25/mysql-test/var/tmp/4/mysqld.1.sock'  port: 16000  Source distribution
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Creating #1 thread id 2805988160 total threads 4.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Creating #2 thread id 2797595456 total threads 4.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Creating #3 thread id 2789202752 total threads 4.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Creating #4 thread id 2780810048 total threads 4.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."tce_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Stopping purge
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/tce_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."tce_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."tc_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/tc_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."tc_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."te_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/te_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."te_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."t_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/t_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."t_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."tpe_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/tpe_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."tpe_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk of '"test"."tp_crc32"' started.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Writing table metadata to './test/tp_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Table '"test"."tp_crc32"' flushed to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/tce_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/tc_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/te_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/t_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/tpe_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Deleting the meta-data file './test/tp_crc32.cfg'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Resuming purge
 
2017-06-22  1:05:01 2974498624 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=447] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Importing tablespace for table 'test/tce_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: "test"."tce_crc32" autoinc value set to 2
 
2017-06-22  1:05:01 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=13] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=61] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2797595456 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=421] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2780810048 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=395] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Importing tablespace for table 'test/tc_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: "test"."tc_crc32" autoinc value set to 2
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Importing tablespace for table 'test/te_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:01 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=14] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=62] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2797595456 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=466] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: "test"."te_crc32" autoinc value set to 2
 
2017-06-22  1:05:01 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=15] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=63] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2797595456 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=469] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Importing tablespace for table 'test/t_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:01 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:02 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=16] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=64] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: "test"."t_crc32" autoinc value set to 2
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Importing tablespace for table 'test/tpe_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:02 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=17] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=65] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: "test"."tpe_crc32" autoinc value set to 2
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Importing tablespace for table 'test/tp_crc32' that was exported from host 'ubuntu-precise-i386'
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase I - Update all pages
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Sync to disk
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Sync to disk - done!
 
2017-06-22  1:05:02 2789202752 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=18] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2805988160 [Warning] InnoDB: innodb_checksum_algorithm is set to "strict_crc32" but the page [page id: space=0, page number=66] contains a valid checksum "innodb". Accepting the page as valid. Change innodb_checksum_algorithm to "crc32" to silently accept such pages or rewrite all pages so that they contain "crc32" checksum.
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: Phase IV - Flush complete
 
2017-06-22  1:05:02 2974498624 [Note] InnoDB: "test"."tp_crc32" autoinc value set to 2


2017-06-22  1:05:02 2780810048 [ERROR] InnoDB: Corruption: Block space_id 0 != page space_id 0 or Block offset 510 != page offset 0
 
2017-06-22 01:05:02 a5bfcb40  InnoDB: Assertion failure in thread 2780810048 in file buf0buf.cc line 2734
 
InnoDB: Failing assertion: block->page.offset == page_get_page_no(page_align(ptr))
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170622  1:05:02 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.1.25-MariaDB-debug
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=1
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61820 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x48400
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld(my_print_stacktrace+0x32)[0x8b2eaf1]
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld(handle_fatal_signal+0x3b0)[0x84d9008]
 
[0xb773f400]
 
[0xb773f424]
 
/lib/i386-linux-gnu/libc.so.6(gsignal+0x4f)[0xb721b1ef]
 
/lib/i386-linux-gnu/libc.so.6(abort+0x175)[0xb721e835]
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld[0x898d5ac]
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld[0x898d61f]
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld[0x8828df1]
 
/mnt/buildbot/build/mariadb-10.1.25/sql/mysqld[0x88245c0]
 
mysys/stacktrace.c:267(my_print_stacktrace)[0x8825454]
 
fil/fil0crypt.cc:1992(fil_crypt_rotate_page)[0x8a160f0]
 
fil/fil0crypt.cc:2122(fil_crypt_rotate_pages)[0x8a165d9]
 
fil/fil0crypt.cc:2355(fil_crypt_thread)[0x8a16e02]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0xb74c7d4c]
 
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb72d7ace]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file
 
----------SERVER LOG END-------------



 Comments   
Comment by Elena Stepanova [ 2017-08-18 ]

Local occurrence:

10.1 06106c01481

 
encryption.innodb-checksum-algorithm '8k,ctr,innodb_plugin' w6 [ fail ]
 
        Test ended at 2017-08-18 20:48:28
 
 
 
CURRENT_TEST: encryption.innodb-checksum-algorithm
 
mysqltest: At line 110: query 'ALTER TABLE tc_$checksum DISCARD TABLESPACE' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
restore: tc_crc32 .ibd and .cfg files
 
restore: te_crc32 .ibd and .cfg files
 
restore: t_crc32 .ibd and .cfg files
 
restore: tpe_crc32 .ibd and .cfg files
 
restore: tp_crc32 .ibd and .cfg files
 
ALTER TABLE tce_crc32 IMPORT TABLESPACE;
 
update tce_crc32 set b=substr(b,1);
 
ALTER TABLE tc_crc32 IMPORT TABLESPACE;
 
update tc_crc32 set b=substr(b,1);
 
ALTER TABLE te_crc32 IMPORT TABLESPACE;
 
update te_crc32 set b=substr(b,1);
 
ALTER TABLE t_crc32 IMPORT TABLESPACE;
 
update t_crc32 set b=substr(b,1);
 
ALTER TABLE tpe_crc32 IMPORT TABLESPACE;
 
update tpe_crc32 set b=substr(b,1);
 
ALTER TABLE tp_crc32 IMPORT TABLESPACE;
 
update tp_crc32 set b=substr(b,1);
 
SET GLOBAL innodb_checksum_algorithm=none;
 
ALTER TABLE tce_crc32 DISCARD TABLESPACE;
 
ALTER TABLE tc_crc32 DISCARD TABLESPACE;
 
...
 
2017-08-18 20:48:27 140298488044288 [Note] InnoDB: Sync to disk
 
2017-08-18 20:48:27 140298488044288 [Note] InnoDB: Sync to disk - done!
 
2017-08-18 20:48:27 140298488044288 [Note] InnoDB: Phase III - Flush changes to disk
 
2017-08-18 20:48:27 140298488044288 [Note] InnoDB: Phase IV - Flush complete
 
2017-08-18 20:48:27 140298488044288 [Note] InnoDB: "test"."tp_crc32" autoinc value set to 2


2017-08-18 20:48:27 140298046916352 [ERROR] InnoDB: Corruption: Block space_id 0 != page space_id 0 or Block offset 570 != page offset 0 
2017-08-18 20:48:27 7f99af3fc700  InnoDB: Assertion failure in thread 140298046916352 in file buf0buf.cc line 2865
 
InnoDB: Failing assertion: block->page.offset == page_get_page_no(page_align(ptr))
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170818 20:48:27 [ERROR] mysqld got signal 6 ;
 
#5  0x00007f99c75d33fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x00007f99c0a2581e in buf_block_align_instance (buf_pool=0x7f99c6c88478, ptr=0x7f99be680022 "") at /data/src/bb-10.1-elenst/storage/innobase/buf/buf0buf.cc:2864
 
#7  0x00007f99c0a25898 in buf_block_align (ptr=0x7f99be680022 "") at /data/src/bb-10.1-elenst/storage/innobase/buf/buf0buf.cc:2895
 
#8  0x00007f99c0b7f263 in mtr_memo_contains_page (mtr=0x7f99af3fb8b0, ptr=0x7f99be680022 "", type=2) at /data/src/bb-10.1-elenst/storage/innobase/mtr/mtr0mtr.cc:420
 
#9  0x00007f99c0b7b276 in mlog_write_initial_log_record_fast (ptr=0x7f99be680022 "", type=4 '\004', log_ptr=0x7f99af3fbb10 "\204", mtr=0x7f99af3fb8b0) at /data/src/bb-10.1-elenst/storage/innobase/include/mtr0log.ic:1
 
93
 
#10 0x00007f99c0b7c080 in mlog_write_ulint (ptr=0x7f99be680022 "", val=0, type=4 '\004', mtr=0x7f99af3fb8b0) at /data/src/bb-10.1-elenst/storage/innobase/mtr/mtr0log.cc:287
 
#11 0x00007f99c0aa816d in fil_crypt_rotate_page (key_state=0x7f99af3fbe00, state=0x7f99af3fbe10) at /data/src/bb-10.1-elenst/storage/innobase/fil/fil0crypt.cc:1870
 
#12 0x00007f99c0aa85b9 in fil_crypt_rotate_pages (key_state=0x7f99af3fbe00, state=0x7f99af3fbe10) at /data/src/bb-10.1-elenst/storage/innobase/fil/fil0crypt.cc:2003
 
#13 0x00007f99c0aa8d8c in fil_crypt_thread (arg=0x0) at /data/src/bb-10.1-elenst/storage/innobase/fil/fil0crypt.cc:2231
 
#14 0x00007f99c953c494 in start_thread (arg=0x7f99af3fc700) at pthread_create.c:333
 
#15 0x00007f99c768793f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Bootstrap log, error log, datadir.tar.gz mysqld.1.err.gz test.out bootstrap.log MTR stdout and the datadir are attached.

Comment by Marko Mäkelä [ 2017-08-21 ]

The local occurrence datadir.tar.gz looks awfully similar to the assertion failure that was reported in MDEV-12905.
We seem to have an all-zero page 0:570 in the buffer pool (at least its space id and page number fields are zero).
Indeed, in the attached ibdata1 file, all bytes from 0x470000 (page number 568) onwards are zero.
It seems to be clearly wrong to attempt to rotate the encryption key on an unused page that is filled with zero bytes.

Now, why does fil_crypt_rotate_page() write to tablespace 0 (the system tablespace)? It looks like this is intentional: many pages from 1 to 567 look like random noise, so they probably are encrypted. Several pages appear to still be in clear text: page 5 (bytes 0xa000‥0xbfff), page 26‥60 (0x34000‥0x79fff), 74‥76 (0x94000‥0x99fff) to name a few.

The bug seems to be a design flaw of the key rotation: InnoDB is rotating the encryption key on unused, unallocated pages, wasting resources.
I believe that the simplest course of action would be to modify fil_crypt_rotate_pages() so that it will skip unallocated pages. This would have the drawback that if the tablespace originally was unencrypted and some page was freed, the unencrypted free page would remain available in clear-text until the page is reused for something while encryption is enabled.

A more complex solution would involve zeroing out (or punching holes on) pages that are being freed. This would probably require a new redo log record type, and it could create extra I/O load. (While it could be considered bad practice to disclose to an attacker which pages are freed, we are already disclosing that information for the first innodb_page_size pages, because page 0 contains the allocation bitmap in unencrypted format.)

Comment by Marko Mäkelä [ 2017-08-21 ]

bb-10.2-marko
I am working on backporting the fix to 10.1.

Comment by Marko Mäkelä [ 2017-08-21 ]

bb-10.1-marko

Comment by Jan Lindström (Inactive) [ 2017-08-21 ]

Can you change the error logging I commented, otherwise ok to push.

Comment by Marko Mäkelä [ 2017-08-22 ]

After some discussion on instant messenger, I agree that we should keep applying key rotation to pages that have been freed. Only pages that were never allocated should remain so. If a page is found to be currently not in use, the key rotation can clear the page contents before encrypting it, for even better data protection.

After amending the 10.2 fix, I came to the conclusion that it might not be feasible to backport this fix to MariaDB 10.1 for now. The main reason is that 10.1 is missing some code refactoring that the patch depends on; for example, the fields fil_space_t::free_limit and fil_space_t::size_in_header are missing, and many functions do not take fil_space_t* as a parameter. Also, there were some test failures on bb-10.1-marko which I would not like to spend time analyzing.

Comment by Marko Mäkelä [ 2017-08-23 ]

I believe that it is feasible to fix this in 10.1 after all.
For 10.2, we can do some additional cleanup.
The actual fix is now brewing on bb-10.2-marko and bb-10.1-marko. The 10.1 fix is slightly smaller, and thus the key rotation in the 10.1 version will perform more unnecessary page reads.

Comment by Jan Lindström (Inactive) [ 2017-08-23 ]

ok to push both 10.1 and 10.2 versions.

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