5.6.26-74.0-1.jessie Assertion failure in thread 140227040917248 in file row0ins.cc line 277

[Yarikdot]

We experienced an outage today with following logs in mysql-error.log.

InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_1` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 8000547f; asc T ;;
 1: len 4; hex 800259a7; asc Y ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 8000547f; asc T ;;
 1: len 4; hex 80011f39; asc 9;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 51 row lock(s), undo log entries 51
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_4` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 2; hex 5449; asc TI;;
 1: len 4; hex 800259a7; asc Y ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 3; hex 534b42; asc SKB;;
 1: len 4; hex 8001bbcd; asc ;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 51 row lock(s), undo log entries 51
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_1` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 80004da7; asc M ;;
 1: len 4; hex 8002b80d; asc ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 80004d13; asc M ;;
 1: len 4; hex 8001bbcd; asc ;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 62 row lock(s), undo log entries 62
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_4` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 444f5350; asc DOSP;;
 1: len 4; hex 8002b80d; asc ;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 444f5350; asc DOSP;;
 1: len 4; hex 8002b66b; asc k;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 62 row lock(s), undo log entries 62
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_1` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 80005765; asc We;;
 1: len 4; hex 8002d15b; asc [;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 80005753; asc WS;;
 1: len 4; hex 80012dd7; asc - ;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 72 row lock(s), undo log entries 72
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry update in
InnoDB: index `hold_fill_targets_ibfk_4` of table `koha_test2`.`hold_fill_targets`
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 2; hex 5645; asc VE;;
 1: len 4; hex 8002d15b; asc [;;
InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 2; hex 5645; asc VE;;
 1: len 4; hex 8002c8cd; asc ;;

TRANSACTION 1196342150, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 72 row lock(s), undo log entries 72
MySQL thread id 64146, OS thread handle 0x7f8926f63700, query id 98315295 localhost koha_test2 updating
DELETE FROM hold_fill_targets

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
2016-07-20 15:17:33 7f8926f63700 InnoDB: Assertion failure in thread 140227040917248 in file row0ins.cc line 277
InnoDB: Failing assertion: *cursor->index->name == TEMP_INDEX_PREFIX
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.
13:17:33 UTC - 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.
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=29
max_threads=502
thread_count=16
connection_count=16
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 232471 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x30c7220
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 = 7f8926f62e88 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8b7c8c]
/usr/sbin/mysqld(handle_fatal_signal+0x469)[0x644b39]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f898993e8d0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f8987acf067]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f8987ad0448]
/usr/sbin/mysqld[0x99a1cf]
/usr/sbin/mysqld[0x99c122]
/usr/sbin/mysqld[0x99c516]
/usr/sbin/mysqld[0x9a7adf]
/usr/sbin/mysqld[0x90e686]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0x96)[0x595476]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x77)[0x6ab057]
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x105d)[0x6b020d]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x21e6)[0x6c48d6]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6c87f8]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xd38)[0x6c9be8]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x1a2)[0x696c92]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x696d30]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0x8ee053]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f89899370a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f8987b8287d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f88bc93fa40): is an invalid pointer
Connection ID (thread ID): 64146
Status: NOT_KILLED

After first attempt to restart we got:

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
160720 15:17:34 mysqld_safe Number of processes running now: 0
160720 15:17:34 mysqld_safe mysqld restarted
2016-07-20 15:17:35 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-07-20 15:17:35 0 [Note] /usr/sbin/mysqld (mysqld 5.6.26-74.0-log) starting as process 25087 ...
2016-07-20 15:17:35 25087 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2016-07-20 15:17:35 25087 [Warning] The option innodb (skip-innodb) is deprecated and will be removed in a future release
2016-07-20 15:17:35 25087 [Note] Plugin 'FEDERATED' is disabled.
2016-07-20 15:17:35 25087 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-07-20 15:17:35 25087 [Note] InnoDB: The InnoDB memory heap is disabled
2016-07-20 15:17:35 25087 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-07-20 15:17:35 25087 [Note] InnoDB: Memory barrier is not used
2016-07-20 15:17:35 25087 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-07-20 15:17:35 25087 [Note] InnoDB: Using Linux native AIO
2016-07-20 15:17:35 25087 [Note] InnoDB: Using CPU crc32 instructions
2016-07-20 15:17:35 25087 [Note] InnoDB: Initializing buffer pool, size = 768.0M
2016-07-20 15:17:35 25087 [Note] InnoDB: Completed initialization of buffer pool
2016-07-20 15:17:35 25087 [Note] InnoDB: Highest supported file format is Barracuda.
2016-07-20 15:17:35 25087 [Note] InnoDB: Log scan progressed past the checkpoint lsn 68614383256
2016-07-20 15:17:35 25087 [Note] InnoDB: Database was not shutdown normally!
2016-07-20 15:17:35 25087 [Note] InnoDB: Starting crash recovery.
2016-07-20 15:17:35 25087 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-07-20 15:17:43 25087 [Note] InnoDB: Restoring possible half-written data pages
2016-07-20 15:17:43 25087 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 68614464601
2016-07-20 15:17:44 25087 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 13:17:44 UTC - mysqld got signal 11 ;
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.
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=0
max_threads=502
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 232471 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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8b7c8c]
/usr/sbin/mysqld(handle_fatal_signal+0x469)[0x644b39]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f587d76c8d0]
/usr/sbin/mysqld[0x96904d]
/usr/sbin/mysqld[0x96af61]
/usr/sbin/mysqld[0x950ca6]
/usr/sbin/mysqld[0x952aff]
/usr/sbin/mysqld[0xa36e84]
/usr/sbin/mysqld[0xa80d18]
/usr/sbin/mysqld[0x9d0bd0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f587d7650a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f587b9b087d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
160720 15:17:45 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

After setting innodb_recovery to 1:

160720 15:24:01 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql/
2016-07-20 15:24:02 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-07-20 15:24:02 0 [Note] /usr/sbin/mysqld (mysqld 5.6.26-74.0-log) starting as process 28011 ...
2016-07-20 15:24:02 28011 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2016-07-20 15:24:02 28011 [Warning] The option innodb (skip-innodb) is deprecated and will be removed in a future release
2016-07-20 15:24:02 28011 [Note] Plugin 'FEDERATED' is disabled.
2016-07-20 15:24:02 28011 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-07-20 15:24:02 28011 [Note] InnoDB: The InnoDB memory heap is disabled
2016-07-20 15:24:02 28011 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-07-20 15:24:02 28011 [Note] InnoDB: Memory barrier is not used
2016-07-20 15:24:02 28011 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-07-20 15:24:02 28011 [Note] InnoDB: Using Linux native AIO
2016-07-20 15:24:02 28011 [Note] InnoDB: Using CPU crc32 instructions
2016-07-20 15:24:02 28011 [Note] InnoDB: Initializing buffer pool, size = 768.0M
2016-07-20 15:24:02 28011 [Note] InnoDB: Completed initialization of buffer pool
2016-07-20 15:24:02 28011 [Note] InnoDB: Highest supported file format is Barracuda.
2016-07-20 15:24:02 28011 [Note] InnoDB: Log scan progressed past the checkpoint lsn 68614383256
2016-07-20 15:24:02 28011 [Note] InnoDB: Database was not shutdown normally!
2016-07-20 15:24:02 28011 [Note] InnoDB: Starting crash recovery.
2016-07-20 15:24:02 28011 [Note] InnoDB: Reading tablespace information from the .ibd files...
2016-07-20 15:24:07 28011 [Note] InnoDB: Restoring possible half-written data pages
2016-07-20 15:24:07 28011 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 68614464601
2016-07-20 15:24:10 28011 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 InnoDB: Probable data corruption on page 3
InnoDB: Original record (compact record)
InnoDB: on that page.
InnoDB: Cannot find the dir slot for record (compact record)
InnoDB: on that page!
2016-07-20 15:24:10 7f12b77e9700 InnoDB: Page dump in ascii and hex (16384 bytes):
 len 16384; hex
........
(sorry, I had to remove this part due to personal data - I am able to share them privately)
........
InnoDB: End of page dump
2016-07-20 15:24:10 7f12b77e9700 InnoDB: uncompressed page, stored checksum in field1 1191648935, calculated checksums for field1: crc32 422365429, innodb 1096851135, none 3735928559, stored checksum in field2 15, calculated checksums for field2: crc32 422365429, innodb 1945883478, none 3735928559, page LSN 15 4189887192, low 4 bytes of LSN at page end 4189887192, page number (if stored to page already) 3, space id (if created with >= MySQL-4.1.1 and stored already) 1204
InnoDB: Page may be an index page where index id is 3050
2016-07-20 15:24:10 7f12b77e9700 InnoDB: Assertion failure in thread 139718364665600 in file page0page.cc line 159
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.
13:24:10 UTC - 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.
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/
key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=0
max_threads=502
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 232471 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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8b7c8c]
/usr/sbin/mysqld(handle_fatal_signal+0x469)[0x644b39]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f13154cd8d0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f131365e067]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f131365f448]
/usr/sbin/mysqld[0x96d0c4]
/usr/sbin/mysqld[0x96bf98]
/usr/sbin/mysqld[0x96c804]
/usr/sbin/mysqld[0x950cc6]
/usr/sbin/mysqld[0x952aff]
/usr/sbin/mysqld[0xa36e84]
/usr/sbin/mysqld[0xa80d18]
/usr/sbin/mysqld[0x9d0bd0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f13154c60a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f131371187d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
160720 15:24:11 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

We decided to delete (rm -rf on filesystem) possibly corrupted database (koha_test2) and mysql started correctly (just with some crap about missing files).

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3493