Bug #75913 InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)

Description:
2015-02-06T23:09:43.443935Z 5 [ERROR] Invalid (old?) table or database name '@'
2015-02-07 10:09:43 0x7fe8bc004700  InnoDB: Assertion failure in thread 140637563275008 in file btr0cur.cc line 1239
InnoDB: Failing assertion: (fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)

How to repeat:
This assertion can be triggered with the testcase from bug 74876;

DROP DATABASE transforms;CREATE DATABASE transforms;DROP DATABASE test;CREATE DATABASE test;USE test;
DELETE FROM mysql.innodb_table_stats WHERE table_name = 'test_ps_fetch_nonexistent';
create TABLE t1 (a int not null);
DROP TABLE t1;
SET @start_global_value = @@global.auto_increment_offset;
ALTER TABLE t1 ADD c4 NUMERIC NOT NULL AFTER c2;
CREATE TABLE mytable_ref (id int,constraint FOREIGN KEY (id) REFERENCES FOO(id) ON DELETE CASCADE) ENGINE=innodb;
SET @@global.innodb_trx_rseg_n_slots_debug = @start_global_value;
INSERT INTO t1  VALUES (INET6_ATON('1.2.3.4')), (INET6_ATON('255.255.255.255')), (INET6_ATON('::1.2.3.4')), (INET6_ATON('::ffff:255.255.255.255')), (INET6_ATON('::')), (INET6_ATON('::1')), (INET6_ATON('1020:3040:5060:7080:90A0:B0C0:D0E0:F010'));
SET GLOBAL innodb_file_per_table=0;
INSERT INTO t1 VALUES ('00:00:01.000012'); ;

However, you would have to run the testcase many times to trigger the bug (I think, not verfied) - usually it seems to trigger bug 74876 instead.

(gdb) bt
#0  0x00007fe8bba4c771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000e15e08 in my_write_core (sig=6) at /bzr/mysql-5.7-percona-patches_dbg/mysys/stacktrace.c:247
#2  0x00000000008220f4 in handle_fatal_signal (sig=6) at /bzr/mysql-5.7-percona-patches_dbg/sql/signal_handler.cc:219
#3  <signal handler called>
#4  0x00007fe8ba6505c9 in raise () from /lib64/libc.so.6
#5  0x00007fe8ba651cd8 in abort () from /lib64/libc.so.6
#6  0x00000000010d538b in ut_dbg_assertion_failed (expr=0x14f63e8 "(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)", file=0x14f59a8 "/bzr/mysql-5.7-percona-patches_dbg/storage/innobase/btr/btr0cur.cc", line=1239) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/ut/ut0dbg.cc:68
#7  0x00000000011014d5 in btr_cur_search_to_nth_level (index=0x7fe769b77898, level=0, tuple=0x7fe769b56298, mode=4, latch_mode=2, cursor=0x7fe8bc000ab0, has_search_latch=0, file=0x14b9d30 "/bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc", line=2372, mtr=0x7fe8bc000ec0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/btr/btr0cur.cc:1239
#8  0x0000000000ffac38 in btr_pcur_open_low (index=0x7fe769b77898, level=0, tuple=0x7fe769b56298, mode=4, latch_mode=2, cursor=0x7fe8bc000ab0, file=0x14b9d30 "/bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc", line=2372, mtr=0x7fe8bc000ec0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/include/btr0pcur.ic:455
#9  0x0000000000fffc2e in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7fe769b77898, n_uniq=0, entry=0x7fe769b56298, n_ext=0, thr=0x7fe76a90f7d0, dup_chk_only=false) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:2372
#10 0x0000000001001f14 in row_ins_clust_index_entry (index=0x7fe769b77898, entry=0x7fe769b56298, thr=0x7fe76a90f7d0, n_ext=0, dup_chk_only=false) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:3182
#11 0x00000000010023a9 in row_ins_index_entry (index=0x7fe769b77898, entry=0x7fe769b56298, thr=0x7fe76a90f7d0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:3306
#12 0x000000000100280b in row_ins_index_entry_step (node=0x7fe76a90f588, thr=0x7fe76a90f7d0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:3448
#13 0x0000000001002b9c in row_ins (node=0x7fe76a90f588, thr=0x7fe76a90f7d0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:3590
#14 0x00000000010030f9 in row_ins_step (thr=0x7fe76a90f7d0) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0ins.cc:3762
#15 0x000000000101e1cd in row_insert_for_mysql_using_ins_graph (mysql_rec=0x7fe769b75338 <incomplete sequence \375>, prebuilt=0x7fe76a90f098) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0mysql.cc:1579
#16 0x000000000101e51c in row_insert_for_mysql (mysql_rec=0x7fe769b75338 <incomplete sequence \375>, prebuilt=0x7fe76a90f098) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/row/row0mysql.cc:1695
#17 0x0000000000f11c26 in ha_innobase::write_row (this=0x7fe769b75020, record=0x7fe769b75338 <incomplete sequence \375>) at /bzr/mysql-5.7-percona-patches_dbg/storage/innobase/handler/ha_innodb.cc:6785
#18 0x000000000088cb6a in handler::ha_write_row (this=0x7fe769b75020, buf=0x7fe769b75338 <incomplete sequence \375>) at /bzr/mysql-5.7-percona-patches_dbg/sql/handler.cc:7423
#19 0x0000000000d1aa35 in write_record (thd=0x7fe76981c000, table=0x7fe7716cb210, info=0x7fe8bc001960, update=0x7fe8bc0019e0) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_insert.cc:1679
#20 0x0000000000d183a9 in mysql_insert (thd=0x7fe76981c000, table_list=0x7fe769827970, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_insert.cc:707
#21 0x0000000000b49d85 in mysql_execute_command (thd=0x7fe76981c000) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:3367
#22 0x0000000000b4fd71 in mysql_parse (thd=0x7fe76981c000, parser_state=0x7fe8bc002e60) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:5427
#23 0x0000000000b448c4 in dispatch_command (command=COM_QUERY, thd=0x7fe76981c000, packet=0x7fe76a944011 "INSERT INTO t1 VALUES ('00:00:01.000012');", packet_length=42) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:1250
#24 0x0000000000b435fd in do_command (thd=0x7fe76981c000) at /bzr/mysql-5.7-percona-patches_dbg/sql/sql_parse.cc:834
#25 0x0000000000c4d54e in handle_connection (arg=0x7fe89d7fff00) at /bzr/mysql-5.7-percona-patches_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#26 0x0000000000e395e8 in pfs_spawn_thread (arg=0x7fe89dff9290) at /bzr/mysql-5.7-percona-patches_dbg/storage/perfschema/pfs.cc:2137
#27 0x00007fe8bba47df3 in start_thread () from /lib64/libpthread.so.0
#28 0x00007fe8ba7111ad in clone () from /lib64/libc.so.6

