[MDEV-13167] InnoDB key rotation is not skipping unused pages - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1(EOL)
Fix Version/s: 10.1.27, 10.2.9, 10.3.2
Component/s: Storage Engine - InnoDB, Tests
Labels:
None

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-------------

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

bootstrap.log
140 kB
2017-08-18 20:37
datadir.tar.gz
5.65 MB
2017-08-18 20:37
mysqld.1.err.gz
1.20 MB
2017-08-18 20:37
test.out
559 kB
2017-08-18 20:37

Issue Links

duplicates

MDEV-13586 [Draft] InnoDB: Failing assertion: block->page.offset == page_get_page_no(page_align(ptr))

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2017-08-18 20:38

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

#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.

Elena Stepanova added a comment - 2017-08-18 20:38 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.

Marko Mäkelä added a comment - 2017-08-21 07:14

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.)

Marko Mäkelä added a comment - 2017-08-21 07:14 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.)

Marko Mäkelä added a comment - 2017-08-21 08:50

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

Marko Mäkelä added a comment - 2017-08-21 08:50 bb-10.2-marko I am working on backporting the fix to 10.1.

Marko Mäkelä added a comment - 2017-08-21 09:42

bb-10.1-marko

Marko Mäkelä added a comment - 2017-08-21 09:42 bb-10.1-marko

Jan Lindström (Inactive) added a comment - 2017-08-21 10:50

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

Jan Lindström (Inactive) added a comment - 2017-08-21 10:50 Can you change the error logging I commented, otherwise ok to push.

Marko Mäkelä added a comment - 2017-08-22 19:13

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.

Marko Mäkelä added a comment - 2017-08-22 19:13 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.

Marko Mäkelä added a comment - 2017-08-23 07:48

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.

Marko Mäkelä added a comment - 2017-08-23 07:48 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.

Jan Lindström (Inactive) added a comment - 2017-08-23 08:15

ok to push both 10.1 and 10.2 versions.

Jan Lindström (Inactive) added a comment - 2017-08-23 08:15 ok to push both 10.1 and 10.2 versions.

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2017-06-24 17:41

Updated:: 2017-08-31 15:39

Resolved:: 2017-08-23 13:40

Git Integration

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

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration