Bug #45357 5.1.35 crashes with Failing assertion: index->type & DICT_CLUSTERED

Description:
We have upgraded from 5.1.34 to 5.1.35 and the server will crash with:

090606 13:53:50  InnoDB: Assertion failure in thread 12 in file row/row0mysql.c line 1534
InnoDB: Failing assertion: index->type & DICT_CLUSTERED
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.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
090606 13:53:49 - mysqld got signal 11 ;

This machine is a slave to a machine running 5.1.34 -- a local build with Sphinx.

The problem has been observed against a local build of 5.1.35 with Sphinx and the 5.1.35 distribution from MySQL.

Downgrading to 5.1.34 results in a crash recovery but no subsequent problems. We have stopped and started the server under 5.1.34 without any problems.

We are using binlog_format=mixed, innodb_file_per_table and trying to upgrade to take advantage of the --slave-skip-errors fix  (Bug#39393) in 5.1.35. Looking at the binary log on the master there is row based replication against an InnoDB table:

#090606 13:54:02 server id 52  end_log_pos 214708425    Table_map: `removed`.`ox_data_raw_ad_impression` mapped to number 18358
#090606 13:54:02 server id 52  end_log_pos 214709455    Delete_rows: table id 18358
etc

How to repeat:
Upgrade to 5.1.35 distribution against 5.1.34 master with row/mixed replication.

Suggested fix:
None

Thank you for the report.

Does crash happens after some activity on master? If yes, please, provide binary log which caused the problem.

Is it possible that you have innodb_locks_unsafe_for_binlog=1 or use read committed transaction isolation level? Please, check.

Try to comment out this:

set-variable                            = transaction-isolation=READ-COMMITTED

and check if you will get similar assertion failure after that. Pure guess, but a bit educated...

I have been running without that option for a few days without a problem. So I guess we know what the problem is... Guess I should change the synopsis to include that it happens when the option is used,

Had you identified the exact statement that led to crash? 

Now we know the reason for this bug (fix to #39320), and possible workaround you had confirmed, but we still do not have a simple repeatable test case.

i repeated this quickly with 5.1.35 and fake data:

mysqld.exe!row_unlock_for_mysql  Line 1534
mysqld.exe!row_search_for_mysql  Line 4090
mysqld.exe!ha_innobase::index_read  Line 4412
mysqld.exe!handler::index_read_map  Line 1390
mysqld.exe!handler::read_range_first
mysqld.exe!handler::read_multi_range_first
mysqld.exe!QUICK_RANGE_SELECT::get_next
mysqld.exe!rr_quick
mysqld.exe!mysql_delete
mysqld.exe!mysql_execute_command
mysqld.exe!mysql_parse
mysqld.exe!dispatch_command
mysqld.exe!do_command
mysqld.exe!handle_one_connection
mysqld.exe!pthread_start
mysqld.exe!_callthreadstart
mysqld.exe!_threadstart

packet	0x08e98fcd "delete from `table4` where `col131` <= '16627'"	char *

I'll make a testcase soon...

start server with --transaction-isolation=read-committed and run this.

drop table if exists t1;
create table t1(a int, b int,key(b))engine=innodb;
insert into t1 values (25170,6122);
update t1 set a=1 where b=30131;
delete from t1 where b < 20996;
delete from t1 where b < 7001;

valeriy, will you test on latest bzr and set verified if it crashes ?

I can confirm that test case crashes my setup and is cured when the option is removed.

Verified just as described by Shane with recent 5.1.36 from bzr, on Mac OS X:

valeriy-kravchuks-macbook-pro:5.1 openxs$ bin/mysqld_safe --transaction-isolation=read-committed &
[1] 11155
valeriy-kravchuks-macbook-pro:5.1 openxs$ 090615 16:10:04 mysqld_safe Logging to '/Users/openxs/dbs/5.1/var/valeriy-kravchuks-macbook-pro.local.err'.
chown: /Users/openxs/dbs/5.1/var/valeriy-kravchuks-macbook-pro.local.err: Operation not permitted
090615 16:10:04 mysqld_safe Starting mysqld daemon with databases from /Users/openxs/dbs/5.1/var

valeriy-kravchuks-macbook-pro:5.1 openxs$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.36-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> drop table if exists t1;
Query OK, 0 rows affected (0.00 sec)

mysql> create table t1(a int, b int,key(b))engine=innodb;
Query OK, 0 rows affected (0.40 sec)

mysql> insert into t1 values (25170,6122);
Query OK, 1 row affected (0.00 sec)

mysql> update t1 set a=1 where b=30131;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 0  Changed: 0  Warnings: 0

mysql> delete from t1 where b < 20996;
Query OK, 1 row affected (0.00 sec)

mysql> delete from t1 where b < 7001;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> 090615 16:10:26 mysqld_safe mysqld restarted

just a note for folks hitting this bug. if you downgrade back to earlier versions (e.g. 5.1.34) you risk running into bug #39320 . so better workaround is to not use read committed or innodb_locks_unsafe_for_binlog at all.

Sorry, my bad. While I did not find out yet what exactly is causing the assertion to fail, the assertion can be replaced with a condition that simply refuses to unlock a row when prebuilt->new_rec_locks==1 and the index in the persistent cursor is not a clustered one:

=== modified file 'storage/innobase/row/row0mysql.c'
--- storage/innobase/row/row0mysql.c	2009-04-15 11:46:08 +0000
+++ storage/innobase/row/row0mysql.c	2009-06-16 19:30:31 +0000
@@ -1529,9 +1529,14 @@
 			index = btr_pcur_get_btr_cur(clust_pcur)->index;
 		}
 
+		if (UNIV_UNLIKELY(!(index->type & DICT_CLUSTERED))) {
+			/* This is not a clustered index record.  We
+			do not know how to unlock the record. */
+			goto no_unlock;
+		}
+
 		/* If the record has been modified by this
 		transaction, do not unlock it. */
-		ut_a(index->type & DICT_CLUSTERED);
 
 		if (index->trx_id_offset) {
 			rec_trx_id = trx_read_trx_id(rec
@@ -1568,7 +1573,7 @@
 						prebuilt->select_lock_type);
 			}
 		}
