Bug #66704 Error: Write to file ./ib_logfile0 failed ; Error number 0 means 'Success'.
Submitted: 5 Sep 2012 12:23 Modified: 7 Sep 2012 12:50
Reporter: Eric Hymowitz Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Errors Severity:S3 (Non-critical)
Version:5.5.25 OS:Linux
Assigned to: CPU Architecture:Any

[5 Sep 2012 12:23] Eric Hymowitz
Description:
Greetings.

I run bacula for my backups.  It runs overnights automated.  I couldn't tell you how long it's been running just fine with no errors.  But last night (for the second time) I got this error:

05-Sep 01:14 herman-dir JobId 1955: Fatal error: sql_create.c:731 sql_create.c:
731 insert INSERT INTO batch VALUES (138780,1955,'/home/hymie/BrettspielWelt/ro
tacticalPics/levels/levels/','level_097.txt','gn YR6 IGk B y Bk A Jk BAA I BQQE
gJ +60Mh BFalPG A A C','26E4+aYmrT4Wxos4e34ysA') failed:
Lost connection to MySQL server during query

Mysql returns these error messages.  The first part confuses me, because of the "Error number 0 means 'Success'."

120905  1:14:14  InnoDB: Error: Write to file ./ib_logfile0 failed at offset 0 4046336.
InnoDB: 1024 bytes should have been written, only 512 were written.
InnoDB: Operating system error number 0.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 0 means 'Success'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
120905  1:14:15  InnoDB: Assertion failure in thread 2833865584 in file fil0fil.c line 4517
InnoDB: Failing assertion: ret
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
05:14:15 UTC - mysqld got signal 6 ;
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=8388608
read_buffer_size=131072
max_used_connections=5
max_threads=151
thread_count=4
connection_count=4
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337875 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x9a2c560
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_bottom = ffffffffa8e95358 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2d)[0x83c7631]
/usr/sbin/mysqld(handle_fatal_signal+0x428)[0x829d720]
[0xb77b7400]
/lib/libc.so.6(abort+0x182)[0xb75ef2e2]
/usr/sbin/mysqld[0x848cdfa]
/usr/sbin/mysqld[0x84b43ed]
/usr/sbin/mysqld[0x84b68f4]
/usr/sbin/mysqld[0x842698b]
/usr/sbin/mysqld[0x83ddb0f]
/usr/sbin/mysqld(_Z19ha_commit_one_phaseP3THDb+0x89)[0x82a0cfd]
/usr/sbin/mysqld(_Z15ha_commit_transP3THDb+0x1d8)[0x82a0f96]
/usr/sbin/mysqld(_Z17trans_commit_stmtP3THD+0x30)[0x824acc0]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x5c7)[0x8199b10]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x181)[0x81a07f3]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x180b)[0x81a294a]
/usr/sbin/mysqld(_Z10do_commandP3THD+0xdf)[0x81a2fd9]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x17c)[0x823dd51]
/usr/sbin/mysqld(handle_one_connection+0x49)[0x823ddae]
/lib/libpthread.so.0(+0x5830)[0xb7793830]
/lib/libc.so.6(clone+0x5e)[0xb76a215e]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (9a36a80): INSERT INTO batch VALUES (138780,1955,'/home/hymie/BrettspielWelt/rotacticalPics/levels/levels/','level_097.txt','gn YR6 IGk B y Bk A Jk BAA I BQQEgJ +60Mh BFalPG A A C','26E4+aYmrT4Wxos4e34ysA')
Connection ID (thread ID): 63
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
120905 01:14:18 mysqld_safe Number of processes running now: 0
120905 01:14:18 mysqld_safe mysqld restarted
120905  1:14:20 [Note] Plugin 'FEDERATED' is disabled.
120905  1:14:20 InnoDB: The InnoDB memory heap is disabled
120905  1:14:20 InnoDB: Mutexes and rw_locks use InnoDB's own implementation
120905  1:14:20 InnoDB: Compressed tables use zlib 1.2.3
120905  1:14:20 InnoDB: Using Linux native AIO
120905  1:14:21 InnoDB: Initializing buffer pool, size = 128.0M
120905  1:14:21 InnoDB: Completed initialization of buffer pool
120905  1:14:21 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 29109834
120905  1:14:21  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 34352640
InnoDB: Error: tried to read 65536 bytes at offset 0 4015616.
InnoDB: Was only able to read 31232.
120905  1:15:12  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
InnoDB: File operation call: 'read'.
InnoDB: Cannot continue operation.
120905 01:15:12 mysqld_safe mysqld from pid file /var/run/mysql/mysql.pid ended

I checked the most obvious thing I could think of:

herman-pts/4:/var/lib/mysql% ls -l
 5132 -rw-rw----  1 mysql mysql  5242880 2012-09-05 01:13 ib_logfile0
 5132 -rw-rw----  1 mysql mysql  5242880 2012-09-05 01:12 ib_logfile1
The files are only 5MB, nowhere near the max file size.  Also,
herman-pts/4:/var/lib/mysql% df -h .
Filesystem            Size  Used Avail Use% Mounted on
/dev/sda5             4.0G  1.1G  2.7G  29% /var/lib/mysql
the file system is not full.

I tried running some of the commands in that "crashing.html" page, but I cannot even start my mysql instance anymore.  I can erase my ibdata files and start fresh, but then the tests wouldn't be valid.

Also, as far as I can tell, I'm not using innodb.  My files are all named
BaseFiles.MYD
BaseFiles.MYI
BaseFiles.frm
so I believe I am using ISAM.

Can anybody point me towards more troubleshooting and/or a fix for my problem?

Thank you very much.

--EbH

How to repeat:
This job runs overnights automated.  I have not been able to start my mysql database and cause the error intentionally.
[5 Sep 2012 18:32] Sveta Smirnova
Thank you for the report.

> Also, as far as I can tell, I'm not using innodb.

What is the output of SHOW CREATE TABLE batch? Seems to be bakula's table?

Please also try to run MySQL with option innodb_use_native_aio=0 and inform us if it solves the problem.
[7 Sep 2012 12:33] Eric Hymowitz
>What is the output of SHOW CREATE TABLE batch? Seems to be bakula's table?

Fascinating.  There is no table called "batch".  None of my bacula instances have a table named "batch".

I guess this is a bacula error after all.  Sorry.
[7 Sep 2012 12:50] Eric Hymowitz
The problem has been traced to a disk error.  Thanks for the pointer.