Bug #10691 innodb database corruption after 4.0 -> 4.1 upgrade
Submitted: 17 May 2005 15:52 Modified: 20 May 2005 11:40
Reporter: Jan Drobil Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:4.1.10a-Debian_2 OS:Linux (Linux, Ubuntu 5.04)
Assigned to: CPU Architecture:Any

[17 May 2005 15:52] Jan Drobil
Description:
After upgrade mysql server from 4.0.23-3ubuntu2 to 4.1.10a-2,
these errors appears in our log (one or two per a hour):

May 17 11:16:41 gds30db mysqld[4753]: InnoDB: error in sec index entry update in
May 17 11:16:41 gds30db mysqld[4753]: InnoDB: index `IDX_name` of table `mojedovole/s_user`
May 17 11:16:41 gds30db mysqld[4753]: InnoDB: tuple DATA TUPLE: 3 fields;
May 17 11:16:41 gds30db mysqld[4753]:  0: len 5; hex 4672e1f261; asc Fr  a;; 1: len 4; hex 4a69f8ed; asc Ji  ;; 2: len 4; hex 0000780a; asc   
x ;;
May 17 11:16:41 gds30db mysqld[4753]: 
May 17 11:16:41 gds30db mysqld[4753]: InnoDB: record PHYSICAL RECORD: n_fields 3; 1-byte offs TRUE; info bits 0
May 17 11:16:41 gds30db mysqld[4753]:  0: len 8; hex 46726175736f76e1; asc Frausov ;; 1: len 9; hex 6d69726f736c617661; asc miroslava;; 2: len
 4; hex 0000b10a; asc     ;;
May 17 11:16:41 gds30db mysqld[4753]: 
May 17 11:16:41 gds30db mysqld[4753]: TRANSACTION 0 32473053, ACTIVE 0 sec, process no 4752, OS thread id 2494544816 updating or deleting, thr
ead declared inside InnoDB 499
May 17 11:16:41 gds30db mysqld[4753]: mysql tables in use 1, locked 1
May 17 11:16:41 gds30db mysqld[4753]: 2 lock struct(s), heap size 320, undo log entries 1
May 17 11:16:41 gds30db mysqld[4753]: MySQL thread id 193463, query id 2648906 gds30.globe.cz 81.95.98.221 mojedovole Updating
May 17 11:16:41 gds30db mysqld[4753]: UPDATE s_user SET s_first='jiri', s_last='frana' WHERE nl_user_id=30730
May 17 11:16:41 gds30db mysqld[4753]: 
May 17 11:16:41 gds30db mysqld[4753]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com

After about 2 days table s_user crash totaly a we must dump all databases
and re-create them.

May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Dump of the child page:
May 17 12:58:40 gds30db mysqld[4753]: 050517 12:58:40  InnoDB: Page dump in ascii and hex (16384 bytes):

<data>

May 17 12:58:40 gds30db mysqld[4753]: 050517 12:58:40  InnoDB: Page checksum 2831106318, prior-to-4.0.14-form checksum 3567915543
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: stored checksum 574270728, prior-to-4.0.14-form stored checksum 3567915543
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page lsn 2 3853117381, low 4 bytes of lsn at page end 3853117381
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page number (if stored to page already) 8714,
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 0
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page may be an index page where index id is 0 3286
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: (index IDX_name of table mojedovole/s_user)
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Dump of the parent page:

<data>

May 17 12:58:40 gds30db mysqld[4753]: 050517 12:58:40  InnoDB: Page checksum 4091556221, prior-to-4.0.14-form checksum 4135641457
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: stored checksum 4091556221, prior-to-4.0.14-form stored checksum 4135641457
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page lsn 2 3094002445, low 4 bytes of lsn at page end 3094002445
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page number (if stored to page already) 21676,
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 0
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Page may be an index page where index id is 0 3286
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: (index IDX_name of table mojedovole/s_user)
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Corruption of an index tree: table mojedovole/s_user, index IDX_name,
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: father ptr page no 39391, child page no 8714
May 17 12:58:40 gds30db mysqld[4753]: PHYSICAL RECORD: n_fields 3; 1-byte offs TRUE; info bits 0
May 17 12:58:40 gds30db mysqld[4753]:  0: len 7; hex 4368766f6a6b61; asc Chvojka;; 1: len 6; hex 56e1636c6176; asc V clav;; 2: len 4; hex 0000
3f75; asc   ?u;;
May 17 12:58:40 gds30db mysqld[4753]:             n_owned: 0; heap_no: 2; next rec: 160
May 17 12:58:40 gds30db mysqld[4753]: PHYSICAL RECORD: n_fields 4; 1-byte offs TRUE; info bits 0
May 17 12:58:40 gds30db mysqld[4753]:  0: len 6; hex 43656e696772; asc Cenigr;; 1: len 5; hex 4c69626f72; asc Libor;; 2: len 4; hex 00001413; 
asc     ;; 3: len 4; hex 000099df; asc     ;;
May 17 12:58:40 gds30db mysqld[4753]:             n_owned: 0; heap_no: 65; next rec: 4033
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: You should dump + drop + reimport the table to fix the
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: corruption. If the crash happens at the database startup, see
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: http://dev.mysql.com/doc/mysql/en/Forcing_recovery.html about
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: forcing recovery. Then dump + drop + reimport.
May 17 12:58:40 gds30db mysqld[4753]: 050517 12:58:40InnoDB: Assertion failure in thread 2881047472 in file btr0btr.c line 618
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Failing assertion: btr_node_ptr_get_child_page_no(node_ptr) == buf_frame_get_page_no(page)
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: We intentionally generate a memory trap.
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: If you get repeated assertion failures or crashes, even
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: immediately after the mysqld startup, there may be
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: corruption in the InnoDB tablespace. Please refer to
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: http://dev.mysql.com/doc/mysql/en/Forcing_recovery.html
May 17 12:58:40 gds30db mysqld[4753]: InnoDB: about forcing recovery.
May 17 12:58:40 gds30db mysqld[4753]: mysqld got signal 11;
May 17 12:58:40 gds30db mysqld[4753]: This could be because you hit a bug. It is also possible that this binary
May 17 12:58:40 gds30db mysqld[4753]: or one of the libraries it was linked against is corrupt, improperly built,
May 17 12:58:40 gds30db mysqld[4753]: or misconfigured. This error can also be caused by malfunctioning hardware.
May 17 12:58:40 gds30db mysqld[4753]: We will try our best to scrape up some info that will hopefully help diagnose
May 17 12:58:40 gds30db mysqld[4753]: the problem, but since we have already crashed, something is definitely wrong
May 17 12:58:40 gds30db mysqld[4753]: and this may fail.
May 17 12:58:40 gds30db mysqld[4753]: 

How to repeat:
??
[17 May 2005 16:08] Heikki Tuuri
Hi!

Have you checked if the sorting order changes between 4.0 and 4.1 could be behind the index corruption?

http://dev.mysql.com/doc/mysql/en/upgrading-from-4-0.html

Regards,

Heikki
[19 May 2005 13:35] Jan Drobil
You are probably right, thanks !
We restore all databases from dump and errors gone.
[20 May 2005 11:40] Heikki Tuuri
Ok, thank you!

Heikki