Bug #42768 Stack trace on startup of replication only node
Submitted: 11 Feb 2009 16:06 Modified: 12 Mar 2009 16:25
Reporter: Ben Hughes Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:Ver 5.0.32-Debian_7etch8-log for pc-linu, 5.0.51 OS:Linux (Debian 2.6.18-6-686 i686)
Assigned to: CPU Architecture:Any

[11 Feb 2009 16:06] Ben Hughes
Description:
A previously happily replicating slave suddenly won't start up. No outage on it's connection. Nothing changed on the master. Now every time it starts up I get the following:

/var/log/syslog.0 output:

mysqld: 090210 18:15:28  InnoDB: Database was not shut down normally!
mysqld: InnoDB: Starting crash recovery.
mysqld: InnoDB: Reading tablespace information from the .ibd files...
mysqld: InnoDB: Restoring possible half-written data pages from the doublewrite
mysqld: InnoDB: buffer...
mysqld: 090210 18:15:29  InnoDB: Starting log scan based on checkpoint at
mysqld: InnoDB: log sequence number 7 708007781.
mysqld: InnoDB: Doing recovery: scanned up to log sequence number 7 709328791
mysqld: InnoDB: 1 transaction(s) which must be rolled back or cleaned up
mysqld: InnoDB: in total 1 row operations to undo
mysqld: InnoDB: Trx id counter is 0 33629440
mysqld: 090210 18:15:29  InnoDB: Starting an apply batch of log records to the database...
mysqld: InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 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 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
mysqld: InnoDB: Apply batch completed
mysqld: InnoDB: In a MySQL replication slave the last master binlog file
mysqld: InnoDB: position 0 81265972, file name mysql-bin.000236
mysqld: InnoDB: Last MySQL binlog file position 0 98, file name /var/log/mysql/mysql-bin.000041
mysqld: InnoDB: Starting in background the rollback of uncommitted transactions
mysqld: 090210 18:15:44  InnoDB: Rolling back trx with id 0 33628928, 1 rows to undo
mysqld: 090210 18:15:44  InnoDB: Started; log sequence number 7 709328791
mysqld: 090210 18:15:44 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
mysqld: 090210 18:15:44 [Note] Starting crash recovery...
mysqld: 090210 18:15:44 [Note] Crash recovery finished.
mysqld: 090210 18:15:44InnoDB: Assertion failure in thread 1896246192 in file rem0rec.c line 339
mysqld: InnoDB: We intentionally generate a memory trap.
mysqld: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
mysqld: InnoDB: If you get repeated assertion failures or crashes, even
mysqld: InnoDB: immediately after the mysqld startup, there may be
mysqld: InnoDB: corruption in the InnoDB tablespace. Please refer to
mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
mysqld: InnoDB: about forcing recovery.
mysqld: mysqld got signal 11;
mysqld: This could be because you hit a bug. It is also possible that this binary
mysqld: or one of the libraries it was linked against is corrupt, improperly built,
mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
mysqld: We will try our best to scrape up some info that will hopefully help diagnose
mysqld: the problem, but since we have already crashed, something is definitely wrong
mysqld: and this may fail.
mysqld: 
mysqld: key_buffer_size=16777216
mysqld: read_buffer_size=131072
mysqld: max_used_connections=0
mysqld: max_connections=600
mysqld: threads_connected=0
mysqld: It is possible that mysqld could use up to 
mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 1321979 K
mysqld: bytes of memory
mysqld: Hope that's ok; if not, decrease some variables in the equation.
mysqld: 
mysqld: thd=(nil)
mysqld: Attempting backtrace. You can use the following information to find out
mysqld: where mysqld died. If you see no messages after this, something went
mysqld: terribly wrong...
mysqld: Cannot determine thread, fp=0x71064fc8, backtrace may not be correct.
mysqld: Stack range sanity check OK, backtrace follows:
mysqld: 0x81c0759
mysqld: 0x83ceb2c
mysqld: 0x83cd7f3
mysqld: 0x834dbbe
mysqld: 0x8325183
mysqld: 0x833497e
mysqld: 0x833596a
mysqld: 0x832e178
mysqld: 0x830a01f
mysqld: 0x836aea0
mysqld: 0xb7fa1240
mysqld: 0xb7ddc49e
mysqld: New value of fp=(nil) failed sanity check, terminating stack trace!
mysqld: Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
mysqld: stack trace is much more helpful in diagnosing the problem, so please do 
mysqld: resolve it
mysqld: The manual page at http://www.mysql.com/doc/en/Crashing.html contains
mysqld: information that should help you find out what is causing the crash.

Converted stack trace:

0x83ceb2c rec_get_offsets_func + 364
0x83cd7f3 page_cur_search_with_match + 947
0x834dbbe btr_cur_search_to_nth_level + 1422
0x8325183 row_search_index_entry + 99
0x833497e row_undo_ins + 2078
0x833596a row_undo_mod + 1962
0x832e178 row_undo_step + 104
0x830a01f que_run_threads + 1631
0x836aea0 trx_rollback_or_clean_all_without_sess + 896
0xb7fa1240 _end + -1349814224
0xb7ddc49e _end + -1351669106

How to repeat:
Start previously running mysqld.

Suggested fix:
none
[11 Feb 2009 17:48] Susanne Ebrecht
Many thanks for writing a bug report.

MySQL 5.0.32 is really old.

Debian has had some trouble in their packages with replication.

Please try newer version here. Our actual version is 5.0.76 and 5.1.31)

You can download here:
http://dev.mysql.com/downloads/
[12 Feb 2009 12:27] Ben Hughes
Well it happens on version '5.0.51a-23~bpo40+1-log' too. Is that not new enough still?

I'm guessing I'm now at the stage of scrapping that install and starting replication from the beginning.
[12 Feb 2009 16:25] Sveta Smirnova
Thank you for the feedback.

There is similar bug #32629

Please answer same questions from comment "[22 Nov 2007 18:19] Heikki Tuuri":

please post the .err logs in full, from the time the database instances were created.

The error looks like data file corruption.

Did you move files when the database was running, or remove ib_logfiles when recovery was necessary?
[13 Mar 2009 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".