Bug #47285 Crash MySQL and restart
Submitted: 12 Sep 2009 10:45 Modified: 14 Oct 2009 6:19
Reporter: Francis Besset Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.0.51a-24+lenny2-log (Debian) OS:Linux (Debian Lenny)
Assigned to: CPU Architecture:Any
Tags: crash

[12 Sep 2009 10:45] Francis Besset 
Description:
Hello,
My server MySQL crash alone occasionally 

I have a bug report in Syslog of Linux Debian :
Sep 12 12:20:28 ns38999 kernel: grsec: From 62.147.174.185: signal 11 sent to /usr/sbin/mysqld[mysqld:31392] uid/euid:103/103 gid/egid:106/106, parent /usr/bin/mysqld_safe[mysqld_safe:29802] uid/euid:0/0 gid/egid:0/0
Sep 12 12:20:28 ns38999 mysqld[29850]: 090912 12:20:28InnoDB: Assertion failure in thread 1081375056 in file row0mysql.c line 145
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: Failing assertion: lenlen == 1
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: We intentionally generate a memory trap.
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: If you get repeated assertion failures or crashes, even
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: immediately after the mysqld startup, there may be
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: corruption in the InnoDB tablespace. Please refer to
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
Sep 12 12:20:28 ns38999 mysqld[29850]: InnoDB: about forcing recovery.
Sep 12 12:20:28 ns38999 mysqld[29850]: 090912 12:20:28 - mysqld got signal 11;
Sep 12 12:20:28 ns38999 mysqld[29850]: This could be because you hit a bug. It is also possible that this binary
Sep 12 12:20:28 ns38999 mysqld[29850]: or one of the libraries it was linked against is corrupt, improperly built,
Sep 12 12:20:28 ns38999 mysqld[29850]: or misconfigured. This error can also be caused by malfunctioning hardware.
Sep 12 12:20:28 ns38999 mysqld[29850]: We will try our best to scrape up some info that will hopefully help diagnose
Sep 12 12:20:28 ns38999 mysqld[29850]: the problem, but since we have already crashed, something is definitely wrong
Sep 12 12:20:28 ns38999 mysqld[29850]: and this may fail.
Sep 12 12:20:28 ns38999 mysqld[29850]:
Sep 12 12:20:28 ns38999 mysqld[29850]: key_buffer_size=16777216
Sep 12 12:20:28 ns38999 mysqld[29850]: read_buffer_size=131072
Sep 12 12:20:28 ns38999 mysqld[29850]: max_used_connections=12
Sep 12 12:20:28 ns38999 mysqld[29850]: max_connections=100
Sep 12 12:20:28 ns38999 mysqld[29850]: threads_connected=6
Sep 12 12:20:28 ns38999 mysqld[29850]: It is possible that mysqld could use up to
Sep 12 12:20:28 ns38999 mysqld[29850]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 233983 K
Sep 12 12:20:28 ns38999 mysqld[29850]: bytes of memory
Sep 12 12:20:28 ns38999 mysqld[29850]: Hope that's ok; if not, decrease some variables in the equation.
Sep 12 12:20:28 ns38999 mysqld[29850]:
Sep 12 12:20:28 ns38999 mysqld[29850]: thd=0x24d3f70
Sep 12 12:20:28 ns38999 mysqld[29850]: Attempting backtrace. You can use the following information to find out
Sep 12 12:20:28 ns38999 mysqld[29850]: where mysqld died. If you see no messages after this, something went
Sep 12 12:20:28 ns38999 mysqld[29850]: terribly wrong...
Sep 12 12:20:28 ns38999 mysqld[29850]: Cannot determine thread, fp=0x24d3f70, backtrace may not be correct.
Sep 12 12:20:28 ns38999 mysqld[29850]: Bogus stack limit or frame pointer, fp=0x24d3f70, stack_bottom=0x40750000, thread_stack=131072, aborting backtrace.
Sep 12 12:20:28 ns38999 mysqld[29850]: Trying to get some variables.
Sep 12 12:20:28 ns38999 mysqld[29850]: Some pointers may be invalid and cause the dump to abort...
Sep 12 12:20:28 ns38999 mysqld[29850]: thd->query at 0x7f3a74441b50  is invalid pointer
Sep 12 12:20:28 ns38999 mysqld[29850]: thd->thread_id=88535
Sep 12 12:20:28 ns38999 mysqld[29850]: The manual page at http://www.mysql.com/doc/en/Crashing.html contains
Sep 12 12:20:28 ns38999 mysqld[29850]: information that should help you find out what is causing the crash.
Sep 12 12:20:28 ns38999 mysqld_safe[9796]: Number of processes running now: 0
Sep 12 12:20:28 ns38999 mysqld_safe[9798]: restarted
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Log scan progressed past the checkpoint lsn 0 4272434154
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28  InnoDB: Database was not shut down normally!
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Starting crash recovery.
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Reading tablespace information from the .ibd files...
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Restoring possible half-written data pages from the doublewrite
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: buffer...
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Doing recovery: scanned up to log sequence number 0 4272449042
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Transaction 0 14246889 was in the XA prepared state.
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: 2 transaction(s) which must be rolled back or cleaned up
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: in total 1 row operations to undo
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Trx id counter is 0 14247168
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28  InnoDB: Starting an apply batch of log records to the database...
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Progress in percents: 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
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Apply batch completed
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Last MySQL binlog file position 0 12854494, file name /var/log/mysql/mysql-bin.000043
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Starting in background the rollback of uncommitted transactions
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28  InnoDB: Rolling back trx with id 0 14246883, 1 rows to undo
Sep 12 12:20:28 ns38999 postfix/smtp[9894]: ABB9C13F407C: to=<fran6web@free.fr>, relay=mx1.free.fr[212.27.48.7]:25, conn_use=3, delay=0.31, delays=0.09/0/0.01/0.22, dsn=2.0.0, status=sent (250 OK)
Sep 12 12:20:28 ns38999 postfix/qmgr[13078]: ABB9C13F407C: removed
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28  InnoDB: Started; log sequence number 0 4272449042
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
Sep 12 12:20:28 ns38999 mysqld[9806]:
Sep 12 12:20:28 ns38999 mysqld[9806]: InnoDB: Rolling back of trx id 0 14246883 completed
Sep 12 12:20:28 ns38999 mysqld[9806]: 090912 12:20:28  InnoDB: Rollback of non-prepared transactions completed
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29 [Note] Starting crash recovery...
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29  InnoDB: Starting recovery for XA transactions...
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29  InnoDB: Transaction 0 14246889 in prepared state after recovery
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29  InnoDB: Transaction contains changes to 1 rows
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29  InnoDB: 1 transactions in prepared state after recovery
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29 [Note] Found 1 prepared transaction(s) in InnoDB
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29 [Note] Crash recovery finished.
Sep 12 12:20:29 ns38999 mysqld[9806]: 090912 12:20:29 [Note] /usr/sbin/mysqld: ready for connections.
Sep 12 12:20:29 ns38999 mysqld[9806]: Version: '5.0.51a-24+lenny2-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

How to repeat:
Start and wait.
[12 Sep 2009 12:33] Valeriy Kravchuk 
I had never seen this assertion failure. Wrong value (not 2 and not 1) is passed to row_mysql_store_true_var_len() function. It just should never happen. Please, check if you have any messages about memory errors/corruption.

Do you know what exact statement leads to this assertion failure?
[13 Sep 2009 12:22] Francis Besset 
How can I check messages from memory errors / corruption? 

The server at that time had 400 MB of RAM available. 
I also have an 8 GB swap to prevent forgetfulness of memory.
[14 Sep 2009 6:19] Susanne Ebrecht 
Which statement occurs the crash?
[14 Oct 2009 23: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".