[MDEV-8950] encryption.innodb_encryption_discard_import fails sporadically in buildbot Created: 2015-10-15  Updated: 2015-10-29  Resolved: 2015-10-29

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Tests
Affects Version/s: 10.1
Fix Version/s: 10.1.9

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

Issue Links:
Blocks
blocks MDEV-7069 Fix buildbot failures in main server ... Stalled
Sprint: 10.1.9-1

 Description   

encryption.innodb_encryption_discard_import fails sporadically in buildbot
https://internal.askmonty.org/buildbot/builders/kvm-deb-sid-x86/builds/1357/steps/test_4/logs/stdio

CURRENT_TEST: encryption.innodb_encryption_discard_import
mysqltest: At line 133: query 'ALTER TABLE t1 IMPORT TABLESPACE' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
ALTER TABLE t3 DISCARD TABLESPACE;
# Discarded tablespaces should be encrypted
# t1 yes on expecting NOT FOUND
NOT FOUND /foobar/ in t1.ibd
# t2 ... on expecting NOT FOUND
NOT FOUND /temp/ in t2.ibd
# t3 ... on expecting NOT FOUND
NOT FOUND /barfoo/ in t3.ibd
# List after t1 DISCARD
t1.frm
t2.frm
t3.frm
# Tablespaces should be still encrypted
# t1 yes on expecting NOT FOUND
NOT FOUND /foobar/ in t1.ibd
# t2 ... on expecting NOT FOUND
NOT FOUND /temp/ in t2.ibd
# t3 ... on expecting NOT FOUND
NOT FOUND /barfoo/ in t3.ibd
ALTER TABLE t1 IMPORT TABLESPACE;
 
More results from queries before failure can be found in /dev/shm/var/3/log/innodb_encryption_discard_import.log
 
 
Server [mysqld.1 - pid: 24957, winpid: 24957, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Sync to disk of '"test"."t1"' started.
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Stopping purge
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Writing table metadata to './test/t1.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Table '"test"."t1"' flushed to disk
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Sync to disk of '"test"."t2"' started.
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Writing table metadata to './test/t2.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Table '"test"."t2"' flushed to disk
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Sync to disk of '"test"."t3"' started.
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Writing table metadata to './test/t3.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Table '"test"."t3"' flushed to disk
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Deleting the meta-data file './test/t1.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Deleting the meta-data file './test/t2.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Deleting the meta-data file './test/t3.cfg'
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Resuming purge
2015-10-15  9:05:19 3068185408 [Note] /usr/sbin/mysqld: Normal shutdown
 
2015-10-15  9:05:19 3068185408 [Note] Event Scheduler: Purging the queue. 0 events
2015-10-15  9:05:19 2764045120 [Note] InnoDB: FTS optimize thread exiting.
2015-10-15  9:05:19 3068185408 [Note] InnoDB: Starting shutdown...
2015-10-15  9:05:20 3068185408 [Note] InnoDB: Shutdown completed; log sequence number 10268187
2015-10-15  9:05:20 3068185408 [Note] /usr/sbin/mysqld: Shutdown complete
 
2015-10-15  9:05:21 3068377088 [Note] /usr/sbin/mysqld (mysqld 10.1.8-MariaDB-1~sid-log) starting as process 24958 ...
2015-10-15  9:05:21 3068377088 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2015-10-15  9:05:21 3068377088 [Note] Plugin 'partition' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'SEQUENCE' is disabled.
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2015-10-15  9:05:21 3068377088 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Memory barrier is not used
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Using Linux native AIO
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Not using CPU crc32 instructions
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Initializing buffer pool, size = 8.0M
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Completed initialization of buffer pool
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-15  9:05:21 3068377088 [Note] InnoDB: 128 rollback segment(s) are active.
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Waiting for purge to start
2015-10-15  9:05:21 3068377088 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 10268187
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Creating #1 thread id 2755656512 total threads 4.
2015-10-15  9:05:21 2789206848 [Note] InnoDB: Dumping buffer pool(s) not yet started
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Creating #2 thread id 2747263808 total threads 4.
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Creating #3 thread id 2730490688 total threads 4.
2015-10-15  9:05:21 3068377088 [Note] InnoDB: Creating #4 thread id 2722097984 total threads 4.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'XTRADB_RSEG' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'FEEDBACK' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_CMP' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_CHANGED_PAGES' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2015-10-15  9:05:21 3068377088 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2015-10-15  9:05:21 3068377088 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2015-10-15  9:05:21 3068377088 [Note] Server socket created on IP: '127.0.0.1'.
2015-10-15  9:05:21 3068377088 [Note] Event Scheduler: Loaded 0 events
2015-10-15  9:05:21 3068377088 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.8-MariaDB-1~sid-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16060  mariadb.org binary distribution
2015-10-15  9:05:32 3067906880 [Note] InnoDB: Importing tablespace for table 'test/t1' that was exported from host 'debian-sid-i386'
2015-10-15  9:05:32 3067906880 [Note] InnoDB: Phase I - Update all pages
2015-10-15  9:05:32 3067906880 [Note] InnoDB: Sync to disk
2015-10-15  9:05:32 3067906880 [Note] InnoDB: Sync to disk - done!
InnoDB: Error: trying to access page number 0 in space 7,
InnoDB: space name test/t1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2015-10-15 09:05:32 a3bfeb40  InnoDB: Assertion failure in thread 2747263808 in file fil0fil.cc line 5820
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.
151015  9:05:32 [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 http://kb.askmonty.org/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.8-MariaDB-1~sid-log
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 = 61759 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0x0
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 0x48000
/usr/sbin/mysqld(my_print_stacktrace+0x28)[0x8090ac18]
/usr/sbin/mysqld(handle_fatal_signal+0x334)[0x80446114]
linux-gate.so.1(__kernel_sigreturn+0x0)[0xb7701bbc]
linux-gate.so.1(__kernel_vsyscall+0x10)[0xb7701be0]
/lib/i386-linux-gnu/i686/cmov/libc.so.6(gsignal+0x47)[0xb7041307]
/lib/i386-linux-gnu/i686/cmov/libc.so.6(abort+0x143)[0xb70429c3]
/usr/sbin/mysqld(+0x70b82b)[0x8074782b]
/usr/sbin/mysqld(+0x6ceb8f)[0x8070ab8f]
/usr/sbin/mysqld(+0x6cfba1)[0x8070bba1]
/usr/sbin/mysqld(+0x6b14db)[0x806ed4db]
/usr/sbin/mysqld(+0x716004)[0x80752004]
/lib/i386-linux-gnu/i686/cmov/libpthread.so.0(+0x6efb)[0xb76e0efb]
/lib/i386-linux-gnu/i686/cmov/libc.so.6(clone+0x5e)[0xb70fc66e]
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

Happens on different builds/builders. So far we could not reproduce it manually.



 Comments   
Comment by Jan Lindström (Inactive) [ 2015-10-28 ]

commit 1108c1ca5c1d71bb9ca39a463a4f0465b23350b6
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Oct 28 14:30:30 2015 +0200

MDEV-8950: encryption.innodb_encryption_discard_import fails sporadically in buildbot

At least some of the failures where due to fact that TMPDIR contained
old file.

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