encryption.innodb-compressed-blob failed in buildbot, assertion in btr0cur.cc line 1398

encryption.innodb-compressed-blob '16k,ctr,innodb,none' w1 [ fail ]

        Test ended at 2017-11-24 17:32:49

CURRENT_TEST: encryption.innodb-compressed-blob

Server [mysqld.1 - pid: 14642, winpid: 14642, exit: 256] failed during test run

Server log from this test:

----------SERVER LOG START-----------

2017-11-24 17:32:42 0 [Note] /usr/sbin/mysqld (mysqld 10.3.3-MariaDB-log) starting as process 14403 ...

2017-11-24 17:32:42 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)

2017-11-24 17:32:43 0 [Note] Plugin 'partition' is disabled.

2017-11-24 17:32:43 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-11-24 17:32:43 0 [Note] InnoDB: Uses event mutexes

2017-11-24 17:32:43 0 [Note] InnoDB: Compressed tables use zlib 1.2.7

2017-11-24 17:32:43 0 [Note] InnoDB: Using Linux native AIO

2017-11-24 17:32:43 0 [Note] InnoDB: Number of pools: 1

2017-11-24 17:32:43 0 [Note] InnoDB: Using generic crc32 instructions

2017-11-24 17:32:43 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M

2017-11-24 17:32:43 0 [Note] InnoDB: Completed initialization of buffer pool

2017-11-24 17:32:43 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2017-11-24 17:32:43 0 [Note] InnoDB: 128 out of 128 rollback segments are active.

2017-11-24 17:32:43 0 [Note] InnoDB: Creating shared tablespace for temporary tables

2017-11-24 17:32:43 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2017-11-24 17:32:43 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

2017-11-24 17:32:43 0 [Note] InnoDB: Waiting for purge to start

2017-11-24 17:32:43 0 [Note] InnoDB: 5.7.20 started; log sequence number 1635112

2017-11-24 17:32:43 0 [Note] InnoDB: Creating #1 encryption thread id 140415768459008 total threads 4.

2017-11-24 17:32:43 0 [Note] InnoDB: Creating #2 encryption thread id 140415760066304 total threads 4.

2017-11-24 17:32:43 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/1/mysqld.1/data/ib_buffer_pool

2017-11-24 17:32:43 0 [Note] InnoDB: Creating #3 encryption thread id 140415751673600 total threads 4.

2017-11-24 17:32:43 0 [Note] InnoDB: Creating #4 encryption thread id 140415743280896 total threads 4.

2017-11-24 17:32:43 0 [Note] InnoDB: Buffer pool(s) load completed at 171124 17:32:43

2017-11-24 17:32:43 0 [Note] Plugin 'SEQUENCE' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_CMP' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'FEEDBACK' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'user_variables' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.

2017-11-24 17:32:43 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.

2017-11-24 17:32:43 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'

2017-11-24 17:32:43 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'

2017-11-24 17:32:43 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'

2017-11-24 17:32:43 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'

2017-11-24 17:32:43 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'

2017-11-24 17:32:43 0 [Note] Server socket created on IP: '127.0.0.1'.

2017-11-24 17:32:43 0 [Note] Reading of all Master_info entries succeded

2017-11-24 17:32:43 0 [Note] Added new Master_info '' to hash table

2017-11-24 17:32:43 0 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.3.3-MariaDB-log'  socket: '/dev/shm/var/tmp/1/mysqld.1.sock'  port: 16060  MariaDB Server

2017-11-24 17:32:43 0 [Note] /usr/sbin/mysqld (root[root] @ localhost []): Normal shutdown

2017-11-24 17:32:43 0 [Note] Event Scheduler: Purging the queue. 0 events

2017-11-24 17:32:43 0 [Note] InnoDB: FTS optimize thread exiting.

2017-11-24 17:32:43 0 [Note] InnoDB: Starting shutdown...

2017-11-24 17:32:43 0 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/var/1/mysqld.1/data/ib_buffer_pool

2017-11-24 17:32:43 0 [Note] InnoDB: Instance 0, restricted to 128 pages due to innodb_buf_pool_dump_pct=25

