[MDEV-14058] InnoDB Assertion failure !leaf on rem0rec.cc line 566 on test innodb_gis.rtree_recovery Created: 2017-10-12  Updated: 2018-01-04  Resolved: 2018-01-04

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.10, 10.3.2
Fix Version/s: 10.3.4, 10.2.13

Type: Bug Priority: Major
Reporter: Jan Lindström (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-14218 rem0rec.cc:566: Assertion `!leaf' fai... Closed
relates to MDEV-14227 innodb_gis.rtree_compress2 '4k,16k,in... Closed

 Description   

Checkout branch bb-10.2-MDEV-13626

innodb_gis.rtree_recovery 'innodb'       [ fail ]
        Test ended at 2017-10-12 17:09:35
 
CURRENT_TEST: innodb_gis.rtree_recovery
 
 
Server [mysqld.1 - pid: 30049, winpid: 30049, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2017-10-12 17:09:31 139888212065536 [Note] /home/jan/mysql/10.2-orig/sql/mysqld (mysqld 10.2.10-MariaDB-debug-log) starting as process 29984 ...
2017-10-12 17:09:31 139888212065536 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'SEQUENCE' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'partition' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Uses event mutexes
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Using Linux native AIO
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Number of pools: 1
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Using SSE2 crc32 instructions
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Completed initialization of buffer pool
2017-10-12 17:09:31 139887940458240 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: Waiting for purge to start
2017-10-12 17:09:31 139888212065536 [Note] InnoDB: 5.7.19 started; log sequence number 1633766
2017-10-12 17:09:31 139887772669696 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/mysqld.1/data/ib_buffer_pool
2017-10-12 17:09:31 139887772669696 [Note] InnoDB: Buffer pool(s) load completed at 171012 17:09:31
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_CMP' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'FEEDBACK' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'user_variables' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-10-12 17:09:31 139888212065536 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-10-12 17:09:31 139888212065536 [Warning] /home/jan/mysql/10.2-orig/sql/mysqld: unknown option '--loose-pam-debug'
2017-10-12 17:09:31 139888212065536 [Note] Server socket created on IP: '127.0.0.1'.
2017-10-12 17:09:31 139888212065536 [Note] Reading of all Master_info entries succeded
2017-10-12 17:09:31 139888212065536 [Note] Added new Master_info '' to hash table
2017-10-12 17:09:31 139888212065536 [Note] /home/jan/mysql/10.2-orig/sql/mysqld: ready for connections.
Version: '10.2.10-MariaDB-debug-log'  socket: '/dev/shm/tmp/mysqld.1.sock'  port: 16000  Source distribution
2017-10-12 17:09:31 139888061196032 [Note] /home/jan/mysql/10.2-orig/sql/mysqld (root[root] @ localhost []): Normal shutdown
 
2017-10-12 17:09:31 139887814633216 [Note] InnoDB: FTS optimize thread exiting.
2017-10-12 17:09:31 139888061196032 [Note] Event Scheduler: Purging the queue. 0 events
2017-10-12 17:09:31 139888061196032 [Note] InnoDB: Starting shutdown...
2017-10-12 17:09:31 139887772669696 [Note] InnoDB: Dumping buffer pool(s) to /dev/shm/mysqld.1/data/ib_buffer_pool
2017-10-12 17:09:31 139887772669696 [Note] InnoDB: Instance 0, restricted to 128 pages due to innodb_buf_pool_dump_pct=25
2017-10-12 17:09:31 139887772669696 [Note] InnoDB: Buffer pool(s) dump completed at 171012 17:09:31
2017-10-12 17:09:33 139888061196032 [Note] InnoDB: Shutdown completed; log sequence number 1633785
2017-10-12 17:09:33 139888061196032 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-10-12 17:09:33 139888061196032 [Note] Debug sync points hit:                   917
2017-10-12 17:09:33 139888061196032 [Note] Debug sync points executed:              0
2017-10-12 17:09:33 139888061196032 [Note] Debug sync points max active per thread: 0
2017-10-12 17:09:33 139888061196032 [Note] /home/jan/mysql/10.2-orig/sql/mysqld: Shutdown complete
 
2017-10-12 17:09:34 139983246265600 [Note] /home/jan/mysql/10.2-orig/sql/mysqld (mysqld 10.2.10-MariaDB-debug-log) starting as process 30020 ...
2017-10-12 17:09:34 139983246265600 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'SEQUENCE' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'partition' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Uses event mutexes
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Using Linux native AIO
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Number of pools: 1
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Using SSE2 crc32 instructions
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Completed initialization of buffer pool
2017-10-12 17:09:34 139982975002368 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: Waiting for purge to start
2017-10-12 17:09:34 139983246265600 [Note] InnoDB: 5.7.19 started; log sequence number 1633785
2017-10-12 17:09:34 139982807213824 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/mysqld.1/data/ib_buffer_pool
2017-10-12 17:09:34 139982807213824 [Note] InnoDB: Buffer pool(s) load completed at 171012 17:09:34
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_CMP' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'FEEDBACK' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'user_variables' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-10-12 17:09:34 139983246265600 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-10-12 17:09:34 139983246265600 [Warning] /home/jan/mysql/10.2-orig/sql/mysqld: unknown option '--loose-pam-debug'
2017-10-12 17:09:34 139983246265600 [Note] Server socket created on IP: '127.0.0.1'.
2017-10-12 17:09:34 139983246265600 [Note] Reading of all Master_info entries succeded
2017-10-12 17:09:34 139983246265600 [Note] Added new Master_info '' to hash table
2017-10-12 17:09:34 139983246265600 [Note] /home/jan/mysql/10.2-orig/sql/mysqld: ready for connections.
Version: '10.2.10-MariaDB-debug-log'  socket: '/dev/shm/tmp/mysqld.1.sock'  port: 16000  Source distribution
2017-10-12 17:09:35 140284560018688 [Note] /home/jan/mysql/10.2-orig/sql/mysqld (mysqld 10.2.10-MariaDB-debug-log) starting as process 30050 ...
2017-10-12 17:09:35 140284560018688 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-10-12 17:09:35 140284560018688 [Note] Plugin 'SEQUENCE' is disabled.
2017-10-12 17:09:35 140284560018688 [Note] Plugin 'partition' is disabled.
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Uses event mutexes
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Using Linux native AIO
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Number of pools: 1
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Using SSE2 crc32 instructions
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Completed initialization of buffer pool
2017-10-12 17:09:35 140284285409024 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1633785
2017-10-12 17:09:35 140284560018688 [Note] InnoDB: Starting final batch to recover 19 pages from redo log.
mysqld: /home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc:566: ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**): Assertion `!leaf' failed.
171012 17:09:35 [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.2.10-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63097 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 0x49000
/home/jan/mysql/10.2-orig/sql/mysqld(my_print_stacktrace+0x38)[0x556bff2d2374]
/home/jan/mysql/10.2-orig/sql/mysqld(handle_fatal_signal+0x3a3)[0x556bfeb66352]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7f968b26f0c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7f9688a41fcf]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f9688a433fa]
/lib/x86_64-linux-gnu/libc.so.6(+0x2be37)[0x7f9688a3ae37]
/lib/x86_64-linux-gnu/libc.so.6(+0x2bee2)[0x7f9688a3aee2]
mysys/stacktrace.c:267(my_print_stacktrace)[0x556bfee6f5e7]
sql/signal_handler.cc:168(handle_fatal_signal)[0x556bfefbafed]
log/log0recv.cc:1293(recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*))[0x556bfee10956]
log/log0recv.cc:1804(recv_recover_page(bool, buf_block_t*))[0x556bfee1220f]
buf/buf0buf.cc:6026(buf_page_io_complete(buf_page_t*, bool))[0x556bfeff2309]
fil/fil0fil.cc:5340(fil_aio_wait(unsigned long))[0x556bff08054e]
srv/srv0start.cc:340(io_handler_thread)[0x556bfef26e87]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7494)[0x7f968b265494]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f9688af7aff]
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-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
create table t1 (c1 int, c2 geometry not null, spatial index (c2))engine=innodb;
create procedure insert_t1(IN total int)
begin
declare i int default 1;
while (i <= total) DO
insert into t1 values (i, Point(i, i));
set i = i + 1;
end while;
end|
create procedure update_t1(IN total int)
begin
declare i int default 1;
while (i <= total) DO
update t1 set c2 = Point(i + 10000, i + 10000) where c2 = Point(i, i);
set i = i + 1;
end while;
end|
CALL insert_t1(367);
COMMIT;
# Kill and restart
 
 
 
 - saving '/dev/shm/log/innodb_gis.rtree_recovery-innodb/' to '/dev/shm/log/innodb_gis.rtree_recovery-innodb/'
 - found 'core' (0/5)
 