-
+no_unlock:
 		mtr_commit(&mtr);
 	}

Bug #45633  was marked as a duplicate of this one.

Bug #45643 was marked as a duplicate of this one.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/76807

2968 Satya B	2009-06-22
      Applying InnoDB snashot 5.1-ss5343, Fixes BUG#45357
      
      1. BUG#45357 - 5.1.35 crashes with Failing assertion: index->type & DICT_CLUSTERED
      
      2. Also fixes the compilation problem when the flag -DUNIV_MUST_NOT_INLINE
      
      Detailed revision comments:
      
      r5340 | marko | 2009-06-17 12:11:49 +0300 (Wed, 17 Jun 2009) | 4 lines
      branches/5.1: row_unlock_for_mysql(): When the clustered index is unknown,
      refuse to unlock the record.
      (Bug #45357, caused by the fix of Bug #39320).
      rb://132 approved by Sunny Bains.
      r5339 | marko | 2009-06-17 11:01:37 +0300 (Wed, 17 Jun 2009) | 2 lines
      branches/5.1: Add missing #include "mtr0log.h" so that the code compiles
      with -DUNIV_MUST_NOT_INLINE.
      added:
        mysql-test/r/innodb_bug45357.result
        mysql-test/t/innodb_bug45357.test
      modified:
        storage/innobase/btr/btr0cur.c
        storage/innobase/include/trx0rseg.ic
        storage/innobase/row/row0mysql.c
        storage/innobase/trx/trx0rec.c

I hit this bug also after upgrading from 5.1.32 to 5.1.35 on Linux Centos 5.2.
We have multi-master replication settings. Both machines are master & slave for each other, but only 1 machine is actually active and getting traffic. 
My possible relevant settings are:
binlog-format=ROW
transaction-isolation=READ-COMMITTED
innodb_locks_unsafe_for_binlog
innodb_rollback_on_timeout=1
innodb_flush_log_at_trx_commit=2
innodb_autoinc_lock_mode=2
innodb_file_per_table

Does only removing transaction-isolation from being READ-COMMITTED solves the problem ? If yes wouldn't it cause higher locking contention in high concurrency ?

Any known date for official fix for it ? I was counting on this version for ignoring/skipping errors in row based replication, which is fixed in this version.

Thanks,
Eyal

Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:joro@sun.com-20090622115751-e2946ixgjf73narz) (merge vers: 5.1.37) (pib:11)