2017-11-24 17:32:43 0 [Note] InnoDB: Buffer pool(s) dump completed at 171124 17:32:43

2017-11-24 17:32:44 0 [Note] InnoDB: Shutdown completed; log sequence number 1635131

2017-11-24 17:32:44 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

2017-11-24 17:32:44 0 [Note] /usr/sbin/mysqld: Shutdown complete

2017-11-24 17:32:45 0 [Note] /usr/sbin/mysqld (mysqld 10.3.3-MariaDB-log) starting as process 14524 ...

2017-11-24 17:32:45 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)

2017-11-24 17:32:45 0 [Note] Plugin 'partition' is disabled.

2017-11-24 17:32:45 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-11-24 17:32:45 0 [Note] InnoDB: Uses event mutexes

2017-11-24 17:32:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.7

2017-11-24 17:32:45 0 [Note] InnoDB: Using Linux native AIO

2017-11-24 17:32:45 0 [Note] InnoDB: Number of pools: 1

2017-11-24 17:32:45 0 [Note] InnoDB: Using generic crc32 instructions

2017-11-24 17:32:45 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M

2017-11-24 17:32:45 0 [Note] InnoDB: Completed initialization of buffer pool

2017-11-24 17:32:45 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2017-11-24 17:32:45 0 [Note] InnoDB: 128 out of 128 rollback segments are active.

2017-11-24 17:32:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables

2017-11-24 17:32:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2017-11-24 17:32:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

2017-11-24 17:32:45 0 [Note] InnoDB: Waiting for purge to start

2017-11-24 17:32:46 0 [Note] InnoDB: 5.7.20 started; log sequence number 1635131

2017-11-24 17:32:46 0 [Note] InnoDB: Creating #1 encryption thread id 139958195046144 total threads 4.

2017-11-24 17:32:46 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/1/mysqld.1/data/ib_buffer_pool

2017-11-24 17:32:46 0 [Note] InnoDB: Creating #2 encryption thread id 139958186653440 total threads 4.

2017-11-24 17:32:46 0 [Note] InnoDB: Creating #3 encryption thread id 139958178260736 total threads 4.

2017-11-24 17:32:46 0 [Note] InnoDB: Creating #4 encryption thread id 139958169868032 total threads 4.

2017-11-24 17:32:46 0 [Note] InnoDB: Buffer pool(s) load completed at 171124 17:32:46

2017-11-24 17:32:46 0 [Note] Plugin 'SEQUENCE' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_CMP' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'FEEDBACK' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'user_variables' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.

2017-11-24 17:32:46 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.

2017-11-24 17:32:46 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'

2017-11-24 17:32:46 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'

2017-11-24 17:32:46 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'

2017-11-24 17:32:46 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'

2017-11-24 17:32:46 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'

2017-11-24 17:32:46 0 [Note] Server socket created on IP: '127.0.0.1'.

2017-11-24 17:32:46 0 [Note] Reading of all Master_info entries succeded

2017-11-24 17:32:46 0 [Note] Added new Master_info '' to hash table

2017-11-24 17:32:46 0 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.3.3-MariaDB-log'  socket: '/dev/shm/var/tmp/1/mysqld.1.sock'  port: 16060  MariaDB Server

2017-11-24 17:32:46 0 [Note] /usr/sbin/mysqld (root[root] @ localhost []): Normal shutdown

2017-11-24 17:32:46 0 [Note] Event Scheduler: Purging the queue. 0 events

2017-11-24 17:32:46 0 [Note] InnoDB: FTS optimize thread exiting.

2017-11-24 17:32:46 0 [Note] InnoDB: Starting shutdown...

2017-11-24 17:32:46 0 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/var/1/mysqld.1/data/ib_buffer_pool

2017-11-24 17:32:46 0 [Note] InnoDB: Instance 0, restricted to 128 pages due to innodb_buf_pool_dump_pct=25

2017-11-24 17:32:46 0 [Note] InnoDB: Buffer pool(s) dump completed at 171124 17:32:46

2017-11-24 17:32:47 0 [Note] InnoDB: Shutdown completed; log sequence number 1675340