Adding a semi-testcase. Reducer script seems best at reproducing this.

$ ./reducer_hacked_for_bug75913.sh  # Make sure bug75913.sql is in the same directory. (This file has a number of DUMMY SELECTs added.)
[...various output...]
2015-02-16 16:46:26 [Init] Number of lines in input file: 24
2015-02-16 16:46:26 [] [Stage V] Verifying the bug/issue exists and is reproducible by reducer (duration depends on initial input file size)
[...]
2015-02-16 16:47:43 [*] [Stage 1] [Trial 2] Now filtering line(s) 14 to 18 (Current chunk size: 5)
./reducer_hacked_for_bug75913.sh: line 1295:  5941 Segmentation fault      ${PQUERY_LOC} --infile=$WORKT --database=test --threads=1 --user=root --socket=$WORKD/socket.sock > $WORKD/pquery.out 2>&1
2015-02-16 16:47:48 [*] [Stage 1] [Trial 2] [*ErrorLogOutputBug*] [1] Swapping files & saving last known good mysqld error log output issue in /sda/012378/bug75913.sql_out
Issue found... Inspect /dev/shm/1424065544/data/* - Press a key to continue...

Then, check the error log;

$ grep "Assertion" /dev/shm/1424065544/error.log.out
2015-02-16 16:47:47 0x7f9c1062f700  InnoDB: Assertion failure in thread 140308266546944 in file btr0cur.cc line 1244

file btr0cur.cc line 1239 + the assertion message = Percona Server
file btr0cur.cc line 1244 = MySQL Server

In Percona Server the assertion is:

Failing assertion: (fil_page_get_type(page) == 17855 || fil_page_get_type(page) 

Here is what the assertion looks like in MySQL:

InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)

reducer_hacked_for_bug75913.sh

Attachment: reducer_hacked_for_bug75913.sh (application/octet-stream, text), 176.73 KiB.

bug75913.sql

Attachment: bug75913.sql (application/octet-stream, text), 997 bytes.

Thank you for the report.

reducer_hacked_for_bug75913.sh  cannot start MYSQL server, because it cannot find privilege tables. Did I miss some option?

Also is it possible to specify custom WORKDIR_LOCATION?

Sveta, interesting, what does the startup log show exactly? Did you use something like make_binary_distribution and then use this? Reducer should put all that is needed in place.

And thank you for checking :)

Roel,

hm... I use self-compiled distribution. Just cmake [option]; make; make install. Will try with binary package now.

I just tried with mysql-5.7.5-m15-linux-glibc2.5-x86_64 and I don't see "missed grant tables" error anymore, server started, but reducer_hacked_for_bug75913.sh reports it is not:

$./reducer_hacked_for_bug75913.sh bug75913.sql
./reducer_hacked_for_bug75913.sh: line 257: sysctl: command not found
./reducer_hacked_for_bug75913.sh: line 257: [: -lt: unary operator expected
2015-02-27 19:24:08 [Init] Workdir: /tmp/1425061448
2015-02-27 19:24:08 [Init] Temporary storage directory (TMP environment variable) set to /tmp/1425061448/tmp
2015-02-27 19:24:08 [Init] Input file: bug75913.sql
2015-02-27 19:24:08 [Init] Server (When MULTI mode is not active): /home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64/bin/mysqld (as ssmirnov)
2015-02-27 19:24:08 [Init] Client (When MULTI mode is not active): /home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64/bin/mysql -uroot -S/tmp/1425061448/socket.sock
2015-02-27 19:24:08 [Init] Querytimeout: 90 seconds (ensure this is at least 1.5x what was set in RQG using the --querytimeout option)
2015-02-27 19:24:08 [Init] Passing the following additional options to mysqld: --innodb_adaptive_hash_index=ON --server_id=4294967295 --innodb_flush_method=O_DIRECT --log-bin=binlog --binlog_format=MIXED --innodb_file_per_table=1 --innodb_buffer_pool_dump_now=ON --innodb_buffer_pool_size=4294967244 --innodb_buffer_pool_load_now=ON --innodb_flush_neighbors=2 --innodb_page_cleaners=2 --innodb_random_read_ahead=ON --innodb_purge_threads=2  --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY
2015-02-27 19:24:08 [Init] Setting up standard working subdirectories
2015-02-27 19:26:34 [Init] [ERROR] Failed to start mysqld server (1st boot), check /tmp/1425061448/error.log.out, /tmp/1425061448/mysqld.out, /tmp/1425061448/mysql_install_db.init, and maybe /tmp/1425061448/data/error.log. Also check that there is plenty of space on the device being used

$tail /tmp/1425061448/error.log.out
2015-02-27T18:24:36.040589Z 0 [Warning] Failed to setup SSL
2015-02-27T18:24:36.040607Z 0 [Warning] SSL error: SSL context is not usable without certificate and private key
2015-02-27T18:24:36.040639Z 0 [Note] Server hostname (bind-address): '*'; port: 33876
2015-02-27T18:24:36.040683Z 0 [Note] IPv6 is available.
2015-02-27T18:24:36.040700Z 0 [Note]   - '::' resolves to '::';
2015-02-27T18:24:36.040710Z 0 [Note] Server socket created on IP: '::'.
2015-02-27T18:24:36.136814Z 0 [Note] Event Scheduler: Loaded 0 events
2015-02-27T18:24:36.136905Z 0 [Note] /home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64/bin/mysqld: ready for connections.
Version: '5.7.5-m15-log'  socket: '/tmp/1425061448/socket.sock'  port: 33876  MySQL Community Server (GPL)
2015-02-27T18:24:36.136946Z 1 [Note] Event Scheduler: scheduler thread started with id 1

$ps -ef | grep mysqld | grep ssmirnov
ssmirnov 30948     1  0 19:24 pts/0    00:00:01 /home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64/bin/mysqld --no-defaults --basedir=/home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64 --datadir=/tmp/1425061448/data --tmpdir=/tmp/1425061448/tmp --port=33876 --pid-file=/tmp/1425061448/pid.pid --socket=/tmp/1425061448/socket.sock --user=ssmirnov --innodb_adaptive_hash_index=ON --server_id=4294967295 --innodb_flush_method=O_DIRECT --log-bin=binlog --binlog_format=MIXED --innodb_file_per_table=1 --innodb_buffer_pool_dump_now=ON --innodb_buffer_pool_size=4294967244 --innodb_buffer_pool_load_now=ON --innodb_flush_neighbors=2 --innodb_page_cleaners=2 --innodb_random_read_ahead=ON --innodb_purge_threads=2 --event-scheduler=ON --maximum-bulk_insert_buffer_size=1M --maximum-join_buffer_size=1M --maximum-max_heap_table_size=1M --maximum-max_join_size=1M --maximum-myisam_max_sort_file_size=1M --maximum-myisam_mmap_size=1M --maximum-myisam_sort_buffer_size=1M --maximum-optimizer_trace_max_mem_size=1M --maximum-preload_buffer_size=1M --maximum-query_alloc_block_size=1M --maximum-query_prealloc_size=1M --maximum-range_alloc_block_size=1M --maximum-read_buffer_size=1M --maximum-read_rnd_buffer_size=1M --maximum-sort_buffer_size=1M --maximum-tmp_table_size=1M --maximum-transaction_alloc_block_size=1M --maximum-transaction_prealloc_size=1M --log-output=none --sql_mode=ONLY_FULL_GROUP_BY --log-error=/tmp/1425061448/error.log.out --event-scheduler=ON
ssmirnov 31510 29240  0 19:28 pts/0    00:00:00 grep mysqld

$cat  /tmp/1425061448/mysqld.out
2015-02-27T18:24:34.076092Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-02-27T18:24:34.076236Z 0 [Note] /home/ssmirnov/blade12/mysql-5.7.5-m15-linux-glibc2.5-x86_64/bin/mysqld (mysqld 5.7.5-m15-log) starting as process 30948 ...

$cat /tmp/1425061448/mysql_install_db.init

$cat /tmp/1425061448/data/error.log
cat: /tmp/1425061448/data/error.log: No such file or directory

So server is up and running, no error, but test does not work. What should I fix to have it running?

Hi Sveta,

Thanks for trying. I tried again and used /tmp also to match your setup as closely as possible. It seems to reproduce easily (though have to check subreducers dirs - error in my earlier comment)

[roel@localhost ~]$ grep -A2 "Assertion" /tmp/1426318033/subreducer/*/error.log.out
/tmp/1426318033/subreducer/10/error.log.out:2015-03-14 18:31:56 0x7fdd1d7c3700  InnoDB: Assertion failure in thread 140587659179776 in file btr0cur.cc line1244
/tmp/1426318033/subreducer/10/error.log.out-InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)
/tmp/1426318033/subreducer/10/error.log.out-InnoDB: We intentionally generate a memory trap.
--
/tmp/1426318033/subreducer/1/error.log.out:2015-03-14 18:31:20 0x7f56c1f46700  InnoDB: Assertion failure in thread 140010597934848 in file btr0cur.cc line 1244
/tmp/1426318033/subreducer/1/error.log.out-InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)
/tmp/1426318033/subreducer/1/error.log.out-InnoDB: We intentionally generate a memory trap.
--
/tmp/1426318033/subreducer/2/error.log.out:2015-03-14 18:30:10 0x7f37853ca700  InnoDB: Assertion failure in thread 139876435273472 in file btr0cur.cc line 1244
/tmp/1426318033/subreducer/2/error.log.out-InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)
/tmp/1426318033/subreducer/2/error.log.out-InnoDB: We intentionally generate a memory trap.
--
... more ...

