Bug #3173 bug at innodb recovery
Submitted: 15 Mar 2004 5:09 Modified: 17 Sep 2004 12:34
Reporter: [ name withheld ] Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:mysql Ver 11.18 Distrib 3.23.54, for re OS:Linux (Red Hat Linux release 9 (Shrike))
Assigned to: Heikki Tuuri CPU Architecture:Any

[15 Mar 2004 5:09] [ name withheld ]
Description:
i'm using mysql database as the background database for the radius server, we start using mysql and radius for 6 years ago, and now the database growing larger and larger, and the database always crashed after that we decide to change out tables from MyIsam ro InnoDB. the database size now arownd 2 GB. after converting MyIsam to InnoDB every thing goes will for 10 days today mysql crashed and i tried times and times to fix this but no way.

InnoDB tried many times to fix that automatically and after that to skip recovery i added this line at my.cnf file set-variable = innodb_force_recovery = 4
mysql start but radius server can't insert or update records at database.

Note: I have two servers one as master and the other as slave. this problem happened at the master server.

How to repeat:
this is what i got at the mysqld.log 

Successfully dumped variables, if you ran with --log, take a look at the
details of what thread 4 did to cause the crash.  In some cases of really
bad corruption, the values shown above may be invalid

The manual page at http://www.mysql.com/doc/C/r/Crashing.html contains
information that should help you find out what is causing the crash

Number of processes running now: 0
040314 17:26:27  mysqld restarted
040314 17:26:27  InnoDB: Database was not shut down normally.
InnoDB: Starting recovery from log files...
InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 1036052332
InnoDB: Doing recovery: scanned up to log sequence number 0 1036053743
040314 17:26:27  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 1166, file name ./auth-bin.546
040314 17:26:28  InnoDB: Flushing modified pages from the buffer pool...
040314 17:26:28  InnoDB: Started
/usr/libexec/mysqld: ready for connections
040314 17:26:33  InnoDB: Assertion failure in thread 1103525952 in file ../include/page0page.ic line 482
InnoDB: We intentionally generate a memory trap.
InnoDB: Send a detailed bug report to mysql@lists.mysql.com
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail

key_buffer_size=8388600
record_buffer=131072
sort_buffer=2097144
max_used_connections=1
max_connections=100
threads_connected=2
It is possible that mysqld could use up to 
key_buffer_size + (record_buffer + sort_buffer)*max_connections = 225791 K
bytes of memory
Hope that's ok, if not, decrease some variables in the equation

Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Stack range sanity check OK, backtrace follows:
0x80e345c
0x40088618
0x41c66a8a
0x820b9bf
0x820c277
0x819c985
0x81a2336
0x8177931
0x8177c3b
0x8177cbd
0x8177d0f
0x8177f4f
0x8179d5e
0x8136e41
0x811166f
0x8111405
0x80eaf1f
0x80eda04
0x80e92b1
0x80e8898
Stack trace seems successful - bottom reached
Please read http://www.mysql.com/doc/U/s/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8738dd8 = INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSInnoDB: Thread 1240693184 stopped in file ../include/sync0sync.ic line 109
essionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('', '0001057A', 'e181f5325295fdf2', 'ghassan1', '', '212.33.104.41', '260', 'Async', DATE_SUB('2004-03-14 17:26:33',INTERVAL (606 + 12) SECOND), '2004-03-14 17:26:33', '606', 'RADIUS', '', '53333/28800 V90/V44/LAPM', '109565', '944875', '82856888', '82061832', 'User-Request', 'Framed-User', 'PPP', '212.33.106.8', '0', '12')
thd->thread_id=2

Successfully dumped variables, if you ran with --log, take a look at the
details of what thread 2 did to cause the crash.  In some cases of really
bad corruption, the values shown above may be invalid

The manual page at http://www.mysql.com/doc/C/r/Crashing.html contains
information that should help you find out what is causing the crash

Number of processes running now: 0
040314 17:26:33  mysqld restarted
040314 17:26:33  InnoDB: Database was not shut down normally.
InnoDB: Starting recovery from log files...
InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 1036054403
InnoDB: Doing recovery: scanned up to log sequence number 0 1036054403
InnoDB: Last MySQL binlog file position 0 429, file name ./auth-bin.547
040314 17:26:33  InnoDB: Flushing modified pages from the buffer pool...
040314 17:26:33  InnoDB: Started
/usr/libexec/mysqld: ready for connections
040314 17:26:39  InnoDB: Assertion failure in thread 1103525952 in file ../include/page0page.ic line 482
InnoDB: We intentionally generate a memory trap.
InnoDB: Send a detailed bug report to mysql@lists.mysql.com
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail

key_buffer_size=8388600
record_buffer=131072
sort_buffer=2097144
max_used_connections=1
max_connections=100
threads_connected=2
It is possible that mysqld could use up to 
key_buffer_size + (record_buffer + sort_buffer)*max_connections = 225791 K

Suggested fix:
i don't have any Suggestion about this problem.
[15 Mar 2004 5:24] Heikki Tuuri
Hi!

The database is corrupt. You have to dump your tables, recreate InnoDB's data files and ib_logfiles, and report your table dumps. If mysqld does not crash with innodb_force_recovery=4, that helps you to do the dumps. You got corruption very quickly, the log sequence number is only 1 GB.

Also, you should upgrade to MySQL-4.0.18. It has better checks against database corruption.

So far almost all cases of corruption have probably been caused by the OS/drivers/hardware, not by MySQL or InnoDB. You should consider upgrading your OS, and running RAM check and disk check tools.

Regards,

Heikki
[15 Mar 2004 23:03] [ name withheld ]
dear:

thank alot for the notes you send to me it's realy help me to force this proble :-).

but unfortimtly i think the same problem will return back because InnoDB still try to insert a query with null ID this is the query the cause my Mysql Server to goes down 
thd->query at 0x8705f78 = INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('', '000026E1', 'c94e23f053fde554', 'ghassan1', '', '212.33.106.34', '34', 'Async', DATE_SUB('2004-03-16 07:19:19',INTERVAL (6802 + 18) SECOND), '2004-03-16 07:19:19', '6802', 'RADIUS', '', '', '4358837', '6814712', '82856888', '82061832', 'User-Request', 'Framed-User', 'PPP', '212.33.106.8', '0', '18')
thd->thread_id=1

would you please help me to avoid this thd->query.

InnoDB try many times any time but no way because the radacct table has radaccid field wich is the primary key and imposible to insert it as null value. 

regards :-(
[16 Mar 2004 23:12] [ name withheld ]
Dear:

this is a very important issue because i don't know how this statement generated without a primary key (which is auto increment) I still have same problem and many records are appears in my mysqld.log file, so please help..

regards.
[17 Sep 2004 12:34] Heikki Tuuri
Hi!

Changing the status of this bug report to Can't repeat.

Inserting an empty string '' or an SQL NULL value should not crash InnoDB, nor cause database corruption.

Regards,

Heikki