[MDEV-13181] encryption.innodb-first-page-read sporadically fails in buildbot with signal 8 Created: 2017-06-26  Updated: 2017-08-31  Resolved: 2017-08-31

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

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-13557 Startup failure, unable to decrypt ib... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/work-amd64-valgrind/builds/10103/steps/test/logs/stdio

encryption.innodb-first-page-read 'ctr,xtradb' w2 [ fail ]
        Test ended at 2017-06-18 12:14:29
 
CURRENT_TEST: encryption.innodb-first-page-read
mysqltest: In included file "./include/wait_condition.inc": 
included from /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/suite/encryption/t/innodb-first-page-read.test at line 82:
At line 54: query 'let $success= `$wait_condition`' failed with wrong errno 2013: 'Lost connection to MySQL server during query', instead of 0...
 
The result from queries just before the failure was:
< snip >
insert into innodb_datadir1 select * from innodb_normal;
insert into innodb_datadir2 select * from innodb_normal;
insert into innodb_datadir3 select * from innodb_normal;
commit;
# Restart server and see how many page 0's are read
# result should be less than actual number of tables
# i.e. < 23 + 3 = 26
show status like 'innodb_pages0_read%';
Variable_name	Value
Innodb_pages0_read	19
use innodb_test;
show status like 'innodb_pages0_read%';
Variable_name	Value
Innodb_pages0_read	19
use test;
show status like 'innodb_pages0_read%';
Variable_name	Value
Innodb_pages0_read	19
set global innodb_encrypt_tables=OFF;
# wait until tables are decrypted
 
More results from queries before failure can be found in /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/2/log/innodb-first-page-read.log
 
 
Server [mysqld.1 - pid: 25583, winpid: 25583, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2017-06-18 12:13:29 68836096 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld: Normal shutdown
 
2017-06-18 12:13:30 68836096 [Note] Event Scheduler: Purging the queue. 0 events
2017-06-18 12:13:30 348886784 [Note] InnoDB: FTS optimize thread exiting.
2017-06-18 12:13:30 68836096 [Note] InnoDB: Starting shutdown...
2017-06-18 12:13:31 68836096 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2017-06-18 12:13:34 68836096 [Note] InnoDB: Shutdown completed; log sequence number 1748119
2017-06-18 12:13:34 68836096 [Note] Debug sync points hit:                   2937
2017-06-18 12:13:34 68836096 [Note] Debug sync points executed:              0
2017-06-18 12:13:34 68836096 [Note] Debug sync points max active per thread: 0
2017-06-18 12:13:34 68836096 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld: Shutdown complete
 
2017-06-18 12:13:39 67401408 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld (mysqld 10.1.25-MariaDB-debug) starting as process 25584 ...
2017-06-18 12:13:39 67401408 [Warning] Could not increase number of max_open_files to more than 1012 (request: 4162)
2017-06-18 12:13:40 67401408 [Note] Plugin 'partition' is disabled.
2017-06-18 12:13:40 67401408 [Note] Plugin 'SEQUENCE' is disabled.
2017-06-18 12:13:41 40476c0 InnoDB: Warning: Setting innodb_use_sys_malloc to FALSE is DEPRECATED. This option may be removed in future releases, together with the InnoDB's internal memory allocator.
innodb_open_files should not be greater than the open_files_limit.
2017-06-18 12:13:41 67401408 [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-18 12:13:41 67401408 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-06-18 12:13:41 67401408 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-06-18 12:13:41 67401408 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2017-06-18 12:13:41 67401408 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-06-18 12:13:41 67401408 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-06-18 12:13:41 67401408 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-06-18 12:13:41 67401408 [Note] InnoDB: Using Linux native AIO
2017-06-18 12:13:41 67401408 [Note] InnoDB: Using generic crc32 instructions
2017-06-18 12:13:41 67401408 [Note] InnoDB: Initializing buffer pool, size = 8.0M
2017-06-18 12:13:41 67401408 [Note] InnoDB: Completed initialization of buffer pool
2017-06-18 12:13:41 67401408 [Note] InnoDB: Highest supported file format is Barracuda.
2017-06-18 12:13:49 67401408 [Note] InnoDB: 128 rollback segment(s) are active.
2017-06-18 12:13:49 67401408 [Note] InnoDB: Waiting for purge to start
2017-06-18 12:13:49 67401408 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 1748119
2017-06-18 12:13:50 67401408 [Note] InnoDB: Creating #1 thread id 390850304 total threads 4.
2017-06-18 12:13:50 382457600 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-06-18 12:13:50 67401408 [Note] InnoDB: Creating #2 thread id 399243008 total threads 4.
2017-06-18 12:13:50 67401408 [Note] InnoDB: Creating #3 thread id 407635712 total threads 4.
2017-06-18 12:13:50 67401408 [Note] InnoDB: Creating #4 thread id 416028416 total threads 4.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'XTRADB_RSEG' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'FEEDBACK' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_CMP' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_CHANGED_PAGES' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-06-18 12:13:50 67401408 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-06-18 12:13:50 67401408 [Warning] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld: unknown option '--loose-pam-debug'
2017-06-18 12:13:51 67401408 [Note] Server socket created on IP: '127.0.0.1'.
2017-06-18 12:13:52 67401408 [Note] /mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld: ready for connections.
Version: '10.1.25-MariaDB-debug'  socket: '/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/tmp/2/mysqld.1.sock'  port: 16020  Source distribution
170618 12:14:27 [ERROR] mysqld got signal 8 ;
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 = 63032 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/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(my_print_stacktrace+0x38)[0xf23b51]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(handle_fatal_signal+0x38f)[0x86951d]
/lib64/libpthread.so.0(+0xf9f0)[0x4e439f0]
/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/sql/mysqld(+0xd6d8fe)[0xe758fe]
mysys/stacktrace.c:267(my_print_stacktrace)[0xe77405]
/lib64/libpthread.so.0(+0x80db)[0x4e3c0db]
/lib64/libc.so.6(clone+0x6d)[0x6b28e3d]
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-------------
 
 
 - skipping '/mnt/data/buildot/maria-slave/work-opensuse-amd64/build/mysql-test/var/2/log/encryption.innodb-first-page-read-ctr,xtradb/'
***Warnings generated in error logs during shutdown after running tests: encryption.innodb-first-page-read
 
170618 12:14:27 [ERROR] mysqld got signal 8 ;
Attempting backtrace. You can use the following information to find out



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

Fixed in MDEV-13557: Startup failure, unable to decrypt ibdata1

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