I am not sure what the difference between our machines is. Let me see if I can make a better testcase next week. Should be possible.

I can verify getting the assertion one way, but I cannot accept the provided testcase as is.

5.8.0-debug:

InnoDB: Assertion failure in thread 140736364254976 in file btr0cur.cc line 1246
InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)

(gdb) bt
#0  in raise () from /usr/lib64/libc.so.6
#1  in abort () from /usr/lib64/libc.so.6
#2  in ut_dbg_assertion_failed at ut0dbg.cc:67
#3  in btr_cur_search_to_nth_level at btr0cur.cc:1246
#4  in btr_pcur_open_low at btr0pcur.ic:465
#5  in row_search_on_row_ref at row0row.cc:817
#6  in row_purge_reposition_pcur at row0purge.cc:104
#7  in row_purge_remove_clust_if_poss_low at row0purge.cc:144
#8  in row_purge_remove_clust_if_poss at row0purge.cc:204
#9  in row_purge_del_mark at row0purge.cc:619
#10 in row_purge_record_func at row0purge.cc:904
#11 in row_purge at row0purge.cc:960
#12 in row_purge_step at row0purge.cc:1039
#13 in que_thr_step at que0que.cc:1049
#14 in que_run_threads_low at que0que.cc:1111
#15 in que_run_threads at que0que.cc:1151
#16 in trx_purge  at trx0purge.cc:1813
#17 in srv_do_purge  at srv0srv.cc:2487
#18 in srv_purge_coordinator_thread at srv0srv.cc:2675
#19 in start_thread () from /usr/lib64/libpthread.so.0
#20 in clone () from /usr/lib64/libc.so.6

pseudo-random testcase for the assertion I see.

Attachment: bug75913.cpp (text/plain), 6.66 KiB.

Posted by developer:
 
Fixed as of the upcoming 5.7.8, 5.8.0 release, and here's the changelog entry:

After a failed "DROP TABLE" operation, the purge background thread
asserted while attempting to access an index page of the table. Purge
should not attempt to clean a table that is marked as corrupt. Purge now
checks for a corrupt primary index. 

Thank you for the bug report.

there's still a problem in 5.7 with this. Filing a new bug shortly and putting in BPS.