4.0 slave -> 3.23 master replication failures when mysqlhotcopy runs
Myk Melez
master server is running 3.23.44. The upgrade went fine and
replication proceeded normally until the middle of the night, when
cron started the following job that uses mysqlhotcopy to back up the
database on the slave:
--------------------------------------------------------------------
45 0 * * * cd /var/lib/mysql; mv -f bugs-bak.tar.gz
bugs-bak-old.tar.gz; mysqlhotcopy bugs && tar --create --to-stdout
--remove-files bugs_copy | gzip - > bugs-bak.tar.gz && rmdir bugs_copy
--------------------------------------------------------------------
At that point, replication failed with the following error in
mysqld.log:
--------------------------------------------------------------------
030328 0:47:35 Slave SQL thread: I/O error reading event(errno: -1
cur_log->error: 17)
030328 0:47:35 Error reading relay log event: Aborting slave SQL
thread because of partial event read
030328 0:47:35 Could not parse log event entry, check the master for
binlog corruption
This may also be a network problem, or just a bug in the master or
slave code.
030328 0:47:35 Error running query, slave SQL thread aborted. Fix
the problem, and restart the slave SQL thread with "SLAVE START". We
stopped at log 'FIRST' position 5552828
--------------------------------------------------------------------
I found out about the problem in the morning and tried restarting the
slave thread with "SLAVE START", whereupon I got this error, which
references the same "FIRST" binary log (which doesn't exist on the
master server) as the previous log message:
--------------------------------------------------------------------
030328 11:03:42 Error in Log_event::read_log_event(): 'Found invalid
event in binary log', data_len=186840,event_type=84
030328 11:03:42 Error reading relay log event: slave SQL thread
aborted because of I/O error
030328 11:03:42 Could not parse log event entry, check the master for
binlog corruption
This may also be a network problem, or just a bug in the master or
slave code.
030328 11:03:42 Error running query, slave SQL thread aborted. Fix
the problem, and restart the slave SQL thread with "SLAVE START". We
stopped at log 'FIRST' position 5552828
--------------------------------------------------------------------
Shutting down and restarting the slave generated the same errors as
before along with a message indicating that replication had restarted.
--------------------------------------------------------------------
030328 11:21:06 /usr/sbin/mysqld: Normal shutdown
030328 11:21:06 Slave I/O thread exiting, read up to log
'replication.058', position 1338382
030328 11:21:07 /usr/sbin/mysqld: Shutdown Complete
030328 11:21:07 mysqld ended
030328 11:21:10 mysqld started
/usr/sbin/mysqld: ready for connections.
Version: '4.0.12' socket: '/var/lib/mysql/mysql.sock' port: 3306
030328 11:21:10 Error in Log_event::read_log_event(): 'Found invalid
event in binary log', data_len=186840,event_type=84
030328 11:21:10 Error reading relay log event: slave SQL thread
aborted because of I/O error
030328 11:21:10 Could not parse log event entry, check the master for
binlog corruption
This may also be a network problem, or just a bug in the master or
slave code.
030328 11:21:10 Error running query, slave SQL thread aborted. Fix
the problem, and restart the slave SQL thread with "SLAVE START". We
stopped at log 'FIRST' position 5552828
030328 11:21:10 Slave I/O thread: connected to master
'buttmon...@mothra.mozilla.org:3306', replication started in log
'replication.058' at position 1338382
--------------------------------------------------------------------
Nevertheless, while master.info shows that the slave is keeping up
with changes in the master's binary log, the slave database itself
isn't being updated. Its database files show they were last touched
either when the cron job executed last night or when I restarted the
database this morning, and queries against it return old data.
--------------------------------------------------------------------
-rw-r----- 1 mysql mysql 2635776 Mar 28 11:21
attachments.MYI
-rw-r----- 1 mysql mysql 31504384 Mar 28 11:21
bugs_activity.MYI
-rw-r----- 1 mysql mysql 24853504 Mar 28 11:21 bugs.MYI
-rw-r----- 1 mysql mysql 574464 Mar 28 11:21
logincookies.MYI
-rw-r----- 1 mysql mysql 34036736 Mar 28 11:21 longdescs.MYI
-rw-r----- 1 mysql mysql 2745818316 Mar 28 00:47
attachments.MYD
-rw-r----- 1 mysql mysql 88670104 Mar 28 00:47
bugs_activity.MYD
-rw-r----- 1 mysql mysql 30652996 Mar 28 00:47 bugs.MYD
-rw-r----- 1 mysql mysql 766016 Mar 28 00:47
logincookies.MYD
--------------------------------------------------------------------
What could be the problem here, how do I solve it, and how do I make
sure it doesn't happen again?
-myk
p.s. that mysqlhotcopy process produced an empty bugs-bak.tar.gz file,
in case it matters.