2017-11-24 17:32:47 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

2017-11-24 17:32:47 0 [Note] /usr/sbin/mysqld: Shutdown complete

2017-11-24 17:32:48 0 [Note] /usr/sbin/mysqld (mysqld 10.3.3-MariaDB-log) starting as process 14643 ...

2017-11-24 17:32:48 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)

2017-11-24 17:32:48 0 [Note] Plugin 'partition' is disabled.

2017-11-24 17:32:48 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-11-24 17:32:48 0 [Note] InnoDB: Uses event mutexes

2017-11-24 17:32:48 0 [Note] InnoDB: Compressed tables use zlib 1.2.7

2017-11-24 17:32:48 0 [Note] InnoDB: Using Linux native AIO

2017-11-24 17:32:48 0 [Note] InnoDB: Number of pools: 1

2017-11-24 17:32:48 0 [Note] InnoDB: Using generic crc32 instructions

2017-11-24 17:32:48 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M

2017-11-24 17:32:48 0 [Note] InnoDB: Completed initialization of buffer pool

2017-11-24 17:32:48 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2017-11-24 17:32:48 0 [Note] InnoDB: 128 out of 128 rollback segments are active.

2017-11-24 17:32:48 0 [Note] InnoDB: Creating shared tablespace for temporary tables

2017-11-24 17:32:48 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2017-11-24 17:32:48 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

2017-11-24 17:32:48 0 [Note] InnoDB: Waiting for purge to start

2017-11-24 17:32:48 3 [ERROR] InnoDB: Unable to decompress ./test/t1.ibd[page id: space=4, page number=3]

2017-11-24 17:32:48 3 [Note] InnoDB: Row compressed page could be encrypted with key_version 1

2017-11-24 17:32:48 0x7fcb8a7fc700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.3/storage/innobase/btr/btr0cur.cc line 1398

InnoDB: We intentionally generate a memory trap.

InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

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.7/en/forcing-innodb-recovery.html

InnoDB: about forcing recovery.

171124 17:32:48 [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.3.3-MariaDB-log

key_buffer_size=1048576

read_buffer_size=131072

max_used_connections=0

max_threads=153

thread_count=4

It is possible that mysqld could use up to 

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63060 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fcb740009a8

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 = 0x7fcb8a7fbbe0 thread_stack 0x49000

2017-11-24 17:32:48 2 [ERROR] InnoDB: Unable to decompress ./test/t2.ibd[page id: space=5, page number=3]

2017-11-24 17:32:48 2 [Note] InnoDB: Row compressed page could be encrypted with key_version 1

2017-11-24 17:32:48 0x7fcb8affd700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.3/storage/innobase/btr/btr0cur.cc line 1398

InnoDB: We intentionally generate a memory trap.

InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

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.7/en/forcing-innodb-recovery.html

InnoDB: about forcing recovery.

----------SERVER LOG END-------------

mysqltest failed but provided no output

The result from queries just before the failure was:

< snip >

call mtr.add_suppression("InnoDB: The page \\[page id: space=[1-9][0-9]*, page number=[1-9][0-9]*\\] in file '.*test.t[123]\\.ibd' cannot be decrypted\\.");

call mtr.add_suppression("InnoDB: Unable to decompress ..test.t[1-3]\\.ibd\\[page id: space=[1-9][0-9]*, page number=[0-9]+\\]");

# Restart mysqld --file-key-management-filename=keys2.txt

SET GLOBAL innodb_file_per_table = ON;

set GLOBAL innodb_default_encryption_key_id=4;

create table t1(a int not null primary key, b blob, index(b(10))) engine=innodb row_format=compressed;

create table t2(a int not null primary key, b blob, index(b(10))) engine=innodb row_format=compressed encrypted=yes;

create table t3(a int not null primary key, b blob, index(b(10))) engine=innodb row_format=compressed encrypted=no;

insert into t1 values (1, repeat('secret',6000));

insert into t2 values (1, repeat('secret',6000));

insert into t3 values (1, repeat('secret',6000));

# Restart mysqld --file-key-management-filename=keys3.txt