Trying 'dbx' to get a backtrace
 
Trying 'gdb' to get a backtrace from coredump /dev/shm/log/innodb_gis.rtree_recovery-innodb/mysqld.1/data/core
Core generated by '/home/jan/mysql/10.2-orig/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New LWP 30054]
[New LWP 30050]
[New LWP 30052]
[New LWP 30053]
[New LWP 30055]
[New LWP 30059]
[New LWP 30051]
[New LWP 30056]
[New LWP 30057]
[New LWP 30058]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/home/jan/mysql/10.2-orig/sql/mysqld --defaults-group-suffix=.1 --defaults-file'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
57	../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f96814be700 (LWP 30054))]
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x0000556bff2d2466 in my_write_core (sig=6) at /home/jan/mysql/10.2-orig/mysys/stacktrace.c:477
#2  0x0000556bfeb666fe in handle_fatal_signal (sig=6) at /home/jan/mysql/10.2-orig/sql/signal_handler.cc:303
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f9688a433fa in __GI_abort () at abort.c:89
#6  0x00007f9688a3ae37 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x556bff4c7120 "!leaf", file=file@entry=0x556bff4c6ff8 "/home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc", line=line@entry=566, function=function@entry=0x556bff4c8400 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:92
#7  0x00007f9688a3aee2 in __GI___assert_fail (assertion=0x556bff4c7120 "!leaf", file=0x556bff4c6ff8 "/home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc", line=566, function=0x556bff4c8400 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:101
#8  0x0000556bfee6f5e7 in rec_get_offsets_func (rec=0x7f9682ea007e "", index=0x7f9670001668, offsets=0x0, leaf=true, n_fields=18446744073709551615, file=0x556bff540120 "/home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc", line=3489, heap=0x7f96814bcec8) at /home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc:566
#9  0x0000556bfefbafed in btr_cur_parse_update_in_place (ptr=0x7f9682a5018a "", end_ptr=0x7f9682a5018a "", page=0x7f9682ea0000 "", page_zip=0x0, index=0x7f9670001668) at /home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc:3489
#10 0x0000556bfee10956 in recv_parse_or_apply_log_rec_body (type=MLOG_COMP_REC_UPDATE_IN_PLACE, ptr=0x7f9682a50156 "\a", end_ptr=0x7f9682a5018a "", space_id=4, page_no=4, apply=true, block=0x7f9682928ef0, mtr=0x7f96814bd3d0) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:1293
#11 0x0000556bfee1220f in recv_recover_page (just_read_in=true, block=0x7f9682928ef0) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:1804
#12 0x0000556bfeff2309 in buf_page_io_complete (bpage=0x7f9682928ef0, evict=false) at /home/jan/mysql/10.2-orig/storage/innobase/buf/buf0buf.cc:6015
#13 0x0000556bff08054e in fil_aio_wait (segment=2) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5340
#14 0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9b0 <n+16>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#15 0x00007f968b265494 in start_thread (arg=0x7f96814be700) at pthread_create.c:333
#16 0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 10 (Thread 0x7f967affd700 (LWP 30058)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000556bfee34028 in os_event::wait (this=0x556c00afa350) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:166
#2  0x0000556bfee33a54 in os_event::wait_low (this=0x556c00afa350, reset_sig_count=4) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:336
#3  0x0000556bfee33dd1 in os_event_wait_low (event=0x556c00afa350, reset_sig_count=0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:535
#4  0x0000556bff00afc0 in buf_flush_page_cleaner_coordinator () at /home/jan/mysql/10.2-orig/storage/innobase/buf/buf0flu.cc:3158
#5  0x00007f968b265494 in start_thread (arg=0x7f967affd700) at pthread_create.c:333
#6  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 9 (Thread 0x7f967b7fe700 (LWP 30057)):
#0  0x00007f968a5e16ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x0000556bfee279d7 in LinuxAIOHandler::collect (this=0x7f967b7fdaa0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:1896
#2  0x0000556bfee27f0d in LinuxAIOHandler::poll (this=0x7f967b7fdaa0, m1=0x7f967b7fdb48, m2=0x7f967b7fdb50, request=0x7f967b7fdb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2041
#3  0x0000556bfee28087 in os_aio_linux_handler (global_segment=5, m1=0x7f967b7fdb48, m2=0x7f967b7fdb50, request=0x7f967b7fdb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2095
#4  0x0000556bfee2cacd in os_aio_handler (segment=5, m1=0x7f967b7fdb48, m2=0x7f967b7fdb50, request=0x7f967b7fdb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:5740
#5  0x0000556bff080376 in fil_aio_wait (segment=5) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5295
#6  0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9c8 <n+40>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#7  0x00007f968b265494 in start_thread (arg=0x7f967b7fe700) at pthread_create.c:333
#8  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 8 (Thread 0x7f967bfff700 (LWP 30056)):
#0  0x00007f968a5e16ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x0000556bfee279d7 in LinuxAIOHandler::collect (this=0x7f967bffeaa0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:1896
#2  0x0000556bfee27f0d in LinuxAIOHandler::poll (this=0x7f967bffeaa0, m1=0x7f967bffeb48, m2=0x7f967bffeb50, request=0x7f967bffeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2041
#3  0x0000556bfee28087 in os_aio_linux_handler (global_segment=4, m1=0x7f967bffeb48, m2=0x7f967bffeb50, request=0x7f967bffeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2095
#4  0x0000556bfee2cacd in os_aio_handler (segment=4, m1=0x7f967bffeb48, m2=0x7f967bffeb50, request=0x7f967bffeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:5740
#5  0x0000556bff080376 in fil_aio_wait (segment=4) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5295
#6  0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9c0 <n+32>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#7  0x00007f968b265494 in start_thread (arg=0x7f967bfff700) at pthread_create.c:333
#8  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 7 (Thread 0x7f9683f26700 (LWP 30051)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x0000556bff2d7cee in safe_cond_timedwait (cond=0x556c006bc3a0 <COND_timer>, mp=0x556c006bc2e0 <LOCK_timer>, abstime=0x7f9683f25d30, file=0x556bff610dd0 "/home/jan/mysql/10.2-orig/include/mysql/psi/mysql_thread.h", line=1175) at /home/jan/mysql/10.2-orig/mysys/thr_mutex.c:545
#2  0x0000556bff2d8c63 in inline_mysql_cond_timedwait (that=0x556c006bc3a0 <COND_timer>, mutex=0x556c006bc2e0 <LOCK_timer>, abstime=0x7f9683f25d30, src_file=0x556bff610e10 "/home/jan/mysql/10.2-orig/mysys/thr_timer.c", src_line=292) at /home/jan/mysql/10.2-orig/include/mysql/psi/mysql_thread.h:1175
#3  0x0000556bff2d9770 in timer_handler (arg=0x0) at /home/jan/mysql/10.2-orig/mysys/thr_timer.c:292
#4  0x0000556bff278753 in pfs_spawn_thread (arg=0x556c00969700) at /home/jan/mysql/10.2-orig/storage/perfschema/pfs.cc:1862
#5  0x00007f968b265494 in start_thread (arg=0x7f9683f26700) at pthread_create.c:333
#6  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 6 (Thread 0x7f967a7fc700 (LWP 30059)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
#1  0x0000556bfee338be in os_event::timed_wait (this=0x556c009da120, abstime=0x7f967a7fbd10) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:286
#2  0x0000556bfee33bf2 in os_event::wait_time_low (this=0x556c009da120, time_in_usec=100000, reset_sig_count=1) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:413
#3  0x0000556bfee33dac in os_event_wait_time_low (event=0x556c009da120, time_in_usec=100000, reset_sig_count=1) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0event.cc:518
#4  0x0000556bfee0e1af in recv_writer_thread (arg=0x0) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:530
#5  0x00007f968b265494 in start_thread (arg=0x7f967a7fc700) at pthread_create.c:333
#6  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 5 (Thread 0x7f9680cbd700 (LWP 30055)):
#0  0x00007f968a5e16ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x0000556bfee279d7 in LinuxAIOHandler::collect (this=0x7f9680cbcaa0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:1896
#2  0x0000556bfee27f0d in LinuxAIOHandler::poll (this=0x7f9680cbcaa0, m1=0x7f9680cbcb48, m2=0x7f9680cbcb50, request=0x7f9680cbcb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2041
#3  0x0000556bfee28087 in os_aio_linux_handler (global_segment=3, m1=0x7f9680cbcb48, m2=0x7f9680cbcb50, request=0x7f9680cbcb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2095
#4  0x0000556bfee2cacd in os_aio_handler (segment=3, m1=0x7f9680cbcb48, m2=0x7f9680cbcb50, request=0x7f9680cbcb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:5740
#5  0x0000556bff080376 in fil_aio_wait (segment=3) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5295
#6  0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9b8 <n+24>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#7  0x00007f968b265494 in start_thread (arg=0x7f9680cbd700) at pthread_create.c:333
#8  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 4 (Thread 0x7f9681cbf700 (LWP 30053)):
#0  0x00007f968a5e16ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x0000556bfee279d7 in LinuxAIOHandler::collect (this=0x7f9681cbeaa0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:1896
#2  0x0000556bfee27f0d in LinuxAIOHandler::poll (this=0x7f9681cbeaa0, m1=0x7f9681cbeb48, m2=0x7f9681cbeb50, request=0x7f9681cbeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2041
#3  0x0000556bfee28087 in os_aio_linux_handler (global_segment=1, m1=0x7f9681cbeb48, m2=0x7f9681cbeb50, request=0x7f9681cbeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2095
#4  0x0000556bfee2cacd in os_aio_handler (segment=1, m1=0x7f9681cbeb48, m2=0x7f9681cbeb50, request=0x7f9681cbeb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:5740
#5  0x0000556bff080376 in fil_aio_wait (segment=1) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5295
#6  0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9a8 <n+8>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#7  0x00007f968b265494 in start_thread (arg=0x7f9681cbf700) at pthread_create.c:333
#8  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 3 (Thread 0x7f96824c0700 (LWP 30052)):
#0  0x00007f968a5e16ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x0000556bfee279d7 in LinuxAIOHandler::collect (this=0x7f96824bfaa0) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:1896
#2  0x0000556bfee27f0d in LinuxAIOHandler::poll (this=0x7f96824bfaa0, m1=0x7f96824bfb48, m2=0x7f96824bfb50, request=0x7f96824bfb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2041
#3  0x0000556bfee28087 in os_aio_linux_handler (global_segment=0, m1=0x7f96824bfb48, m2=0x7f96824bfb50, request=0x7f96824bfb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:2095
#4  0x0000556bfee2cacd in os_aio_handler (segment=0, m1=0x7f96824bfb48, m2=0x7f96824bfb50, request=0x7f96824bfb80) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0file.cc:5740
#5  0x0000556bff080376 in fil_aio_wait (segment=0) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5295
#6  0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9a0 <n>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#7  0x00007f968b265494 in start_thread (arg=0x7f96824c0700) at pthread_create.c:333
#8  0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 2 (Thread 0x7f968b5e0d00 (LWP 30050)):
#0  0x00007f968b26e7dd in nanosleep () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000556bfee34348 in os_thread_sleep (tm=500000) at /home/jan/mysql/10.2-orig/storage/innobase/os/os0thread.cc:230
#2  0x0000556bfee12dac in recv_apply_hashed_log_recs (last_batch=true) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:2028
#3  0x0000556bfef2cb1f in innobase_start_or_create_for_mysql () at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:2264
#4  0x0000556bfed6a040 in innobase_init (p=0x556c0099a860) at /home/jan/mysql/10.2-orig/storage/innobase/handler/ha_innodb.cc:4362
#5  0x0000556bfeb683a5 in ha_initialize_handlerton (plugin=0x556c0096d918) at /home/jan/mysql/10.2-orig/sql/handler.cc:520
#6  0x0000556bfe91301d in plugin_initialize (tmp_root=0x7ffd9ce598e0, plugin=0x556c0096d918, argc=0x556bffe2e670 <remaining_argc>, argv=0x556c00824160, options_only=false) at /home/jan/mysql/10.2-orig/sql/sql_plugin.cc:1413
#7  0x0000556bfe913c3a in plugin_init (argc=0x556bffe2e670 <remaining_argc>, argv=0x556c00824160, flags=2) at /home/jan/mysql/10.2-orig/sql/sql_plugin.cc:1694
#8  0x0000556bfe8207e6 in init_server_components () at /home/jan/mysql/10.2-orig/sql/mysqld.cc:5277
#9  0x0000556bfe82187f in mysqld_main (argc=144, argv=0x556c00824160) at /home/jan/mysql/10.2-orig/sql/mysqld.cc:5869
#10 0x0000556bfe8165b0 in main (argc=22, argv=0x7ffd9ce5a678) at /home/jan/mysql/10.2-orig/sql/main.cc:25
 