Pushed into 5.1.37 (revid:joro@sun.com-20090708131116-kyz8iotbum8w9yic) (version source revid:joro@sun.com-20090622115751-e2946ixgjf73narz) (merge vers: 5.1.37) (pib:11)

Pushed into 5.4.4-alpha (revid:anozdrin@bk-internal.mysql.com-20090710111017-bnh2cau84ug1hvei) (version source revid:satya.bn@sun.com-20090622113236-j8cc6krsju4qe1iq) (merge vers: 5.4.4-alpha) (pib:11)

bug #46178 was marked as a duplicate of this one.

bug #46191 was marked as a duplicate of this one.

Where can I download 5.1.37 to test whether http://bugs.mysql.com/bug.php?id=46178 is fixed?

I'm running into the same symptoms:

InnoDB: Assertion failure in thread 4630016000 in file row/row0mysql.c line 1534
InnoDB: Failing assertion: index->type & DICT_CLUSTERED

However, in my setup, tx_isolation=REPEATABLE-READ and innodb_locks_unsafe_for_binlog=OFF. Further, Shane's test case does not cause the server to crash.

I will try and create a test case this afternoon.

Bug #46276 was marked as a duplicate of this one.

Noted in 5.1.37, 5.4.4 changelogs.

An assertion failure could occur if InnoDB tried to unlock a record
when the clustered index record was unknown.

Bug: http://bugs.mysql.com/bug.php?id=46414 was marked as duplicate of this one.

Bug #46484 was marked as a duplicate of this one.

Hey guys I'm still getting this error on mysql  Ver 14.14 Distrib 5.1.35, for redhat-linux-gnu (x86_64) using readline 5.1

mysql> show variables like '%iso%';
+---------------+-----------------+
| Variable_name | Value           |
+---------------+-----------------+
| tx_isolation  | REPEATABLE-READ |
+---------------+-----------------+
1 row in set (0.00 sec)

mysql> show variables like '%lock%';
+--------------------------------+----------------------+
| Variable_name                  | Value                |
+--------------------------------+----------------------+
| innodb_autoinc_lock_mode       | 1                    |
| innodb_lock_wait_timeout       | 50                   |
| innodb_locks_unsafe_for_binlog | OFF                  |

I thought by turning the features off that contributed to the core dump the problem would be avoided.

Does anyone know a way to work around this short of waiting for .37 to be released? :)

I'm having the same issue, crashing on assertion failure on the same line once slave is started.
In my case this occurs after upgrading from 5.1.32 to 5.1.36-log x64_64. OS is Linux 2.6.29.5-191.

Commenting out tx-isolation=READ-COMMITTED from my.cnf stop the problem from occurring.  There is fairly heavy concurrent read/write traffic on this database, and I am concerned about application-level regressions running as REPEATABLE-READ.

Is there another workaround possible?

Noted in 5.4.2 changelog because next 5.4 version will be 5.4.2 and not 5.4.4.

Ignore previous comment about 5.4.2.

Bug: http://bugs.mysql.com/bug.php?id=46859 marked as duplicate if this one.

Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)

Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)

Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)

Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)

The 5.4 fix has been pushed to 5.4.2.

this bug is also in 5.1.34sp1

Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

bug #54142 is a duplicate of this

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)