MySQL crashes trying to free page already marked as free

[Michael Ivanov]

MySQL crashes with an error in logs:

InnoDB: Dump of the tablespace extent descriptor: len 40; hex 0000000000000002000980000d1e0004c0000f9e00000004aaaaaaaafaaaaaabaefaaaaaaaaaaaaa; asc ;
InnoDB: Serious error! InnoDB is trying to free page 667538
InnoDB: though it is already marked as free in the tablespace!
InnoDB: The tablespace free space info is corrupt.
InnoDB: You may need to dump your InnoDB tables and recreate the whole
InnoDB: database!

After this error it can't start again even with force_recovery set to 6. The crash also occurred on all slave servers so it is definitely not a hardware data failure. I inspected all *.ibd files with innodbchecksum utility and it reports no problems. After I analyzed the page number 667538 I found that it contains a record inside our customers table. Table structure is the following

CREATE TABLE `customers` (
  `login` varchar(128) NOT NULL,
  `usertype` char(1) NOT NULL DEFAULT '',
  `password` varchar(255) NOT NULL DEFAULT '',
  `password_hint` varchar(128) NOT NULL DEFAULT '',
  `password_hint_answer` varchar(128) NOT NULL DEFAULT '',
  `b_title` varchar(32) NOT NULL DEFAULT '',
  `b_firstname` varchar(128) NOT NULL DEFAULT '',
  `b_lastname` varchar(128) NOT NULL DEFAULT '',
  `b_address` varchar(64) NOT NULL DEFAULT '',
  `b_city` varchar(64) NOT NULL DEFAULT '',
  `b_county` varchar(32) NOT NULL DEFAULT '',
  `b_state` varchar(32) NOT NULL DEFAULT '',
  `b_country` char(2) NOT NULL DEFAULT '',
  `b_zipcode` varchar(32) NOT NULL DEFAULT '',
  `title` varchar(32) NOT NULL DEFAULT '',
  `firstname` varchar(128) NOT NULL DEFAULT '',
  `lastname` varchar(128) NOT NULL DEFAULT '',
  `company` varchar(255) NOT NULL DEFAULT '',
  `s_title` varchar(32) NOT NULL DEFAULT '',
  `s_firstname` varchar(128) NOT NULL DEFAULT '',
  `s_lastname` varchar(128) NOT NULL DEFAULT '',
  `s_address` varchar(255) NOT NULL DEFAULT '',
  `s_city` varchar(255) NOT NULL DEFAULT '',
  `s_county` varchar(32) NOT NULL DEFAULT '',
  `s_state` varchar(32) NOT NULL DEFAULT '',
  `s_country` char(2) NOT NULL DEFAULT '',
  `s_zipcode` varchar(32) NOT NULL DEFAULT '',
  `email` varchar(128) NOT NULL DEFAULT '',
  `phone` varchar(32) NOT NULL DEFAULT '',
  `fax` varchar(32) NOT NULL DEFAULT '',
  `url` varchar(128) NOT NULL DEFAULT '',
  `card_name` varchar(255) NOT NULL DEFAULT '',
  `card_type` varchar(16) NOT NULL DEFAULT '',
  `card_number` varchar(128) NOT NULL DEFAULT '',
  `card_expire` varchar(4) NOT NULL DEFAULT '',
  `card_cvv2` varchar(64) NOT NULL DEFAULT '',
  `last_login` int(11) NOT NULL DEFAULT '0',
  `first_login` int(11) NOT NULL DEFAULT '0',
  `status` char(1) NOT NULL DEFAULT 'Y',
  `referer` varchar(255) NOT NULL DEFAULT '',
  `ssn` varchar(32) NOT NULL DEFAULT '',
  `language` char(2) NOT NULL DEFAULT 'US',
  `cart` mediumtext NOT NULL,
  `change_password` char(1) NOT NULL DEFAULT 'N',
  `parent` varchar(32) NOT NULL DEFAULT '',
  `pending_plan_id` int(11) NOT NULL DEFAULT '0',
  `activity` char(1) NOT NULL DEFAULT 'Y',
  `membershipid` int(11) NOT NULL DEFAULT '0',
  `is_qa` tinyint(1) NOT NULL DEFAULT '0',
  `pending_membershipid` int(11) NOT NULL DEFAULT '0',
  `tax_number` varchar(50) NOT NULL DEFAULT '',
  `tax_exempt` char(1) NOT NULL DEFAULT 'N',
  `s_company` varchar(255) NOT NULL DEFAULT '',
  `s_phone` varchar(32) NOT NULL DEFAULT '',
  `phone2` varchar(32) NOT NULL DEFAULT '',
  `initials` char(3) NOT NULL DEFAULT '',
  `notify` tinyint(1) NOT NULL DEFAULT '0',
  `cart_completed` mediumtext NOT NULL,
  `sales_goal` varchar(64) NOT NULL DEFAULT '',
  `bml_account` varchar(32) NOT NULL DEFAULT '',
  PRIMARY KEY (`login`),
  KEY `usertype` (`usertype`),
  KEY `last_login` (`last_login`),
  KEY `first_login` (`first_login`),
  KEY `status` (`status`),
  KEY `membershipid` (`membershipid`),
  KEY `notify_idx` (`usertype`,`notify`),
  KEY `email` (`email`(16))
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

One of the related query that was found in binlog a few seconds before crash occurred is

update customers set cart_completed='I am a very long text data containing php-serialized array of customer cart' where login='sensitive information' limit 1

The record updated is the record from page 667538.

When I removed customers.ibd file and copied the old version of that table the servers were able to start again.

Link to mysql bug http://bugs.mysql.com/bug.php?id=68302

[Michael Ivanov (exception0x876)]

I have done more tests and it seems the above query does not produce errors on clean dump with the table data restored via mysqldump. So it seems to me the real table corruption occurred on this record before and the above update query just provoked a crash.

[Valerii Kravchuk (valerii-kravchuk)]

Had you ever been able to repeat this after loading a clean dump?

[Michael Ivanov (exception0x876)]

No, I was not able to repeat this after loading a clean dump and executing binlog. However, after some time (several weeks) the same error pops up again.

[Tsutomu Sugimoto (tsutomucrazy)]

The same error has happened me.
Do you now what this study?

[Shahriyar Rzayev (rzayev-sehriyar)]

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