Thread 1 (Thread 0x7f96814be700 (LWP 30054)):
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x0000556bff2d2466 in my_write_core (sig=6) at /home/jan/mysql/10.2-orig/mysys/stacktrace.c:477
#2  0x0000556bfeb666fe in handle_fatal_signal (sig=6) at /home/jan/mysql/10.2-orig/sql/signal_handler.cc:303
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f9688a433fa in __GI_abort () at abort.c:89
#6  0x00007f9688a3ae37 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x556bff4c7120 "!leaf", file=file@entry=0x556bff4c6ff8 "/home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc", line=line@entry=566, function=function@entry=0x556bff4c8400 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:92
#7  0x00007f9688a3aee2 in __GI___assert_fail (assertion=0x556bff4c7120 "!leaf", file=0x556bff4c6ff8 "/home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc", line=566, function=0x556bff4c8400 <rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)::__PRETTY_FUNCTION__> "ulint* rec_get_offsets_func(const rec_t*, const dict_index_t*, ulint*, bool, ulint, const char*, unsigned int, mem_heap_t**)") at assert.c:101
#8  0x0000556bfee6f5e7 in rec_get_offsets_func (rec=0x7f9682ea007e "", index=0x7f9670001668, offsets=0x0, leaf=true, n_fields=18446744073709551615, file=0x556bff540120 "/home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc", line=3489, heap=0x7f96814bcec8) at /home/jan/mysql/10.2-orig/storage/innobase/rem/rem0rec.cc:566
#9  0x0000556bfefbafed in btr_cur_parse_update_in_place (ptr=0x7f9682a5018a "", end_ptr=0x7f9682a5018a "", page=0x7f9682ea0000 "", page_zip=0x0, index=0x7f9670001668) at /home/jan/mysql/10.2-orig/storage/innobase/btr/btr0cur.cc:3489
#10 0x0000556bfee10956 in recv_parse_or_apply_log_rec_body (type=MLOG_COMP_REC_UPDATE_IN_PLACE, ptr=0x7f9682a50156 "\a", end_ptr=0x7f9682a5018a "", space_id=4, page_no=4, apply=true, block=0x7f9682928ef0, mtr=0x7f96814bd3d0) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:1293
#11 0x0000556bfee1220f in recv_recover_page (just_read_in=true, block=0x7f9682928ef0) at /home/jan/mysql/10.2-orig/storage/innobase/log/log0recv.cc:1804
#12 0x0000556bfeff2309 in buf_page_io_complete (bpage=0x7f9682928ef0, evict=false) at /home/jan/mysql/10.2-orig/storage/innobase/buf/buf0buf.cc:6015
#13 0x0000556bff08054e in fil_aio_wait (segment=2) at /home/jan/mysql/10.2-orig/storage/innobase/fil/fil0fil.cc:5340
#14 0x0000556bfef26e87 in io_handler_thread (arg=0x556bffe9a9b0 <n+16>) at /home/jan/mysql/10.2-orig/storage/innobase/srv/srv0start.cc:343
#15 0x00007f968b265494 in start_thread (arg=0x7f96814be700) at pthread_create.c:333
#16 0x00007f9688af7aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 12 seconds executing testcases
 
Failure: Failed 1/1 tests, 0.00% were successful.
 
Failing test(s): innodb_gis.rtree_recovery
 
The log files in var/log may give you some hint of what went wrong.
 
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
mysql-test-run: *** ERROR: there were failing test cases



 Comments   
Comment by Marko Mäkelä [ 2018-01-04 ]

In 10.2, this was only a debug assertion failure. I added the debug assertion in 10.2 in order to improve the test coverage of the assumptions that I made in MDEV-11369.
In 10.3.2+ this could actually break the crash recovery of SPATIAL INDEX operations.

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